Bug #82899 Trying to turn-off slow_query_log with an active thrd logging slow query ASSERTs
Submitted: 8 Sep 2016 3:14 Modified: 8 Sep 2016 6:22
Reporter: Krunal Bauskar (OCA) Email Updates:
Status: Verified Impact on me:
None 
Category:MySQL Server: Logging Severity:S3 (Non-critical)
Version:5.7.14, 5.7.15 OS:Any
Assigned to: CPU Architecture:Any

[8 Sep 2016 3:14] Krunal Bauskar
Description:

1. If an existing active connection is trying to log slow query and user try to turn-off slow_query_log in parallel following condition in the code is violated causing assert.

bool Query_logger::slow_log_write(THD *thd, const char *query,
                                  size_t query_length)
{
  DBUG_ASSERT(thd->enable_slow_log && opt_slow_log);

This is because thd which is pre-created has enable_slow_log set to true but in meantime opt_slow_log is reset to false.

How to repeat:

We need debug sync point. I have created one using simple sleep but it can be formalized using DBUG_SYNC points.

a. Apply given patch (5.7.14)

diff --git a/sql/log.cc b/sql/log.cc
index 510a330..afc83e6 100644
--- a/sql/log.cc
+++ b/sql/log.cc
@@ -1234,6 +1234,8 @@ void Query_logger::cleanup()
 bool Query_logger::slow_log_write(THD *thd, const char *query,
                                   size_t query_length)
 {
+  DBUG_EXECUTE_IF("about_to_log_slow_query", sleep(10););
+
   DBUG_ASSERT(thd->enable_slow_log && opt_slow_log);
 
   if (!(*slow_log_handler_list))

b. Execute following TCs

#
#

create table t1 (i int) engine=innodb;
set global long_query_time=0;
set global slow_query_log=1;
insert into t1 values (1);
select * from t1;
select @@slow_query_log;

connect (con1,localhost,root,,);
connection con1;
show tables;
set global debug="+d,about_to_log_slow_query";
--send insert into t1 values (2);

connection default;
show processlist;
select sleep(1);
show processlist;
set global slow_query_log=0;
select @@slow_query_log;

connection con1;
--reap
select * from t1;
select sleep(20);

Suggested fix:

* Semantics should be effect of slow logging will be considered from next queries. Existing queries will get follow the old value of slow_logging.
[8 Sep 2016 3:15] Krunal Bauskar
Here is the assert:

Version: '5.7.14-debug-log'  socket: '/opt/projects/codebase/non-forked-oracle/mysql-server/bld/mysql-test/var/tmp/mysqld.1.sock'  port: 13000  Source distribution
mysqld: /opt/projects/codebase/non-forked-oracle/mysql-server/sql/log.cc:1239: bool Query_logger::slow_log_write(THD*, const char*, size_t): Assertion `thd->enable_slow_log && opt_slow_log' failed.
03:08:12 UTC - mysqld got signal 6 ;
This could be because you hit a bug. It is also possible that this binary
or one of the libraries it was linked against is corrupt, improperly built,
or misconfigured. This error can also be caused by malfunctioning hardware.
Attempting to collect some information that could help diagnose the problem.
As this is a crash and something is definitely wrong, the information
collection process might fail.

key_buffer_size=1048576
read_buffer_size=131072
max_used_connections=2
max_threads=151
thread_count=2
connection_count=2
It is possible that mysqld could use up to 
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 61087 K  bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

Thread pointer: 0x7fae1c000b70
Attempting backtrace. You can use the following information to find out
where mysqld died. If you see no messages after this, something went
terribly wrong...
stack_bottom = 7fae695afe38 thread_stack 0x40000
/opt/projects/codebase/non-forked-oracle/mysql-server/bld/sql/mysqld(my_print_stacktrace+0x47)[0x194fd25]
/opt/projects/codebase/non-forked-oracle/mysql-server/bld/sql/mysqld(handle_fatal_signal+0x425)[0xf03cb8]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x10d10)[0x7fae7075cd10]
/lib/x86_64-linux-gnu/libc.so.6(gsignal+0x37)[0x7fae6fb8a267]
/lib/x86_64-linux-gnu/libc.so.6(abort+0x16a)[0x7fae6fb8beca]
/lib/x86_64-linux-gnu/libc.so.6(+0x2e03d)[0x7fae6fb8303d]
/lib/x86_64-linux-gnu/libc.so.6(+0x2e0f2)[0x7fae6fb830f2]
/opt/projects/codebase/non-forked-oracle/mysql-server/bld/sql/mysqld(_ZN12Query_logger14slow_log_writeEP3THDPKcm+0xa9)[0x14e9db5]
/opt/projects/codebase/non-forked-oracle/mysql-server/bld/sql/mysqld(_Z11log_slow_doP3THD+0xec)[0x14eae85]
/opt/projects/codebase/non-forked-oracle/mysql-server/bld/sql/mysqld(_Z18log_slow_statementP3THD+0x28)[0x14eaeb4]
/opt/projects/codebase/non-forked-oracle/mysql-server/bld/sql/mysqld(_Z16dispatch_commandP3THDPK8COM_DATA19enum_server_command+0x20d0)[0x15f11aa]
/opt/projects/codebase/non-forked-oracle/mysql-server/bld/sql/mysqld(_Z10do_commandP3THD+0x51a)[0x15eeba3]
/opt/projects/codebase/non-forked-oracle/mysql-server/bld/sql/mysqld(handle_connection+0x1e0)[0x172a90f]
/opt/projects/codebase/non-forked-oracle/mysql-server/bld/sql/mysqld(pfs_spawn_thread+0x173)[0x198d350]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x76aa)[0x7fae707536aa]
/lib/x86_64-linux-gnu/libc.so.6(clone+0x6d)[0x7fae6fc5beed]
[8 Sep 2016 6:22] Umesh Shastry
Hello Krunal,

Thank you for the report and test case.
Verified as described with 5.7.15 build.

Thanks,
Umesh