MySQL Bugs: #33982: debug assertion and crash reloading grant tables after sighup or kill

Bug #33982	debug assertion and crash reloading grant tables after sighup or kill
Submitted:	22 Jan 2008 15:11	Modified:	17 Jun 2010 22:51
Reporter:	Shane Bester (Platinum Quality Contributor)	Email Updates:
Status:	Closed	Impact on me:	None
Category:	MySQL Server: Security: Privileges	Severity:	S2 (Serious)
Version:	5.1.24-bk-debug, 5.1.37-debug, 6.0	OS:	Any
Assigned to:	Kristofer Pettersson	CPU Architecture:	Any
Tags:	assertion, KILL

Description:
Found while I was trying to repeat bug #26489

I lost ssh connection to linux box, which I suspect caused sighup to trigger.
With this, I got an error in log file just after the memory dump (was full debug build):

Maximum memory usage: 25316000 bytes (24723k)
mysqld: sql_base.cc:2579: TABLE* open_table(THD*, TABLE_LIST*, MEM_ROOT*, bool*, unsigned int): Assertion `thd->lex->is_lex_started' failed.

End safemalloc memory dump.

Memory status:
Non-mmapped space allocated from system: 7069696
Number of free chunks:                   42
Number of fastbin blocks:                0
Number of mmapped regions:               11
Space in mmapped regions:                22323200
Maximum total allocated space:           0
Space available in freed fastbin blocks: 0
Total allocated space:                   6868696
Total free space:                        201000
Top-most, releasable space:              133032
Estimated memory (with thread stack):    29786112

Events status:
LLA = Last Locked At  LUA = Last Unlocked At
WOC = Waiting On Condition  DL = Data Locked
The Event Scheduler is disabled

080122 15:59:55 - 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.
We will try our best to scrape up some info that will hopefully help diagnose
the problem, but since we have already crashed, something is definitely wrong
and this may fail.

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

thd: 0x8dd5ab8
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...
Cannot determine thread, fp=0x425abc34, backtrace may not be correct.
Stack range sanity check OK, backtrace follows:
0x82046b5 handle_segfault + 541
0xffffe410 _end + -142258400
0x400edb75 _end + 932464261
0x400e5903 _end + 932430867
0x824dcb9 open_table(THD*, TABLE_LIST*, st_mem_root*, bool*, unsigned int) + 4017
0x82505c5 open_tables(THD*, TABLE_LIST**, unsigned int*, unsigned int) + 633
0x8250ddd open_and_lock_tables_derived(THD*, TABLE_LIST*, bool) + 145
0x82af93a acl_reload(THD*) + 328
0x821c5e6 reload_acl_and_cache(THD*, unsigned long, TABLE_LIST*, bool*) + 186
0x8205117 signal_hand + 831
0x40038aa7 _end + 931722679
0x4017ec2e _end + 933058366
New value of fp=(nil) failed sanity check, terminating stack trace!
Please read http://dev.mysql.com/doc/refman/5.1/en/resolve-stack-dump.html
and follow instructions on how to resolve the stack trace.
Resolved stack trace is much more helpful in diagnosing the
problem, so please do resolve it
Trying to get some variables.
Some pointers may be invalid and cause the dump to abort...
thd->query at (nil)  is invalid pointer
thd->thread_id=0

How to repeat:
send a sighup?

server was started like this:

./bin/mysqld_safe --skip-grant-tables --skip-name-resolve --log-warn=2 -#F:L:t:n:i:d:o,slave.log --server-id=9 --slave_net_timeout=4

This also happens on 6.0.4. The following steps are sufficient, replication does not have to be enabled:

1. Compile a debug binary
2. Run mysql-test-run.pl --start-and-exit --skip-ndb
3. kill -HUP the mysqld

killing flush privileges causes a debug assertion and crash:

Stack from 5.1.37-debug

Assertion failed: m_status == DA_ERROR || m_status == DA_OK, file e:\builds\bzr\5.1\sql\sql_class.h, line 1146
090707  9:21:03 - mysqld got exception 0x80000003 ;

mysqld.exe!_NMSG_WRITE()[crt0msg.c:198]
mysqld.exe!abort()[abort.c:59]
mysqld.exe!_wassert()[assert.c:212]
mysqld.exe!Diagnostics_area::message()[sql_class.h:1146]
mysqld.exe!servers_reload()[sql_servers.cc:245]
mysqld.exe!reload_acl_and_cache()[sql_parse.cc:6768]
mysqld.exe!mysql_execute_command()[sql_parse.cc:3944]
mysqld.exe!sp_instr_stmt::exec_core()[sp_head.cc:2907]
mysqld.exe!sp_lex_keeper::reset_lex_and_exec_core()[sp_head.cc:2735]
mysqld.exe!sp_instr_stmt::execute()[sp_head.cc:2849]
mysqld.exe!sp_head::execute()[sp_head.cc:1253]
mysqld.exe!sp_head::execute_procedure()[sp_head.cc:1983]
mysqld.exe!mysql_execute_command()[sql_parse.cc:4354]
mysqld.exe!mysql_parse()[sql_parse.cc:5933]
mysqld.exe!dispatch_command()[sql_parse.cc:1213]
mysqld.exe!do_command()[sql_parse.cc:854]
mysqld.exe!handle_one_connection()[sql_connect.cc:1127]
mysqld.exe!pthread_start()[my_winthread.c:85]
mysqld.exe!_callthreadstart()[thread.c:293]
mysqld.exe!_threadstart()[thread.c:277]
kernel32.dll!FlsSetValue()
t some variables.
s may be invalid and cause the dump to abort...
t 05ECED68=flush privileges
id=5
KILL_CONNECTION

testcase:

delimiter ;
drop procedure if exists `p1`;
delimiter //
create procedure `p1`(`numusers` int)
begin

 declare `i` int default '0';
 
 repeat
   flush privileges;
   set @q=concat('grant all on *.* to user',`i`);
   prepare `stmt` from @q;
   execute `stmt`;
   deallocate prepare `stmt`;
   set `i`=`i`+1;
 until `i`>`numusers`
 end repeat;

end//

delimiter ;

call `p1`(5000);  #open another connection and kill this query. repeat until crash.

Thank you for the report.

Verified as described:

Version: '5.1.37-debug'  socket: '/tmp/mysql51.sock'  port: 3351  Source distribution
sql_class.h:1146: failed assertion `m_status == DA_ERROR || m_status == DA_OK'
090713 12:09:37 - mysqld got signal 6 ;

