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).
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).