Uploaded image for project: 'Core Server'
  1. Core Server
  2. SERVER-17796

Handle leak under low bit corruption

    • Type: Icon: Bug Bug
    • Resolution: Done
    • Priority: Icon: Major - P3 Major - P3
    • 3.1.3
    • 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

      
      

            Assignee:
            mark.benvenuto@mongodb.com Mark Benvenuto
            Reporter:
            eitan.klein Eitan Klein
            Votes:
            0 Vote for this issue
            Watchers:
            6 Start watching this issue

              Created:
              Updated:
              Resolved: