Bug #121634 Crash handler can write a mangled or incomplete query to the error log (one byte per write(2))
Submitted: 29 Oct 21:52
Reporter: Surendar Chandra (OCA) Email Updates:
Status: Open Impact on me:
None 
Category:MySQL Server Severity:S3 (Non-critical)
Version:26.10.0 OS:Any
Assigned to: CPU Architecture:Any

[29 Oct 21:52] Surendar Chandra
Description:
The crash log is the only artifact for root-causing a fatal signal.
The statement text in it can today be mangled by another thread's
output, blanked (bytes >= 0x80 become spaces on Linux), extended past
an embedded NUL, or delayed by up to 2^30 `write(2)` calls that hold up
the rest of the post-mortem and the core dump; none of this is
recoverable after the fact.

`sql/signal_handler.cc`, `print_fatal_signal()`:

```cpp
my_safe_printf_stderr("Query (%p): ", query);
// 1024 * 1024 * 1024 is the limit for max_allowed_packet
my_safe_puts_stderr(query,
                    std::min(size_t{1024 * 1024 * 1024}, query_length));
my_safe_printf_stderr("Connection ID (thread ID): %u\n", thd->thread_id());
```

`mysys/stacktrace.cc`, `my_safe_puts_stderr()`: the Linux `/proc` path
(`print_buffer`) and the direct-memory fallback:

```cpp
for (; count && *buffer; --count) {
  my_write_stderr(isprint(*buffer) ? buffer : s, 1);
  ++buffer;
}
...
for (; max_len && ptr_sane(val, heap_end) && *val; --max_len)
  my_write_stderr((val++), 1);
my_safe_printf_stderr("%s", "\n");
```

1. **Interleaving.** The prefix, the query bytes and the newline are
   separate writes, and nothing serialises them against other threads
   writing to the error log (`my_server_abort()` only serialises
   threads that are themselves aborting). Output from another thread can
   land inside the query text. Log pipelines that process the error log
   line by line cannot tell which bytes belong to the statement.

2. **Inconsistent sanitising.** Bytes are replaced by `' '` only on the
   `/proc` path, using `isprint()` in the C locale, which also blanks
   every byte >= 0x80 (UTF-8 identifiers and literals are lost there);
   the fallback and Windows paths write control bytes raw, so a query
   containing `\n` produces extra, unlabelled lines in the error log.

3. **Embedded NUL.** The `/proc` reader stops only within one 256-byte
   buffer at a NUL and then continues with the next buffer, so bytes
   past an embedded NUL are printed.

4. **One `write(2)` per byte.** With the cap at 1 GiB, a crash while a
   large statement is executing can issue up to 2^30 system calls from
   the signal handler before the rest of the post-mortem (thread id,
   status, core dump) is reached.

5. **`sprintf()` in a signal handler.** The `/proc` path builds the
   file name with `sprintf()`, which is not async-signal-safe.

How to repeat:
Linux, any build from trunk.

1. Initialize a data directory, then start the server with stderr
   going to a file:

   ```
   mysqld --no-defaults --initialize-insecure --datadir=...
   mysqld --no-defaults --datadir=... --log-error-verbosity=3 \
          --core-file 2> /tmp/mysqld.err &
   ```

2. In one client, run a statement padded to a few hundred bytes:

   ```sql
   SELECT SLEEP(300) /* 0123456789abcdef... (repeat to ~600 bytes) ... */;
   ```

3. In a second client, find the OS thread id of that connection:

   ```sql
   SELECT thread_os_id
     FROM performance_schema.threads
    WHERE processlist_info LIKE 'SELECT SLEEP(300)%'
      AND processlist_id <> CONNECTION_ID();
   ```

4. Attach `strace -f -e trace=write -p PID` to the server (PID is the
   mysqld process id), then deliver `SIGSEGV` to the thread found in
   step 3 (TID). A plain `kill -SEGV PID` is usually delivered to the
   main thread, whose post-mortem has no query, so use `tgkill(2)`:

   ```
   python3 -c 'import ctypes,sys; l=ctypes.CDLL(None); \
     l.syscall(234, int(sys.argv[1]), int(sys.argv[2]), 11)' PID TID
   ```

   (234 is `SYS_tgkill` on x86_64; use the value for the platform.)

5. Inspect the strace output and `/tmp/mysqld.err`.

**Expected:** the statement is written with a small number of
`write(2)` calls.

**Actual:** strace shows one `write(2, "S", 1)`, `write(2, "E", 1)`,
... per byte of the statement, about 600 calls here and up to 2^30 for
a large statement. A statement containing bytes >= 0x80 (for example
`SELECT 'é'`) shows them as spaces in the error log.

Suggested fix:
The patch in https://github.com/mysql/mysql-server/pull/781 does the
following.

- **Chunked, fault-checked reader.** `my_safe_puts_stderr()` copies the
  statement into a fixed-size stack buffer in bounded steps, checking
  that the memory is readable before using it, and writes each step
  with one `write(2)`. Printing stops at the first NUL or after
  `max_len` bytes on all platforms. No heap allocation; the 1 GiB cap
  in the caller is unchanged. The `/proc` path uses
  `my_safe_snprintf()` instead of `sprintf()`.

- **Default output unchanged in form.** The default is the old
  single-line format, `Query (ADDR): `, the statement and one newline,
  with the same `is an invalid pointer` and `Can't read from address`
  diagnostics. It is read and written in runs of up to 4096 bytes, one
  `write(2)` per run instead of per byte, so a 1 GiB statement takes
  about 262,000 writes. For statements made of printable ASCII the
  output is identical to trunk on Linux.

- **Sanitising.** Only control bytes, 0x00-0x1f and 0x7f, become
  spaces, on all platforms, so the statement stays on one line; UTF-8
  and all other bytes >= 0x80 are printed unchanged (a change from the
  Linux `isprint()` behaviour).

- **Opt-in self-describing format.** The new read-only system variable
  `log_error_crash_query_format` (`SINGLE_LINE`, the default, or
  `TAGGED_LINES`). With `TAGGED_LINES` the statement is printed as
  complete, newline-terminated lines of at most 132 bytes of statement
  text, each written with one `write(2)` and prefixed with the label
  and the byte offset:

  ```
  Query (7fbcd80122f0) +0: SELECT SLEEP(300) /* 0123456789abcdef...
  Query (7fbcd80122f0) +132: 0123456789abcdef0123456789abcdef...
  ...
  Query (7fbcd80122f0) +528: ...0123456789abcdef01234567 */
  Connection ID (thread ID): 9
  ```

  Each line is below `PIPE_BUF`, so other threads can interleave lines
  but not mangle them, provided the other writer's own output is
  newline-terminated (a torn preceding record can still share a
  physical line, which is existing behaviour of all handler output),
  and the offsets let the statement be reassembled and show
  truncation. This is for log pipelines that process the
  error log line by line. With `TAGGED_LINES` a 1 GiB statement still
  takes about 8.1 million writes (2^30/132); the default `SINGLE_LINE`
  takes about 262,000. The server copies the setting into a plain
  global before the fatal signal handler is installed, so the handler
  never reads system variables.

Tests in the patch: a new section in
`mysql-test/t/log_backtrace_debug.test` crashes the server with
`crash_now` once per format and checks the printed statement;
`log_error_crash_query_format_basic` covers the variable; and
`unittest/gunit/mysys_safe_puts_stderr-t.cc` has 25 cases over both
formats (chunk and run boundaries, truncation, control bytes, UTF-8,
NUL, unreadable memory).