-
Type: Bug
-
Resolution: Done
-
Priority: Major - P3
-
Affects Version/s: None
-
Component/s: Concurrency
-
Fully Compatible
-
ALL
-
Platform 3 05/15/15
Environment:
1) Single mongod
db version v3.1.1-pre-
git version: 5e7aa5c9efdea28cc82ff8d0ea0e3a76cf5c94f8
OpenSSL version: OpenSSL 1.0.1m-fips 19 Mar 2015
Test
1) Running apitest_dbcollection.js in a loop using a modify mongo.exe that corrupt/flip few bits randomly before sending the packet to the network.
you can find the modified version @ \\eitan5\tmp\mongoc.zip
2) Problem, you will see handle count growth as result of the problematic connections.
in order to isolate the issue, i used application verifier
A) Enable application verifier for mongod (using gflags)
B) Run w/ windbg attached to the process
C) It will repro in few iteration
5) App verifiy identify the problem release critical section was not called before free the objection (Details below)
=======================================
VERIFIER STOP 0000000000000202: pid 0x1798: Freeing heap block containing an active critical section.
000000D4B822B700 : Critical section address. Run !cs -s <address> to get more information.
000000D4A6CED980 : Critical section initialization stack trace. Run dps <address> to dump the stack trace.
000000D4B822B5A0 : Heap block address.
00000000000001D8 : Heap block size.
=======================================
This verifier stop is continuable.
After debugging it use `go' to continue.
=======================================
(1798.447c): Break instruction exception - code 80000003 (first chance)
verifier!VerifierStopMessageEx+0x6f0:
00007ffd`084fb370 cc int 3
0:099> k
Child-SP RetAddr Call Site
000000d4`bac9dc20 00007ffd`08507176 verifier!VerifierStopMessageEx+0x6f0
000000d4`bac9dfa0 00007ffd`08504248 verifier!AVrfpFreeMemLockChecks+0xee
000000d4`bac9e000 00007ffd`08514ae8 verifier!AVrfpFreeMemNotify+0x38
000000d4`bac9e030 00007ffd`054569d8 verifier!AVrfpHeapFree+0x98
000000d4`bac9e0c0 00007ff7`2f4f0621 MSVCR120!free+0x1c
000000d4`bac9e0f0 00007ff7`2f894016 mongod!mongo::Collection::`scalar deleting destructor'+0x21
000000d4`bac9e120 00007ff7`2f59fd7c mongod!mongo::WiredTigerRecoveryUnit::_commit+0x46 [c:\data\mci\shell\src\src\mongo\db\storage\wiredtiger\wiredtiger_recovery_unit.cpp @ 120]
000000d4`bac9e160 00007ff7`2f59a85a mongod!mongo::CmdDrop::run+0xb0c [c:\data\mci\shell\src\src\mongo\db\dbcommands.cpp @ 536]
000000d4`bac9e5b0 00007ff7`2f59cf47 mongod!mongo::_execCommand+0x6a [c:\data\mci\shell\src\src\mongo\db\dbcommands.cpp @ 1322]
000000d4`bac9e7d0 00007ff7`2f59acd8 mongod!mongo::Command::execCommand+0xe47 [c:\data\mci\shell\src\src\mongo\db\dbcommands.cpp @ 1545]
000000d4`bac9ed60 00007ff7`2f5a4053 mongod!mongo::_runCommands+0x458 [c:\data\mci\shell\src\src\mongo\db\dbcommands.cpp @ 1616]
000000d4`bac9f0c0 00007ff7`2f652a18 mongod!mongo::runCommands+0x43 [c:\data\mci\shell\src\src\mongo\db\dbcommands.cpp @ 1644]
000000d4`bac9f140 00007ff7`2f64f186 mongod!mongo::receivedCommand+0x418 [c:\data\mci\shell\src\src\mongo\db\instance.cpp @ 269]
000000d4`bac9f3a0 00007ff7`2fcb427a mongod!mongo::assembleResponse+0x7c6 [c:\data\mci\shell\src\src\mongo\db\instance.cpp @ 495]
000000d4`bac9fa90 00007ff7`2f9743c3 mongod!mongo::MyMessageHandler::process+0xba [c:\data\mci\shell\src\src\mongo\db\db.cpp @ 213]
000000d4`bac9fc50 00007ff7`2f9d6f01 mongod!mongo::PortMessageServer::handleIncomingMsg+0x573 [c:\data\mci\shell\src\src\mongo\util\net\message_server_port.cpp @ 233]
000000d4`bac9fe70 00007ffd`05414f7f mongod!boost::`anonymous namespace'::thread_start_function+0x21 [c:\data\mci\shell\src\src\third_party\boost-1.56.0\libs\thread\src\win32\thread.cpp @ 215]
000000d4`bac9feb0 00007ffd`05415126 MSVCR120!beginthreadex+0x107
000000d4`bac9fee0 00007ffd`085195cd MSVCR120!endthreadex+0x192
000000d4`bac9ff10 00007ffd`1b6913d2 verifier!AVrfpStandardThreadFunction+0x4d
000000d4`bac9ff50 00007ffd`1c4ee954 KERNEL32!BaseThreadInitThunk+0x22
000000d4`bac9ff80 00000000`00000000 ntdll!RtlUserThreadStart+0x34
0:099> !avrf
Application verifier settings (00048004):
- fast fill heap (a.k.a light page heap)
- lock checks (critical section verifier)
- handle checks
*******************************************************************************
- *
- Exception Analysis *
- *
*******************************************************************************
APPLICATION_VERIFIER_LOCKS_LOCK_IN_FREED_HEAP (202)
Freeing heap block containing an active critical section.
This stop is generated if a heap allocation contains a critical section,
the allocation is freed and the critical section has not been deleted.
To debug this stop use the following debugger commands:
$ !cs -s parameter1 - dump information about this critical section.
$ ln parameter1 - to show symbols near the address of the critical section.
This should help identify the leaked critical section.
$ dps parameter2 - to dump the stack trace for this critical section initialization.
$ parameter3 and parameter4 might help understand where this heap block was
allocated (the size of the allocation is probably significant).
Arguments:
Arg1: 000000d4b822b700, Critical section address. Run !cs -s <address> to get more information.
Arg2: 000000d4a6ced980, Critical section initialization stack trace. Run dps <address> to dump the stack trace.
Arg3: 000000d4b822b5a0, Heap block address.
Arg4: 00000000000001d8, Heap block size.
FAULTING_IP:
verifier!VerifierStopMessageEx+6f0
00007ffd`084fb370 cc int 3
EXCEPTION_RECORD: ffffffffffffffff – (.exr 0xffffffffffffffff)
ExceptionAddress: 00007ffd084fb370 (verifier!VerifierStopMessageEx+0x00000000000006f0)
ExceptionCode: 80000003 (Break instruction exception)
ExceptionFlags: 00000000
NumberParameters: 1
Parameter[0]: 0000000000000000
CONTEXT: 0000000000000000 – (.cxr 0x0;r)
rax=000000d4edc5f1e0 rbx=00007ffd085226b0 rcx=00007ff72e802000
rdx=0000000000000000 rsi=000000d4b822b700 rdi=00000000000003fe
rip=00007ffd084fb370 rsp=000000d4bac9dc20 rbp=00000000000001d8
r8=0000000000000000 r9=00007ffd0852a4a0 r10=0000000000000000
r11=0000000000000000 r12=00000000000001a1 r13=0000000000000202
r14=000000d4b822b5a0 r15=00000000000001d8
iopl=0 nv up ei pl nz na pe nc
cs=0033 ss=002b ds=002b es=002b fs=0053 gs=002b efl=00000200
verifier!VerifierStopMessageEx+0x6f0:
00007ffd`084fb370 cc int 3
FAULTING_THREAD: 000000000000447c
DEFAULT_BUCKET_ID: STATUS_BREAKPOINT
PROCESS_NAME: mongod.exe
CRITICAL_SECTION: 000000d4b822b700 – (!cs -s 000000d4b822b700)
ERROR_CODE: (NTSTATUS) 0x80000003 -
{EXCEPTION}Breakpoint A breakpoint has been reached.
EXCEPTION_CODE: (HRESULT) 0x80000003 (2147483651) - One or more arguments are invalid
EXCEPTION_PARAMETER1: 0000000000000000
NTGLOBALFLAG: 2000100
APPLICATION_VERIFIER_FLAGS: 48004
APP: mongod.exe
ANALYSIS_VERSION: 6.3.9600.17298 (debuggers(dbg).141024-1500) amd64fre
PRIMARY_PROBLEM_CLASS: STATUS_BREAKPOINT
BUGCHECK_STR: APPLICATION_FAULT_STATUS_BREAKPOINT
LAST_CONTROL_TRANSFER: from 00007ffd08507176 to 00007ffd084fb370
STACK_TEXT:
000000d4`bac9dc20 00007ffd`08507176 : 000000d4`edc524d0 000000d4`a8360000 000000d4`b822b500 000000d4`a8361000 : verifier!VerifierStopMessageEx+0x6f0
000000d4`bac9dfa0 00007ffd`08504248 : 00000000`000001d8 00000000`00000000 00000000`00000000 000000d4`b83f95a0 : verifier!AVrfpFreeMemLockChecks+0xee
000000d4`bac9e000 00007ffd`08514ae8 : 000000d4`b822b5a0 000000d4`bac9ee60 00000000`000001d8 000000d4`a8360000 : verifier!AVrfpFreeMemNotify+0x38
000000d4`bac9e030 00007ffd`054569d8 : 000000d4`a8360000 00007ff7`00000000 000000d4`b822b5a0 000000d4`00000000 : verifier!AVrfpHeapFree+0x98
000000d4`bac9e0c0 00007ff7`2f4f0621 : 000000d4`b822b5a0 00000000`00000020 000000d4`e30decf0 00000000`00000020 : MSVCR120!free+0x1c
000000d4`bac9e0f0 00007ff7`2f894016 : 000000d4`e3093fe8 000000d4`bac9fb50 00009f5e`d63bc6d6 000000d4`bac9f2b0 : mongod!mongo::Collection::`scalar deleting destructor'+0x21
000000d4`bac9e120 00007ff7`2f59fd7c : 000000d4`bac9fb50 00000000`ffffffff 00000000`ffffffff 000000d4`bac9f2b0 : mongod!mongo::WiredTigerRecoveryUnit::_commit+0x46
000000d4`bac9e160 00007ff7`2f59a85a : 00000000`00000000 00000000`00000000 00000000`00000000 00000000`00000000 : mongod!mongo::CmdDrop::run+0xb0c
000000d4`bac9e5b0 00007ff7`2f59cf47 : 00000000`00000000 000000d4`bac9ee60 00007ff7`301889e0 00000000`00000000 : mongod!mongo::_execCommand+0x6a
000000d4`bac9e7d0 00007ff7`2f59acd8 : 000000d4`aedf1466 ffffffff`ffffffff ffffffff`ffffffff 00000000`00000000 : mongod!mongo::Command::execCommand+0xe47
000000d4`bac9ed60 00007ff7`2f5a4053 : 000000d4`bac9f2b8 00007ff7`2f959c9c 000000d4`bac9f2b0 00000000`00000000 : mongod!mongo::_runCommands+0x458
000000d4`bac9f0c0 00007ff7`2f652a18 : 000000d4`bac9f2b0 000000d4`e3183940 000000d4`e3183940 000000d4`b8492e30 : mongod!mongo::runCommands+0x43
000000d4`bac9f140 00007ff7`2f64f186 : 000000d4`b883ac90 000000d4`bac9fb90 00000000`00000001 00000000`00000000 : mongod!mongo::receivedCommand+0x418
000000d4`bac9f3a0 00007ff7`2fcb427a : 000000d4`bac9fb50 000000d4`b84bec80 000000d4`b84bec80 00007ffd`08512e7f : mongod!mongo::assembleResponse+0x7c6
000000d4`bac9fa90 00007ff7`2f9743c3 : 00000000`00000000 00000000`00000000 00000000`00000000 00000000`00000000 : mongod!mongo::MyMessageHandler::process+0xba
000000d4`bac9fc50 00007ff7`2f9d6f01 : 000000d4`aedd2190 000000d4`b830fa20 000000d4`b883a7a0 00000000`00000000 : mongod!mongo::PortMessageServer::handleIncomingMsg+0x573
000000d4`bac9fe70 00007ffd`05414f7f : 000000d4`b830fa20 00000000`00000000 000000d4`b830fa20 00000000`00000000 : mongod!boost::`anonymous namespace'::thread_start_function+0x21
000000d4`bac9feb0 00007ffd`05415126 : 00007ffd`054ccb80 00000000`00000000 00000000`00000000 00000000`00000000 : MSVCR120!beginthreadex+0x107
000000d4`bac9fee0 00007ffd`085195cd : 00007ffd`05415024 000000d4`edc5e770 00000000`00000000 00000000`00000000 : MSVCR120!endthreadex+0x192
000000d4`bac9ff10 00007ffd`1b6913d2 : 00007ffd`08519580 00000000`00000000 00000000`00000000 00000000`00000000 : verifier!AVrfpStandardThreadFunction+0x4d
000000d4`bac9ff50 00007ffd`1c4ee954 : 00007ffd`1b6913b0 00000000`00000000 00000000`00000000 00000000`00000000 : KERNEL32!BaseThreadInitThunk+0x22
000000d4`bac9ff80 00000000`00000000 : 00000000`00000000 00000000`00000000 00000000`00000000 00000000`00000000 : ntdll!RtlUserThreadStart+0x34
STACK_COMMAND: .cxr 0x0 ; kb
FOLLOWUP_IP:
mongod!mongo::WiredTigerRecoveryUnit::_commit+46 [c:\data\mci\shell\src\src\mongo\db\storage\wiredtiger\wiredtiger_recovery_unit.cpp @ 120]
00007ff7`2f894016 4883c308 add rbx,8
FAULTING_SOURCE_LINE: c:\data\mci\shell\src\src\mongo\db\storage\wiredtiger\wiredtiger_recovery_unit.cpp
FAULTING_SOURCE_FILE: c:\data\mci\shell\src\src\mongo\db\storage\wiredtiger\wiredtiger_recovery_unit.cpp
FAULTING_SOURCE_LINE_NUMBER: 120
SYMBOL_STACK_INDEX: 6
SYMBOL_NAME: mongod!mongo::WiredTigerRecoveryUnit::_commit+46
FOLLOWUP_NAME: MachineOwner
MODULE_NAME: mongod
IMAGE_NAME: mongod.exe
DEBUG_FLR_IMAGE_TIMESTAMP: 5516095c
FAILURE_BUCKET_ID: STATUS_BREAKPOINT_80000003_mongod.exe!mongo::WiredTigerRecoveryUnit::_commit
BUCKET_ID: APPLICATION_FAULT_STATUS_BREAKPOINT_mongod!mongo::WiredTigerRecoveryUnit::_commit+46
ANALYSIS_SOURCE: UM
FAILURE_ID_HASH_STRING: um:status_breakpoint_80000003_mongod.exe!mongo::wiredtigerrecoveryunit::_commit
FAILURE_ID_HASH:
{8420d324-b64c-0259-3bad-6df003a9ac2f}Followup: MachineOwner
---------
0:099> .cxr 0x0;r
rax=000000d4edc5f1e0 rbx=00007ffd085226b0 rcx=00007ff72e802000
rdx=0000000000000000 rsi=000000d4b822b700 rdi=00000000000003fe
rip=00007ffd084fb370 rsp=000000d4bac9dc20 rbp=00000000000001d8
r8=0000000000000000 r9=00007ffd0852a4a0 r10=0000000000000000
r11=0000000000000000 r12=00000000000001a1 r13=0000000000000202
r14=000000d4b822b5a0 r15=00000000000001d8
iopl=0 nv up ei pl nz na pe nc
cs=0033 ss=002b ds=002b es=002b fs=0053 gs=002b efl=00000200
verifier!VerifierStopMessageEx+0x6f0:
00007ffd`084fb370 cc int 3
0:099> k
Child-SP RetAddr Call Site
000000d4`bac9dc20 00007ffd`08507176 verifier!VerifierStopMessageEx+0x6f0
000000d4`bac9dfa0 00007ffd`08504248 verifier!AVrfpFreeMemLockChecks+0xee
000000d4`bac9e000 00007ffd`08514ae8 verifier!AVrfpFreeMemNotify+0x38
000000d4`bac9e030 00007ffd`054569d8 verifier!AVrfpHeapFree+0x98
000000d4`bac9e0c0 00007ff7`2f4f0621 MSVCR120!free+0x1c
000000d4`bac9e0f0 00007ff7`2f894016 mongod!mongo::Collection::`scalar deleting destructor'+0x21
000000d4`bac9e120 00007ff7`2f59fd7c mongod!mongo::WiredTigerRecoveryUnit::_commit+0x46 [c:\data\mci\shell\src\src\mongo\db\storage\wiredtiger\wiredtiger_recovery_unit.cpp @ 120]
000000d4`bac9e160 00007ff7`2f59a85a mongod!mongo::CmdDrop::run+0xb0c [c:\data\mci\shell\src\src\mongo\db\dbcommands.cpp @ 536]
000000d4`bac9e5b0 00007ff7`2f59cf47 mongod!mongo::_execCommand+0x6a [c:\data\mci\shell\src\src\mongo\db\dbcommands.cpp @ 1322]
000000d4`bac9e7d0 00007ff7`2f59acd8 mongod!mongo::Command::execCommand+0xe47 [c:\data\mci\shell\src\src\mongo\db\dbcommands.cpp @ 1545]
000000d4`bac9ed60 00007ff7`2f5a4053 mongod!mongo::_runCommands+0x458 [c:\data\mci\shell\src\src\mongo\db\dbcommands.cpp @ 1616]
000000d4`bac9f0c0 00007ff7`2f652a18 mongod!mongo::runCommands+0x43 [c:\data\mci\shell\src\src\mongo\db\dbcommands.cpp @ 1644]
000000d4`bac9f140 00007ff7`2f64f186 mongod!mongo::receivedCommand+0x418 [c:\data\mci\shell\src\src\mongo\db\instance.cpp @ 269]
000000d4`bac9f3a0 00007ff7`2fcb427a mongod!mongo::assembleResponse+0x7c6 [c:\data\mci\shell\src\src\mongo\db\instance.cpp @ 495]
000000d4`bac9fa90 00007ff7`2f9743c3 mongod!mongo::MyMessageHandler::process+0xba [c:\data\mci\shell\src\src\mongo\db\db.cpp @ 213]
000000d4`bac9fc50 00007ff7`2f9d6f01 mongod!mongo::PortMessageServer::handleIncomingMsg+0x573 [c:\data\mci\shell\src\src\mongo\util\net\message_server_port.cpp @ 233]
000000d4`bac9fe70 00007ffd`05414f7f mongod!boost::`anonymous namespace'::thread_start_function+0x21 [c:\data\mci\shell\src\src\third_party\boost-1.56.0\libs\thread\src\win32\thread.cpp @ 215]
000000d4`bac9feb0 00007ffd`05415126 MSVCR120!beginthreadex+0x107
000000d4`bac9fee0 00007ffd`085195cd MSVCR120!endthreadex+0x192
000000d4`bac9ff10 00007ffd`1b6913d2 verifier!AVrfpStandardThreadFunction+0x4d
000000d4`bac9ff50 00007ffd`1c4ee954 KERNEL32!BaseThreadInitThunk+0x22
000000d4`bac9ff80 00000000`00000000 ntdll!RtlUserThreadStart+0x34
0:099> !cs -s 000000D4B822B700
-----------------------------------------
Critical section = 0x000000d4b822b700 (+0xD4B822B700)
DebugInfo = 0x000000d4b8300a90
NOT LOCKED
LockSemaphore = 0x0
SpinCount = 0x00000000020007d0
Stack trace for DebugInfo = 0x000000d4b8300a90:
0x00007ffd1c534368: ntdll!RtlInitializeCriticalSectionAndSpinCount+0x52BE8
0x00007ffd0850780a: verifier!AVrfpInitializeCriticalSectionCommon+0x126
0x00007ff72f4f8ef3: mongod!mongo::CursorManager::CursorManager+0x43
0x00007ff72f4effb9: mongod!mongo::Collection::Collection+0xA9
0x00007ff72f4fd519: mongod!mongo::Database::_getOrCreateCollectionInstance+0x119
0x00007ff72f4fe5c6: mongod!mongo::Database::createCollection+0x5F6
0x00007ff72f582348: mongod!mongo::WriteBatchExecutor::ExecInsertsState::_lockAndCheckImpl+0x4C8
0x00007ff72f5854dd: mongod!mongo::insertOne+0x13D
0x00007ff72f583fe5: mongod!mongo::WriteBatchExecutor::execOneInsert+0xF5
0x00007ff72f583e1f: mongod!mongo::WriteBatchExecutor::execInserts+0x15F
0x00007ff72f5831bf: mongod!mongo::WriteBatchExecutor::bulkExecute+0x4F
0x00007ff72f5847a4: mongod!mongo::WriteBatchExecutor::executeBatch+0x384
0x00007ff72f58a0be: mongod!mongo::WriteCmd::run+0x25E
0x00007ff72f59a85a: mongod!mongo::_execCommand+0x6A
0x00007ff72f59cf47: mongod!mongo::Command::execCommand+0xE47
0x00007ff72f59acd8: mongod!mongo::_runCommands+0x458
0x00007ff72f5a4053: mongod!mongo::runCommands+0x43
0x00007ff72f652a18: mongod!mongo::receivedCommand+0x418
0x00007ff72f64f186: mongod!mongo::assembleResponse+0x7C6
0x00007ff72fcb427a: mongod!mongo::MyMessageHandler::process+0xBA
Stack trace for DebugInfo = 0x000000d4b8300a90:
0x00007ffd1c534368: ntdll!RtlInitializeCriticalSectionAndSpinCount+0x52BE8
0x00007ffd0850780a: verifier!AVrfpInitializeCriticalSectionCommon+0x126
0x00007ff72f4f8ef3: mongod!mongo::CursorManager::CursorManager+0x43
0x00007ff72f4effb9: mongod!mongo::Collection::Collection+0xA9
0x00007ff72f4fd519: mongod!mongo::Database::_getOrCreateCollectionInstance+0x119
0x00007ff72f4fe5c6: mongod!mongo::Database::createCollection+0x5F6
0x00007ff72f582348: mongod!mongo::WriteBatchExecutor::ExecInsertsState::_lockAndCheckImpl+0x4C8
0x00007ff72f5854dd: mongod!mongo::insertOne+0x13D
0x00007ff72f583fe5: mongod!mongo::WriteBatchExecutor::execOneInsert+0xF5
0x00007ff72f583e1f: mongod!mongo::WriteBatchExecutor::execInserts+0x15F
0x00007ff72f5831bf: mongod!mongo::WriteBatchExecutor::bulkExecute+0x4F
0x00007ff72f5847a4: mongod!mongo::WriteBatchExecutor::executeBatch+0x384
0x00007ff72f58a0be: mongod!mongo::WriteCmd::run+0x25E
0x00007ff72f59a85a: mongod!mongo::_execCommand+0x6A
0x00007ff72f59cf47: mongod!mongo::Command::execCommand+0xE47
0x00007ff72f59acd8: mongod!mongo::_runCommands+0x458
0x00007ff72f5a4053: mongod!mongo::runCommands+0x43
0x00007ff72f652a18: mongod!mongo::receivedCommand+0x418
0x00007ff72f64f186: mongod!mongo::assembleResponse+0x7C6
0x00007ff72fcb427a: mongod!mongo::MyMessageHandler::process+0xBA
0:099> ln 000000d4a6ced980