MySQL Bugs: #52353: mutex mishap and/memory corruption crashes server during shutdown

Bug #52353	mutex mishap and/memory corruption crashes server during shutdown
Submitted:	25 Mar 2010 7:37	Modified:	17 Dec 2011 17:07
Reporter:	Shane Bester (Platinum Quality Contributor)	Email Updates:
Status:	Can't repeat	Impact on me:	None
Category:	MySQL Server: General	Severity:	S1 (Critical)
Version:	5.1.45-debug, 5.1.46-debug, 5.1.48-debug, 5.6.99-m4-debug	OS:	Any (windows, linux)
Assigned to:		CPU Architecture:	Any
Tags:	regression

Description:
5.6.99 log of the problem that happens at shutdown:
[Note] Got signal 15 to shutdown mysqld
[Note] ./sql/mysqld: Normal shutdown

[Note] Event Scheduler: Purging the queue. 0 events
InnoDB: Starting shutdown...
InnoDB: Shutdown completed; log sequence number 133992895
[Note] ./sql/mysqld: Shutdown complete

safe_mutex: Trying to lock unitialized mutex at safemalloc.c, line 294
 - mysqld got signal 6 ;

Invalid read of size 8
at: handle_segfault (mysqld.cc:2654)
by: ??? (in /lib64/libpthread-2.5.so)
 Address 0x5e4e590 is 48 bytes inside a block of size 2,492 free'd
at: free (vg_replace_malloc.c:325)
by: _myfree (safemalloc.c:314)
by: free_key_cache(char const*, st_key_cache*) (keycaches.cc:143)
by: NAMED_ILIST::delete_elements() (keycaches.cc:75)
by: clean_up(bool) (mysqld.cc:1474)
by: unireg_end() (mysqld.cc:1383)
by: kill_server(void*) (mysqld.cc:1306)
by: kill_server_thread (mysqld.cc:1334)
by: start_thread (in /lib64/libpthread-2.5.so)
by: clone (in /lib64/libc-2.5.so)

5.1.46-debug crash on Windows looks like this:

ntdll.dll!RtlCheckForOrphanedCriticalSections()
ntdll.dll!RtlCheckForOrphanedCriticalSections()
mysqld.exe!_sanity()[safemalloc.c:508]
mysqld.exe!_myfree()[safemalloc.c:265]
mysqld.exe!String::free()[sql_string.h:196]
mysqld.exe!String::~String()[sql_string.h:91]
mysqld.exe!`dynamic atexit destructor for 'my_empty_string''()
mysqld.exe!doexit()[crt0dat.c:553]
mysqld.exe!exit()[crt0dat.c:398]
mysqld.exe!win_main()[mysqld.cc:4581]
mysqld.exe!mysql_service()[mysqld.cc:4598]
mysqld.exe!main()[mysqld.cc:4784]
mysqld.exe!__tmainCRTStartup()[crt0.c:327]
mysqld.exe!mainCRTStartup()[crt0.c:196]
kernel32.dll!BaseProcessInitPostImport()

How to repeat:
not sure yet, this is a new problem. do many queries, then shutdown..

I still see this on 5.1.48-debug:

100618  7:29:55  InnoDB: Starting shutdown...
100618  7:29:57  InnoDB: Shutdown completed; log sequence number 0 52648630
100618  7:29:58 [Note] mysqld-debug: Shutdown complete

100618  7:29:58 - mysqld got exception 0xc0000005 ;
ntdll.dll!RtlValidateHeap()
ntdll.dll!RtlCheckForOrphanedCriticalSections()
mysqld-debug.exe!_sanity()[safemalloc.c:513]
mysqld-debug.exe!_myfree()[safemalloc.c:268]
mysqld-debug.exe!String::free()[sql_string.h:196]
mysqld-debug.exe!String::~String()[sql_string.h:91]
mysqld-debug.exe!`dynamic atexit destructor for 'my_empty_string''()
mysqld-debug.exe!doexit()[crt0dat.c:553]
mysqld-debug.exe!exit()[crt0dat.c:398]
mysqld-debug.exe!win_main()[mysqld.cc:4582]
mysqld-debug.exe!mysql_service()[mysqld.cc:4599]
mysqld-debug.exe!main()[mysqld.cc:4785]
mysqld-debug.exe!__tmainCRTStartup()[crt0.c:327]
mysqld-debug.exe!mainCRTStartup()[crt0.c:196]
kernel32.dll!BaseProcessInitPostImport()

