Bug #46165 server crash in dbug
Submitted: 14 Jul 2009 10:51 Modified: 30 Dec 2012 10:17
Reporter: Ingo Strüwing Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server: Logging Severity:S1 (Critical)
Version:azalea OS:Linux
Assigned to: Jon Olav Hauglid CPU Architecture:Any

[14 Jul 2009 10:51] Ingo Strüwing
Description:
TEST                                      RESULT   TIME (ms)
------------------------------------------------------------

worker[1] Using MTR_BUILD_THREAD 120, with reserved ports 11200..11209
*** glibc detected *** /home2/mydev/bzrroot/mysql-6.0-main/sql/mysqld: double free or corruption (!prev): 0x000000000222d820 ***
======= Backtrace: =========
... (see better backtrace below)

CURRENT_TEST: main.bugnew-1
mysqltest: At line 9: query 'SET SESSION debug = @old_sessiondebug' failed: 2013: Lost connection to MySQL server during query

The result from queries just before the failure was:
SET @old_globaldebug  = @@global.debug;
SET @old_sessiondebug = @@session.debug;
SET GLOBAL debug='+O,../../log/mysqld.1.trace';
SET debug='-d:-t:-i';
SET GLOBAL  debug = @old_globaldebug;

#4  0x00007f168e208d05 in raise () from /lib/libc.so.6
#5  0x00007f168e20bdc1 in abort () from /lib/libc.so.6
#6  0x00007f168e23edd8 in ?? () from /lib/libc.so.6
#7  0x00007f168e2487a8 in ?? () from /lib/libc.so.6
#8  0x00007f168e24a2b6 in free () from /lib/libc.so.6
#9  0x00007f168e239281 in fclose () from /lib/libc.so.6
#10 0x0000000000b674b7 in DBUGCloseFile (cs=0x2315510, fp=0x222d820) at dbug.c:2145
#11 0x0000000000b66c07 in FreeState (cs=0x2315510, state=0x222da60, free_state=0) at dbug.c:1670
#12 0x0000000000b63ca9 in DbugParse (cs=0x2315510, control=0x2052568 "") at dbug.c:510
#13 0x0000000000b64968 in _db_set_ (control=0x2052568 "") at dbug.c:853
#14 0x000000000070f266 in sys_var_thd_dbug::update (this=0x1248340, thd=0x222ab38, var=0x230adf8) at set_var.cc:4901
#15 0x000000000070b638 in set_var::update (this=0x230adf8, thd=0x222ab38) at set_var.cc:4296
#16 0x000000000071137e in sql_set_variables (thd=0x222ab38, var_list=0x222ce70) at set_var.cc:4161
#17 0x0000000000702ba3 in mysql_execute_command (thd=0x222ab38) at sql_parse.cc:3519
#18 0x000000000070742e in mysql_parse (thd=0x222ab38, inBuf=0x230aa10 "SET SESSION debug = @old_sessiondebug", 
    length=37, found_semicolon=0x7f168f7fbf30) at sql_parse.cc:5942
#19 0x000000000070804c in dispatch_command (command=COM_QUERY, thd=0x222ab38, 
    packet=0x223db49 "SET SESSION debug = @old_sessiondebug", packet_length=37) at sql_parse.cc:1061
#20 0x000000000070952a in do_command (thd=0x222ab38) at sql_parse.cc:743
#21 0x00000000006f68a3 in handle_one_connection (arg=0x222ab38) at sql_connect.cc:1158

How to repeat:
This is the minimum set of statements to be put in the test file:

SET @old_globaldebug  = @@global.debug;
SET @old_sessiondebug = @@session.debug;

SET GLOBAL debug='+O,../../log/mysqld.1.trace';
SET debug='-d:-t:-i';

SET GLOBAL  debug = @old_globaldebug;
SET SESSION debug = @old_sessiondebug;
[14 Jul 2009 12:33] Ingo Strüwing
Suggested triage values:
Defact: critical. Server crash.
Workaround: partial. A different sequence might avoid the crash.
Impact: minimal. Uncommon use of the debug variable.
[15 Apr 2010 13:37] Bugs System
A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/105746

3018 Jon Olav Hauglid	2010-04-15
      Bug #46165 server crash in dbug
      
      This crash occured if the "debug" server system variable was used
      in the following way:
      1) Enable debug tracing to a logfile (global scope)
      2) Enable debug tracing to the same logfile (session scope)
      3) Change debug settings (global scope)
      4) Change debug settings (session scope)
      
      This caused a crash because the logfile was, by mistake, closed
      in 3), leading to the same memory being free'd twice when the
      file was closed again in 4).
      
      Internally, the debug settings are stored in a stack, with the current
      (last set) settings on top. When a set of settings is changed, it must
      be determined if the debug logfile is to be closed. Before this was done
      by only checking below on the settings stack. So if the set of settings
      to be changed was not on top of the stack, an existing debug logfile
      reference could be missed. This caused the file to be closed even if it
      was in use, leading to a crash later when it was closed again.
      
      In this case, at point 3) the session settings were at the top of the
      settings stack, with the global settings below. Since 3) changed the
      global settings, the sessions settings were not checked and the other
      file reference was missed. The file was therefore closed by mistake.
      
      This patch fixes the problem by making the stack double-linked so that
      settings above the settings to be changed, can be checked for logfile
      references.
      
      Test case added to variables.test.