Test I used:

while true; do mysql -b --socket=/tmp/mysql51.sock -uroot test -e "call p1(5000);"; done

then typed Ctrl+C until server crashes.

Kristoffer, this is most likely a duplicate of Bug#44521.
Could you please verify that and close if it's the case?

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/96737

3303 Kristofer Pettersson	2010-01-13
      Bug#33982 debug assertion and crash reloading grant tables after sighup or kill
      
      In certain rare cases when a process was interrupted
      during a FLUSH PRIVILEGES operation the diagnostic
      area would be set to an error state but the function
      responsible for the operation would still signal
      success. This would lead to a debug assertion error
      later on when the server would attempt to reset the
      DA before sending the error message.
      
      This patch fixes the issue by assuring that
      reload_acl_and_cache() always fails if an error
      condition is raised.
      
      The second issue was that a KILL could cause
      a console error message which referred to a DA
      state without first making sure that such a
      state existed.
      
      This patch fixes this issue in two different
      palces by first checking DA state before
      fetching the error message.
      
       
     @ sql/sql_acl.cc
        * Make sure that there is an error to print before attempting to do so.
        * Minor style change: change 1 to TRUE for clarity.
     @ sql/sql_parse.cc
        * Always fail reload_acl_and_cache() if the query was killed.
     @ sql/sql_servers.cc
        * Make sure that there is an error to print before attempting to do so.