still seeing this on 5.1.51-debug when shutting down after many many random tests.
 ntdll.dll!RtlpUnWaitCriticalSection()
 ntdll.dll!RtlGetDaclSecurityDescriptor()
 mysqld-debug.exe!_sanity()[safemalloc.c:522]
 mysqld-debug.exe!_myfree()[safemalloc.c:278]
 mysqld-debug.exe!String::free()[sql_string.h:197]
 mysqld-debug.exe!String::~String()[sql_string.h:91]
 mysqld-debug.exe!`dynamic atexit destructor for 'my_empty_string''()
 mysqld-debug.exe!doexit()[crt0dat.c:553]
 mysqld-debug.exe!exit()[crt0dat.c:399]
 mysqld-debug.exe!win_main()[mysqld.cc:4635]
 mysqld-debug.exe!mysql_service()[mysqld.cc:4653]
 mysqld-debug.exe!main()[mysqld.cc:4839]
 mysqld-debug.exe!__tmainCRTStartup()[crt0.c:327]
 mysqld-debug.exe!mainCRTStartup()[crt0.c:196]
 kernel32.dll!BaseProcessStart()

still happens on 5.1.52, after running random tests..

thd: 0x0
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...
0000000077EFBC0B    ntdll.dll!RtlpUnWaitCriticalSection()
0000000077EFBA20    ntdll.dll!RtlGetDaclSecurityDescriptor()
00000001406133A4    mysqld-debug.exe!_sanity()[safemalloc.c:522]
0000000140612BB2    mysqld-debug.exe!_myfree()[safemalloc.c:278]
00000001400794E2    mysqld-debug.exe!String::free()[sql_string.h:197]
00000001400793DD    mysqld-debug.exe!String::~String()[sql_string.h:91]
000000014071D4D6    mysqld-debug.exe!`dynamic atexit destructor for 'my_empty_string''()
0000000140002011    mysqld-debug.exe!doexit()[crt0dat.c:553]
0000000140001D36    mysqld-debug.exe!exit()[crt0dat.c:399]
0000000140058D75    mysqld-debug.exe!win_main()[mysqld.cc:4635]
000000014005BB14    mysqld-debug.exe!mysql_service()[mysqld.cc:4653]
000000014005BF7E    mysqld-debug.exe!main()[mysqld.cc:4839]
000000014000123C    mysqld-debug.exe!__tmainCRTStartup()[crt0.c:327]
000000014000100E    mysqld-debug.exe!mainCRTStartup()[crt0.c:196]
0000000077D596AC    kernel32.dll!BaseProcessStart()
The manual page at http://dev.mysql.com/doc/mysql/en/crashing.html contains
information that should help you find out what is causing the crash.

I'm really gonna need some help in debugging this.  Recording and rerunning a testcase isn't likely to happen here.  How to debug this from a crash dump, or in debugger ?

The problem is the following:

_sanity debug function is doing this:

pthread_mutex_lock(&THR_LOCK_malloc);

But that mutex is already destroyed...
The string object to blame for this is "my_empty_string".
=======================================
VERIFIER STOP 0000000000000210: pid 0x16E4: Critical section not initialized. 

	0000000140CA8E60 : Critical section address.
	0000000000000000 : Critical section debug info address.
	0000000000000000 : Not used.
	0000000000000000 : Not used.

=======================================
This verifier stop is continuable.
After debugging it use `go' to continue.

=======================================

(16e4.19cc): Break instruction exception - code 80000003 (first chance)
ntdll!DbgBreakPoint:
00000000`77ef2ab0 cc              int     3
0:000> k
Child-SP          RetAddr           Call Site
00000000`0012f3e8 00000001`800037ee ntdll!DbgBreakPoint
00000000`0012f3f0 00000000`02289770 vrfcore!VerifierStopMessageEx+0x772
00000000`0012f6f0 00000000`0228a85c vfbasics!AVrfpVerifyInitializedCriticalSection+0xa4
00000000`0012f740 00000000`0228a94e vfbasics!AVrfpRtlEnterCriticalSection2+0x40
00000000`0012f770 00000001`40614124 vfbasics!AVrfpRtlEnterCriticalSection+0x2a
00000000`0012f7a0 00000001`40613932 mysqld!_sanity+0x44 [e:\builds\bzr\mysql-5.1-security\mysys\safemalloc.c @ 522]
00000000`0012f800 00000001`40079672 mysqld!_myfree+0xc2 [e:\builds\bzr\mysql-5.1-security\mysys\safemalloc.c @ 278]
00000000`0012f8e0 00000001`4007956d mysqld!String::free+0x62 [e:\builds\bzr\mysql-5.1-security\sql\sql_string.h @ 201]
00000000`0012f910 00000001`4071e346 mysqld!String::~String+0x2d [e:\builds\bzr\mysql-5.1-security\sql\sql_string.h @ 95]
00000000`0012f940 00000001`40002011 mysqld!`dynamic atexit destructor for 'my_empty_string''+0x26
00000000`0012f970 00000001`40001d36 mysqld!doexit+0xb1 [f:\dd\vctools\crt_bld\self_64_amd64\crt\src\crt0dat.c @ 553]
00000000`0012f9b0 00000001`40058d75 mysqld!exit+0x16 [f:\dd\vctools\crt_bld\self_64_amd64\crt\src\crt0dat.c @ 399]
00000000`0012f9e0 00000001`4005bb14 mysqld!win_main+0x655 [e:\builds\bzr\mysql-5.1-security\sql\mysqld.cc @ 4635]
00000000`0012fc20 00000001`4005bf7e mysqld!mysql_service+0x54 [e:\builds\bzr\mysql-5.1-security\sql\mysqld.cc @ 4653]
00000000`0012fc50 00000001`4000123c mysqld!main+0x44e [e:\builds\bzr\mysql-5.1-security\sql\mysqld.cc @ 4839]
00000000`0012fee0 00000001`4000100e mysqld!__tmainCRTStartup+0x21c [f:\dd\vctools\crt_bld\self_64_amd64\crt\src\crt0.c @ 327]
00000000`0012ff50 00000000`77d596ac mysqld!mainCRTStartup+0xe [f:\dd\vctools\crt_bld\self_64_amd64\crt\src\crt0.c @ 196]
00000000`0012ff80 00000000`00000000 kernel32!BaseProcessStart+0x29
0:000> !cs 140CA8E60
-----------------------------------------
Critical section   = 0x0000000140ca8e60 (mysqld!THR_LOCK_malloc+0x0)
Uninitialized or deleted.
LOCKED
LockCount          = 0xFFFFFFFF
WaiterWoken        = Yes
OwningThread       = 0x0000000000000000
RecursionCount     = 0x0
LockSemaphore      = 0x0
SpinCount          = 0x0000000000000000

the crash is caused by bug #58165 ...

haven't seen this problem for a long time now. i think it's fixed.