Bug #96373 query_time greater than 35 days lead to slow log corruption
Submitted: 30 Jul 2019 6:46 Modified: 9 Oct 2019 13:58
Reporter: Fungo Wang (OCA) Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server: Logging Severity:S3 (Non-critical)
Version:5.7.27, 8.0.17 OS:Any
Assigned to: CPU Architecture:Any
Tags: 35 days, slow_log

[30 Jul 2019 6:46] Fungo Wang
Description:
If there is a query running longer than 35 days and logged to slow_log, we can not retrieve data from mysql.slow_log.

mysql> select * from mysql.slow_log;
ERROR 1194 (HY000): Table 'slow_log' is marked as crashed and should be repaired

How to repeat:
Make sure slow log is enabled and log_output is set to table.

set global slow_query_log = ON;
set global log_output = 'TABLE';

Then execute a long query 

select sleep(35*24*3600);

then query from slow_log
select * from mysql.slow_log;

==============

select sleep(35*24*3600); will run a very long time(35 days), to make it quick, we can use gdb to change the start_time back to 35 days before.

for example:
break on mysql_execute_command
then change start_time and start_utime

p thd->start_time.tv_sec = 1555826389
p thd->start_utime = (longlong)1555826389*1000000

Suggested fix:
If check the CSV data file, we can see the query_time (838:59:59.266398) is bigger than 838:59:59.000000, the max legal value.

"2019-07-30 09:29:05.726679","root[root] @ localhost [127.0.0.1]","838:59:59.726679","838:59:59.266398",3,3,"",0,0,1,"select * from mysql.slow_log",12

This illegal value lead to query failed.

If we don't fetch query_time field, the select is successful.

mysql> select start_time, user_host from mysql.slow_log;
+----------------------------+------------------------------------+
| start_time                 | user_host                          |
+----------------------------+------------------------------------+
| 2019-07-30 09:28:06.823172 | root[root] @ localhost [127.0.0.1] |
| 2019-07-30 09:28:18.067313 | root[root] @ localhost [127.0.0.1] |
| 2019-07-30 09:28:30.163309 | root[root] @ localhost [127.0.0.1] |
| 2019-07-30 09:29:05.726679 | root[root] @ localhost [127.0.0.1] |
+----------------------------+------------------------------------+
4 rows in set (0.00 sec)

mysql> select start_time, user_host, query_time from mysql.slow_log;
ERROR 1194 (HY000): Table 'slow_log' is marked as crashed and should be repaired

Both latest 5.7.27 and 8.0.17 are affected, 5.6 series don't have this issue, because in 5.6 slow_log query_time don't allow fractional  part time.

BTW, lock_time field also have this issue.

A simple fix is to cap fractional time properly in `calc_time_from_sec()` when writing to slow_log.
[30 Jul 2019 8:53] MySQL Verification Team
Hello Fungo Wang,

Thank you for the report.
Verified as described on 8.0.17 build.

regards,
Umesh
[30 Jul 2019 8:55] MySQL Verification Team
Test results - 8.0.17

Attachment: 96373_8.0.17.results (application/octet-stream, text), 6.49 KiB.

[9 Oct 2019 13:58] Paul DuBois
Posted by developer:
 
Fixed in 8.0.19.

Slow queries with an execution time greater than 35 days could cause
corruption of the mysql.slow_log system table requiring a REPAIR
TABLE operation.