Pushed into mysql-next-mr (revid:alik@sun.com-20100204063540-9czpdmpixi3iw2yb) (version source revid:alik@sun.com-20100119163614-172adculixyu26j5) (pib:16)

Pushed into 6.0.14-alpha (revid:alik@sun.com-20100205113942-oqovjy0eoqbarn7i) (version source revid:alik@sun.com-20100204064210-ljwanqvrjs83s1gq) (merge vers: 6.0.14-alpha) (pib:16)

Pushed into 5.5.2-m2 (revid:alik@sun.com-20100203172258-1n5dsotny40yufxw) (version source revid:alexey.kopytov@sun.com-20100115112653-e3a24041ag1cv6v3) (merge vers: 5.5.1-m2) (pib:16)

Noted in 5.5.2, 6.0.14 changelogs.

1) In rare cases, if a thread was interrupted during a FLUSH
PRIVILEGES operation, a debug assertion occurred later due to 
improper diagnostic area setup. 2) A KILL operation could cause a
console error message referring to a diagnostic area state without
first ensuring that the state existed. 

Setting report to Need Merge pending push to Celosia.

Pushed into 5.1.44-ndb-7.0.14 (revid:jonas@mysql.com-20100312135944-t0z8s1da2orvl66x) (version source revid:jonas@mysql.com-20100312115609-woou0te4a6s4ae9y) (merge vers: 5.1.44-ndb-7.0.14) (pib:16)

Pushed into 5.1.44-ndb-6.2.19 (revid:jonas@mysql.com-20100312134846-tuqhd9w3tv4xgl3d) (version source revid:jonas@mysql.com-20100312060623-mx6407w2vx76h3by) (merge vers: 5.1.44-ndb-6.2.19) (pib:16)

Pushed into 5.1.44-ndb-6.3.33 (revid:jonas@mysql.com-20100312135724-xcw8vw2lu3mijrhn) (version source revid:jonas@mysql.com-20100312103652-snkltsd197l7q2yg) (merge vers: 5.1.44-ndb-6.3.33) (pib:16)

Noted in -ndb- changelogs.

Pushed into 5.1.47 (revid:build@mysql.com-20100412101220-adgau1r18kwgthps) (version source revid:build@mysql.com-20100412101220-adgau1r18kwgthps) (merge vers: 5.1.47) (pib:16)

Noted in 5.1.47 changelog.

Pushed into mysql-next-mr (revid:alik@sun.com-20100524190136-egaq7e8zgkwb9aqi) (version source revid:vasil.dimov@oracle.com-20100331130613-8ja7n0vh36a80457) (pib:16)

Pushed into 6.0.14-alpha (revid:alik@sun.com-20100524190941-nuudpx60if25wsvx) (version source revid:alik@sun.com-20100422150658-fkhgnwwkyugtxrmu) (merge vers: 6.0.14-alpha) (pib:16)

Pushed into 5.5.5-m3 (revid:alik@sun.com-20100524185725-c8k5q7v60i5nix3t) (version source revid:alexey.kopytov@sun.com-20100429203306-tg0wz4y2xyx8edrl) (merge vers: 5.5.5-m3) (pib:16)

Already fixed.

Pushed into 5.1.47-ndb-7.0.16 (revid:martin.skold@mysql.com-20100617114014-bva0dy24yyd67697) (version source revid:vasil.dimov@oracle.com-20100331130613-8ja7n0vh36a80457) (merge vers: 5.1.46) (pib:16)

Pushed into 5.1.47-ndb-6.2.19 (revid:martin.skold@mysql.com-20100617115448-idrbic6gbki37h1c) (version source revid:vasil.dimov@oracle.com-20100331130613-8ja7n0vh36a80457) (merge vers: 5.1.46) (pib:16)

Pushed into 5.1.47-ndb-6.3.35 (revid:martin.skold@mysql.com-20100617114611-61aqbb52j752y116) (version source revid:vasil.dimov@oracle.com-20100331130613-8ja7n0vh36a80457) (merge vers: 5.1.46) (pib:16)