PS-9083: server crash when slow query log is on with additional varia…

…bles

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

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;

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

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;