From c67252c7f704c35c62ae71f01008b4f1dabef7e2 Mon Sep 17 00:00:00 2001 From: Dmitry Lenev Date: Wed, 31 Jan 2024 21:54:42 +0100 Subject: [PATCH] PS-9083: server crash when slow query log is on with additional variables https://perconadev.atlassian.net/browse/PS-9083 When slow log was enabled with --long_query_time option set to 0 (or close value) and with --log_slow_verbosity option including "query_info" mode, server might have crashed when a protocol command other than normal statement execution (COM_QUERY or mysql_query() in C API parlance) was executed in a connection which earlier was used to rn some statement. For example, this sometimes happened for COM_QUIT command issue during graceful disconnect. The crash was caused by attempt to write to slow log list of query tables for such non-COM_QUERY command. To do so we tried to iterate through LEX::query_tables list, which in case of such commands might contain garbage left from execution of earlier statements in the connection. This fix solves the problem by avoiding writing to slow log list of query tables for server commands other than COM_QUERY (for most of them it makes no sense or not easily available). --- .../r/percona_slowlog_query_info.result | 17 +++++++++++++-- mysql-test/t/percona_slowlog_query_info.test | 21 +++++++++++++++---- sql/log.cc | 9 +++++++- 3 files changed, 40 insertions(+), 7 deletions(-) diff --git a/mysql-test/r/percona_slowlog_query_info.result b/mysql-test/r/percona_slowlog_query_info.result index e3c5f4be4765..4ef152c5195a 100644 --- a/mysql-test/r/percona_slowlog_query_info.result +++ b/mysql-test/r/percona_slowlog_query_info.result @@ -1,4 +1,3 @@ -SET @saved_slow_query_log = @@GLOBAL.slow_query_log; SET SESSION log_slow_verbosity = 'query_info'; SET GLOBAL slow_query_log = 1; SET long_query_time = 0; @@ -54,5 +53,19 @@ a1 b1 [log_stop.inc] percona.slow_log.query_tables [log_grep.inc] file: percona.slow_log.query_tables pattern: ^# Query_tables: table1,t1 Query_digest: [\d\w]{64} expected_matches: 1 [log_grep.inc] found expected match count: 1 +# +# PS-9083: Server crash when slow query log is on with additional +# variables. +# +[log_start.inc] percona.slow_log.query_tables +WITH table1 (a1, b1) AS (SELECT a, b FROM t1) SELECT a1, b1 FROM table1; +a1 b1 +1 1 +2 2 +3 3 +# Attempt to write to slow log table list for COM_QUIT command has +# caused crash before the fix. +disconnect default; +connect default,localhost,root,,test; +[log_stop.inc] percona.slow_log.query_tables DROP TABLE t1, t2; -SET GLOBAL slow_query_log = @saved_slow_query_log; diff --git a/mysql-test/t/percona_slowlog_query_info.test b/mysql-test/t/percona_slowlog_query_info.test index c8f193ad1310..25021fc06087 100644 --- a/mysql-test/t/percona_slowlog_query_info.test +++ b/mysql-test/t/percona_slowlog_query_info.test @@ -3,8 +3,6 @@ # --source include/log_prepare.inc -SET @saved_slow_query_log = @@GLOBAL.slow_query_log; - SET SESSION log_slow_verbosity = 'query_info'; SET GLOBAL slow_query_log = 1; SET long_query_time = 0; @@ -48,8 +46,23 @@ WITH table1 (a1, b1) AS (SELECT a, b FROM t1) SELECT a1, b1 FROM table1; --let log_expected_matches = 1 --source include/log_grep.inc -DROP TABLE t1, t2; +--echo # +--echo # PS-9083: Server crash when slow query log is on with additional +--echo # variables. +--echo # +--enable_connect_log +--source include/log_start.inc + +WITH table1 (a1, b1) AS (SELECT a, b FROM t1) SELECT a1, b1 FROM table1; -SET GLOBAL slow_query_log = @saved_slow_query_log; +--echo # Attempt to write to slow log table list for COM_QUIT command has +--echo # caused crash before the fix. +--disconnect default +--connect (default,localhost,root,,test) + +--source include/log_stop.inc +--disable_connect_log + +DROP TABLE t1, t2; --source include/log_cleanup.inc diff --git a/sql/log.cc b/sql/log.cc index ff4d420197fd..75f0cb2e530a 100644 --- a/sql/log.cc +++ b/sql/log.cc @@ -912,8 +912,15 @@ bool File_query_log::write_slow(THD *thd, ulonglong current_utime, goto err; } - if ((thd->variables.log_slow_verbosity & (1ULL << SLOG_V_QUERY_INFO))) { + if ((thd->variables.log_slow_verbosity & (1ULL << SLOG_V_QUERY_INFO)) && + thd->get_command() == COM_QUERY) { // Query_tables + // + // Concept of query table list doesn't apply to most of server commands + // other than COM_QUERY. Even if it makes sense, like for COM_STMT_EXECUTE, + // it might be not easily available. They might not fully initialize LEX as + // well, so LEX::query_tables can contain gargbage from previous statements + // for them. std::string tbl_list_str = ""; if (thd->lex->query_tables != nullptr) { std::stringstream tbl_list;