[28 Apr 2010 9:33] Bugs System
A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/106770

3008 Jon Olav Hauglid	2010-04-28
      Bug #46165 server crash in dbug
      
      This crash occured if the same debug trace file was closed twice,
      leading to the same memory being free'd twice. This could occur
      if the "debug" server system variable refered to the same trace
      file in both global and session scope.
      
      Example of an order of events that would lead to a crash:
      1) Enable debug tracing to a trace file (global scope)
      2) Enable debug tracing to the same trace file (session scope)
      3) Reset debug settings (global scope)
      4) Reset debug settings (session scope)
      
      This caused a crash because the trace file was, by mistake, closed
      in 3), leading to the same memory being free'd twice when the file
      was closed again in 4).
      
      Internally, the debug settings are stored in a stack, with session
      settings (if any) on top and the global settings below. Each connection
      has its own stack. When a set of settings is changed, it must be 
      determined if its debug trace file is to be closed. Before, this was done
      by only checking below on the settings stack. So if the global settings
      were changed, an existing debug trace file reference in session settings
      would be missed. This caused the file to be closed even if it was in use,
      leading to a crash later when it was closed again.
      
      This patch fixes the problem by using reference counting to keep track
      of when it is safe to close a given debug trace file.
      
      Test case added to variables.test.
[28 Sep 2010 9:09] Bugs System
A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/119237

3146 Jon Olav Hauglid	2010-09-28
      Bug #46165 server crash in dbug
      
      This crash occured if the same debug trace file was closed twice,
      leading to the same memory being free'd twice. This could occur
      if the "debug" server system variable refered to the same trace
      file in both global and session scope.
      
      Example of an order of events that would lead to a crash:
      1) Enable debug tracing to a trace file (global scope)
      2) Enable debug tracing to the same trace file (session scope)
      3) Reset debug settings (global scope)
      4) Reset debug settings (session scope)
      
      This caused a crash because the trace file was, by mistake, closed
      in 3), leading to the same memory being free'd twice when the file
      was closed again in 4).
      
      Internally, the debug settings are stored in a stack, with session
      settings (if any) on top and the global settings below. Each connection
      has its own stack. When a set of settings is changed, it must be 
      determined if its debug trace file is to be closed. Before, this was done
      by only checking below on the settings stack. So if the global settings
      were changed, an existing debug trace file reference in session settings
      would be missed. This caused the file to be closed even if it was in use,
      leading to a crash later when it was closed again.
      
      This patch fixes the problem by preventing the trace file from being shared
      between global and session settings. If session debug settings are set without
      specifying a new trace file, stderr is used for output. This is a change
      in behaviour and should be reflected in the documentation.
      
      Test case added to variables.test.
[28 Sep 2010 12:23] Jon Olav Hauglid
Pushed to mysql-5.5-runtime (5.5.7-m3).
[29 Sep 2010 8:10] Bugs System
A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/119349

3147 Jon Olav Hauglid	2010-09-29
      Followup to Bug#46165 server crash in dbug
      
      This patch moves the regression test from variables.test to
      variables_debug.test as the debug system variable is not 
      available on release builds.
[4 Nov 2010 1:33] Paul DuBois
Noted in 5.5.7 changelog.

If the global and session debug system variables had the same value,
the debug trace file could be closed twice, leading to freeing
already freed memory and a server crash.
[9 Nov 2010 19:48] Bugs System
Pushed into mysql-5.5 5.5.7-rc (revid:sunanda.menon@sun.com-20101109182959-otkxq8vo2dcd13la) (version source revid:marko.makela@oracle.com-20100824081003-v4ecy0tga99cpxw2) (merge vers: 5.1.50) (pib:21)
[13 Nov 2010 16:09] Bugs System
Pushed into mysql-trunk 5.6.99-m5 (revid:alexander.nozdrin@oracle.com-20101113155825-czmva9kg4n31anmu) (version source revid:marko.makela@oracle.com-20100824081003-v4ecy0tga99cpxw2) (merge vers: 5.1.50) (pib:21)
[13 Nov 2010 16:39] Bugs System
Pushed into mysql-next-mr (revid:alexander.nozdrin@oracle.com-20101113160336-atmtmfb3mzm4pz4i) (version source revid:marko.makela@oracle.com-20100824081003-v4ecy0tga99cpxw2) (pib:21)
[26 Apr 2011 12:42] Mikael Ronström
The bug fix solved the bug but introduced a new one.
The idea when using the command:
SET SESSION debug="+d,enter,info,exit,error,query,make_query_very_long"
is to add more keywords to the debug tracing. However the patch has the
nasty side effect of redirecting all trace output to stderr thus making
it impossible to use DBUG_EXECUTE_IF in conjunction with DBUG tracing.
This makes it impossible to trace many of the important mysql-test-run
scripts.
[30 Dec 2012 10:17] MySQL Verification Team
This was fixed in 5.5.7.