Bug#16467055: GRANT STATEMENTS LOGGED TWICE IN SLOW QUERY LOG

Under very specific circumstances, an obfuscated log-line
could be logged twice.  What happens is this:

- statement is one that is rewritten (password obfuscation etc.)

- since we're executing that statement with mysql -e ...,
  we next send COM_QUIT

- COM_QUIT is not a query. In current server, the string that
  holds the rewritten_query from the previous query (GRANT ...),
  if any, is not reset in this case since we don't go through
  the code path where that happens.  We DO however go through the
  path where we check whether a rewrite happened, and if so,
  prefer it to any original string when logging.

- In other words, on a non-query command following a query that
  was rewritten, we might log the stale rewritten string again.

- This is amended by resetting the rewritten_query in a place that
  guarantees the reset will also happen for non-COM_QUERY queries.

Author: Tatjana Azundris Nuernberg

mysql-test/r/rewrite_general_log.result

@@ -102,8 +102,21 @@ id	select_type	table	partitions	type	possible_keys	key	key_len	ref	rows	filtered
 Warnings:
 Warning	1681	'EXTENDED' is deprecated and will be removed in a future release.
 Note	1003	/* select#1 */ select ((@`a`) = 5) AS `@a=5`,(@b:=10) AS `@b:=10`,(@c:=20) AS `@c:=20`,(@d:=(40 + 5)) AS `@d:=40+5`,((@e:=80) + 5) AS `(@e:=80)+5`
+End of 5.6 tests!
+#
+# Bug#16467055: GRANT STATEMENTS LOGGED TWICE IN SLOW QUERY LOG
+#
+SET GLOBAL slow_query_log=1;
+SET GLOBAL log_output='TABLE';
+TRUNCATE mysql.slow_log;
+SELECT sql_text FROM mysql.slow_log;
+sql_text
+SET SESSION long_query_time=0
+GRANT ALL PRIVILEGES ON *.* TO 'test_user1'@'%' IDENTIFIED BY PASSWORD '*82DC221D557298F6CE9961037DB1C90604792F5C'
+Quit
+DROP USER test_user1;
+End of 5.7 tests!
 DROP TABLE test_log;
 SET GLOBAL general_log_file=  @old_general_log_file;
 SET GLOBAL general_log=       @old_general_log;
 SET GLOBAL log_output=        @old_log_output;
-End of 5.6 tests!

mysql-test/t/rewrite_general_log.test

@@ -5,6 +5,9 @@
 # (see sql/sql_rewrite.cc for bulk of implementation)
 #
 
+# For Bug#16467055 and friends:
+--source include/not_embedded.inc
+
 # make sure we start with a clean slate. log_tables.test says this is OK.
 TRUNCATE TABLE mysql.general_log;
 
@@ -108,12 +111,29 @@ SELECT argument FROM mysql.general_log WHERE argument LIKE 'GRANT SELECT%' AND a
 # VIEWs do not accepted variables at this time.
 EXPLAIN EXTENDED SELECT @a=5,@b:=10,@c:=20,@d:=40+5,(@e:=80)+5;
 
+
+--echo End of 5.6 tests!
+
+
+--echo #
+--echo # Bug#16467055: GRANT STATEMENTS LOGGED TWICE IN SLOW QUERY LOG
+--echo #
+
+SET GLOBAL slow_query_log=1;
+SET GLOBAL log_output='TABLE';
+TRUNCATE mysql.slow_log;
+--exec $MYSQL -e "SET SESSION long_query_time=0; GRANT ALL PRIVILEGES ON *.* TO test_user1 IDENTIFIED BY 'meow';"
+SELECT sql_text FROM mysql.slow_log;
+DROP USER test_user1;
+
+
+--echo End of 5.7 tests!
+
+# cleanup
 DROP TABLE test_log;
 
 --remove_file $MYSQLTEST_VARDIR/log/rewrite_general.log
 
 SET GLOBAL general_log_file=  @old_general_log_file;
 SET GLOBAL general_log=       @old_general_log;
 SET GLOBAL log_output=        @old_log_output;
-
---echo End of 5.6 tests!

sql/sp_head.cc

@@ -753,6 +753,14 @@ bool sp_head::execute(THD *thd, bool merge_da_on_success)
                                                 this->m_sp_share);
 #endif
 
+    /*
+      For now, we're mostly concerned with sp_instr_stmt, but that's
+      likely to change in the future, so we'll do it right from the
+      start.
+    */
+    if (thd->rewritten_query.length())
+      thd->rewritten_query.free();
+
     err_status= i->execute(thd, &ip);
 
 #ifdef HAVE_PSI_STATEMENT_INTERFACE

sql/sql_parse.cc

@@ -1074,6 +1074,7 @@ bool dispatch_command(enum enum_server_command command, THD *thd,
     command= COM_SHUTDOWN;
   }
   thd->set_query_id(next_query_id());
+  thd->rewritten_query.free();
   thd_manager->inc_thread_running();
 
   if (!(server_command_flags[command] & CF_SKIP_QUESTIONS))
@@ -1863,7 +1864,6 @@ bool alloc_query(THD *thd, const char *packet, size_t packet_length)
   query[packet_length]= '\0';
 
   thd->set_query(query, packet_length);
-  thd->rewritten_query.free();                 // free here lest PS break
 
   /* Reclaim some memory */
   thd->packet.shrink(thd->variables.net_buffer_length);