Skip to content

Commit dcb814c

Browse files
committed
MDEV-11628 mysql.slow_log reports incorrect start time
use thd->start_time for the "start_time" column of the slow_log table. "current_time" here refers to the current_time() function return value not to the actual *current* time. also fixes MDEV-33267 User with minimal permissions can intentionally corrupt mysql.slow_log table
1 parent db9fad1 commit dcb814c

File tree

3 files changed

+47
-1
lines changed

3 files changed

+47
-1
lines changed

mysql-test/main/log_tables.result

Lines changed: 28 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -994,6 +994,34 @@ ERROR HY000: Cannot rename 'slow_log'. When logging enabled, rename to/from log
994994
use test;
995995
flush tables with read lock;
996996
unlock tables;
997+
#
998+
# MDEV-33267 User with minimal permissions can intentionally corrupt mysql.slow_log table
999+
#
1000+
truncate mysql.slow_log;
1001+
set global log_output= 'TABLE';
1002+
create user u@localhost;
1003+
set slow_query_log=on, long_query_time=0.1;
1004+
select 'before evil-doing', sleep(0.2);
1005+
before evil-doing sleep(0.2)
1006+
before evil-doing 0
1007+
connect con1,localhost,u,,;
1008+
set @@timestamp= 2147483647;
1009+
set slow_query_log=on, long_query_time=0.1;
1010+
select 'evil-doing', sleep(1.1);
1011+
evil-doing sleep(1.1)
1012+
evil-doing 0
1013+
disconnect con1;
1014+
connection default;
1015+
select 'after evil-doing', sleep(0.2);
1016+
after evil-doing sleep(0.2)
1017+
after evil-doing 0
1018+
select distinct sql_text from mysql.slow_log where sql_text like '%evil%';
1019+
sql_text
1020+
select 'before evil-doing', sleep(0.2)
1021+
select 'evil-doing', sleep(1.1)
1022+
select 'after evil-doing', sleep(0.2)
1023+
set global log_output=default;
1024+
drop user u@localhost;
9971025
SET @@global.log_output= @old_log_output;
9981026
SET @@global.slow_query_log= @old_slow_query_log;
9991027
SET @@global.general_log= @old_general_log;

mysql-test/main/log_tables.test

Lines changed: 18 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -1033,6 +1033,24 @@ use test;
10331033
flush tables with read lock;
10341034
unlock tables;
10351035

1036+
--echo #
1037+
--echo # MDEV-33267 User with minimal permissions can intentionally corrupt mysql.slow_log table
1038+
--echo #
1039+
truncate mysql.slow_log;
1040+
set global log_output= 'TABLE';
1041+
create user u@localhost;
1042+
set slow_query_log=on, long_query_time=0.1;
1043+
select 'before evil-doing', sleep(0.2);
1044+
--connect (con1,localhost,u,,)
1045+
set @@timestamp= 2147483647;
1046+
set slow_query_log=on, long_query_time=0.1;
1047+
select 'evil-doing', sleep(1.1);
1048+
--disconnect con1
1049+
--connection default
1050+
select 'after evil-doing', sleep(0.2);
1051+
select distinct sql_text from mysql.slow_log where sql_text like '%evil%';
1052+
set global log_output=default;
1053+
drop user u@localhost;
10361054

10371055
SET @@global.log_output= @old_log_output;
10381056
SET @@global.slow_query_log= @old_slow_query_log;

sql/log.cc

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -1334,7 +1334,7 @@ bool LOGGER::slow_log_print(THD *thd, const char *query, size_t query_length,
13341334
query_utime= (current_utime - thd->start_utime);
13351335
lock_utime= (thd->utime_after_lock - thd->start_utime);
13361336
my_hrtime_t current_time= { hrtime_from_time(thd->start_time) +
1337-
thd->start_time_sec_part + query_utime };
1337+
thd->start_time_sec_part };
13381338

13391339
if (!query || thd->get_command() == COM_STMT_PREPARE)
13401340
{

0 commit comments

Comments
 (0)