-
Type:
Bug
-
Resolution: Cannot Reproduce
-
Priority:
Minor - P4
-
None
-
Affects Version/s: None
-
Component/s: Networking
-
Labels:None
-
Fully Compatible
-
ALL
-
-
Repl 18 (08/05/16), Platforms 17 (07/15/16)
I was hitting the following invariant in the replsets and replsets_WT suites under OS X and Windows DEBUG while patch testing some replication changes. The changes would have resulted in the thread pool task executor shutting down with some killCursor command in flight (see attached patch file). This is the stack trace from the logs when the invariant was triggered:
[js_test:replset7] 2016-06-24T23:45:38.401+0000 d20761| 2016-06-24T23:45:38.401+0000 I REPL [initial sync] initial sync finishing up
[js_test:replset7] 2016-06-24T23:45:38.401+0000 d20761| 2016-06-24T23:45:38.401+0000 I REPL [initial sync] set minValid={ ts: Timestamp 1466811937000|296, t: 1 }
[js_test:replset7] 2016-06-24T23:45:39.045+0000 d20761| 2016-06-24T23:45:39.044+0000 I REPL [initial sync] initial sync done
[js_test:replset7] 2016-06-24T23:45:39.049+0000 d20761| 2016-06-24T23:45:39.049+0000 I REPL [initial sync] Stopping replication fetcher thread for initial sync
[js_test:replset7] 2016-06-24T23:45:39.051+0000 d20761| 2016-06-24T23:45:39.051+0000 W EXECUTOR [initial sync] killCursors command task failed: CallbackCanceled: Callback canceled
[js_test:replset7] 2016-06-24T23:45:39.051+0000 d20761| 2016-06-24T23:45:39.051+0000 I - [initial sync] Invariant failure conn->getStatus() != kConnectionStateUnknown src\mongo\executor\connection_pool.cpp 295
[js_test:replset7] 2016-06-24T23:45:39.052+0000 d20761| 2016-06-24T23:45:39.051+0000 I - [initial sync]
[js_test:replset7] 2016-06-24T23:45:39.052+0000 d20761|
[js_test:replset7] 2016-06-24T23:45:39.052+0000 d20761| ***aborting after invariant() failure
[js_test:replset7] 2016-06-24T23:45:39.052+0000 d20761|
[js_test:replset7] 2016-06-24T23:45:39.052+0000 d20761|
[js_test:replset7] 2016-06-24T23:45:40.351+0000 d20761| 2016-06-24T23:45:40.352+0000 I CONTROL [initial sync] mongod.exe ...\src\mongo\util\stacktrace_windows.cpp(174) mongo::printStackTrace+0x43
[js_test:replset7] 2016-06-24T23:45:40.352+0000 d20761| 2016-06-24T23:45:40.352+0000 I CONTROL [initial sync] mongod.exe ...\src\mongo\util\signal_handlers_synchronous.cpp(181) mongo::`anonymous namespace'::printSignalAndBacktrace+0x73
[js_test:replset7] 2016-06-24T23:45:40.352+0000 d20761| 2016-06-24T23:45:40.352+0000 I CONTROL [initial sync] mongod.exe ...\src\mongo\util\signal_handlers_synchronous.cpp(237) mongo::`anonymous namespace'::abruptQuit+0x83
[js_test:replset7] 2016-06-24T23:45:40.352+0000 d20761| 2016-06-24T23:45:40.352+0000 I CONTROL [initial sync] mongod.exe d:\th\minkernel\crts\ucrt\src\appcrt\misc\signal.cpp(522) raise+0x468
[js_test:replset7] 2016-06-24T23:45:40.352+0000 d20761| 2016-06-24T23:45:40.352+0000 I CONTROL [initial sync] mongod.exe d:\th\minkernel\crts\ucrt\src\appcrt\startup\abort.cpp(71) abort+0x39
[js_test:replset7] 2016-06-24T23:45:40.352+0000 d20761| 2016-06-24T23:45:40.352+0000 I CONTROL [initial sync] mongod.exe ...\src\mongo\util\assert_util.cpp(154) mongo::invariantFailed+0x20c
[js_test:replset7] 2016-06-24T23:45:40.352+0000 d20761| 2016-06-24T23:45:40.353+0000 I CONTROL [initial sync] mongod.exe ...\src\mongo\executor\connection_pool.cpp(295) mongo::executor::ConnectionPool::SpecificPool::returnConnection+0x98
[js_test:replset7] 2016-06-24T23:45:40.352+0000 d20761| 2016-06-24T23:45:40.353+0000 I CONTROL [initial sync] mongod.exe ...\src\mongo\executor\connection_pool.cpp(237) mongo::executor::ConnectionPool::returnConnection+0x1eb
[js_test:replset7] 2016-06-24T23:45:40.354+0000 d20761| 2016-06-24T23:45:40.353+0000 I CONTROL [initial sync] mongod.exe mongo::executor::NetworkInterfaceASIO::AsyncOp::~AsyncOp+0xe0
[js_test:replset7] 2016-06-24T23:45:40.354+0000 d20761| 2016-06-24T23:45:40.353+0000 I CONTROL [initial sync] mongod.exe c:\program files (x86)\microsoft visual studio 14.0\vc\include\list(1514) std::list<std::pair<mongo::executor::NetworkInterfaceASIO::AsyncOp * __ptr64 const,std::unique_ptr<mongo::executor::NetworkInterfaceASIO::AsyncOp,std::default_delete<mongo::executor::NetworkInterfaceASIO::AsyncOp> > >,std::allocator<std::pair<mongo::executor::NetworkInterfaceASIO::AsyncOp * __ptr64 const,std::unique_ptr<mongo::executor::NetworkInterfaceASIO::AsyncOp,std::default_delete<mongo::executor::NetworkInterfaceASIO::AsyncOp> > > > >::clear+0xb4
[js_test:replset7] 2016-06-24T23:45:40.354+0000 d20761| 2016-06-24T23:45:40.353+0000 I CONTROL [initial sync] mongod.exe c:\program files (x86)\microsoft visual studio 14.0\vc\include\xhash(269) std::_Hash<std::_Umap_traits<mongo::executor::NetworkInterfaceASIO::AsyncOp * __ptr64,std::unique_ptr<mongo::executor::NetworkInterfaceASIO::AsyncOp,std::default_delete<mongo::executor::NetworkInterfaceASIO::AsyncOp> >,std::_Uhash_compare<mongo::executor::NetworkInterfaceASIO::AsyncOp * __ptr64,std::hash<mongo::executor::NetworkInterfaceASIO::AsyncOp * __ptr64>,std::equal_to<mongo::executor::NetworkInterfaceASIO::AsyncOp * __ptr64> >,std::allocator<std::pair<mongo::executor::NetworkInterfaceASIO::AsyncOp * __ptr64 const,std::unique_ptr<mongo::executor::NetworkInterfaceASIO::AsyncOp,std::default_delete<mongo::executor::NetworkInterfaceASIO::AsyncOp> > > >,0> >::~_Hash<std::_Umap_traits<mongo::executor::NetworkInterfaceASIO::AsyncOp * __ptr64,std::unique_ptr<mongo::executor::NetworkInterfaceASIO::AsyncOp,std::default_delete<mongo::executor::NetworkInterfaceASIO::AsyncOp> >,std::_Uhash_compare<mongo::executor::NetworkInterfaceASIO::AsyncOp * __ptr64,std::hash<mongo::executor::NetworkInterfaceASIO::AsyncOp * __pt+0x3e
[js_test:replset7] 2016-06-24T23:45:40.354+0000 d20761| 2016-06-24T23:45:40.353+0000 I CONTROL [initial sync] mongod.exe mongo::executor::NetworkInterfaceASIO::~NetworkInterfaceASIO+0x4a
[js_test:replset7] 2016-06-24T23:45:40.355+0000 d20761| 2016-06-24T23:45:40.353+0000 I CONTROL [initial sync] mongod.exe mongo::executor::NetworkInterfaceASIO::`scalar deleting destructor'+0x14
[js_test:replset7] 2016-06-24T23:45:40.355+0000 d20761| 2016-06-24T23:45:40.353+0000 I CONTROL [initial sync] mongod.exe ...\src\mongo\executor\thread_pool_task_executor.cpp(129) mongo::executor::ThreadPoolTaskExecutor::~ThreadPoolTaskExecutor+0x13a
[js_test:replset7] 2016-06-24T23:45:40.355+0000 d20761| 2016-06-24T23:45:40.353+0000 I CONTROL [initial sync] mongod.exe mongo::repl::BackgroundSync::~BackgroundSync+0x74
[js_test:replset7] 2016-06-24T23:45:40.355+0000 d20761| 2016-06-24T23:45:40.353+0000 I CONTROL [initial sync] mongod.exe ...\src\mongo\db\repl\rs_initialsync.cpp(576) mongo::repl::syncDoInitialSync+0x1ee
[js_test:replset7] 2016-06-24T23:45:40.355+0000 d20761| 2016-06-24T23:45:40.353+0000 I CONTROL [initial sync] mongod.exe c:\program files (x86)\microsoft visual studio 14.0\vc\include\thr\xthread(247) std::_LaunchPad<std::unique_ptr<std::tuple<<lambda_cfeef22a5b4e32645af7062ebc0b0bdc> >,std::default_delete<std::tuple<<lambda_cfeef22a5b4e32645af7062ebc0b0bdc> > > > >::_Run+0x7f
[js_test:replset7] 2016-06-24T23:45:40.355+0000 d20761| 2016-06-24T23:45:40.353+0000 I CONTROL [initial sync] mongod.exe c:\program files (x86)\microsoft visual studio 14.0\vc\include\thr\xthread(210) std::_Pad::_Call_func+0x9
[js_test:replset7] 2016-06-24T23:45:40.355+0000 d20761| 2016-06-24T23:45:40.354+0000 I CONTROL [initial sync] mongod.exe d:\th\minkernel\crts\ucrt\src\appcrt\startup\thread.cpp(92) invoke_thread_procedure+0x2c
[js_test:replset7] 2016-06-24T23:45:40.355+0000 d20761| 2016-06-24T23:45:40.354+0000 I CONTROL [initial sync] mongod.exe d:\th\minkernel\crts\ucrt\src\appcrt\startup\thread.cpp(115) thread_start<unsigned int (__cdecl*)(void * __ptr64)>+0x93
[js_test:replset7] 2016-06-24T23:45:40.355+0000 d20761| 2016-06-24T23:45:40.354+0000 I CONTROL [initial sync] kernel32.dll BaseThreadInitThunk+0xd
[js_test:replset7] 2016-06-24T23:45:40.355+0000 d20761| 2016-06-24T23:45:40.354+0000 F - [initial sync] Got signal: 22 (SIGABRT).
[js_test:replset7] 2016-06-24T23:45:40.355+0000 d20761| 2016-06-24T23:45:40.354+0000 I CONTROL [initial sync] *** unhandled exception 0x0000000E at 0x000007FEFCBAA06D, terminating
[js_test:replset7] 2016-06-24T23:45:40.357+0000 d20761| 2016-06-24T23:45:40.354+0000 I CONTROL [initial sync] *** stack trace for unhandled exception:
[js_test:replset7] 2016-06-24T23:45:40.706+0000 d20760| 2016-06-24T23:45:40.701+0000 I COMMAND [conn1] command d.c command: insert { insert: "c", documents: [ { _id: 8223.0, x: 3223.0, bigstring: "ayayayayayayayayayayayayayayayayayayayayayayayayayayayayayayayayayayayayayayayayayayayayay" } ], ordered: false } ninserted:1 keysInserted:2 numYields:0 reslen:89 locks:{ Global: { acquireCount: { r: 2, w: 2 } }, MMAPV1Journal: { acquireCount: { w: 2 }, acquireWaitCount: { w: 1 }, timeAcquiringMicros: { w: 156513 } }, Database: { acquireCount: { w: 2 } }, Collection: { acquireCount: { W: 1 } }, Metadata: { acquireCount: { w: 1 } }, oplog: { acquireCount: { W: 1 } } } protocol:op_command 156ms
[js_test:replset7] 2016-06-24T23:45:41.030+0000 d20760| 2016-06-24T23:45:41.030+0000 I WRITE [conn1] remove d.c query: { _id: 3331.0, x: 3331.0 } planSummary: IXSCAN { _id: 1 } keysExamined:1 docsExamined:1 ndeleted:1 keysDeleted:2 numYields:0 locks:{ Global: { acquireCount: { r: 2, w: 2 } }, MMAPV1Journal: { acquireCount: { w: 2 }, acquireWaitCount: { w: 1 }, timeAcquiringMicros: { w: 118138 } }, Database: { acquireCount: { w: 2 } }, Collection: { acquireCount: { W: 1 } }, Metadata: { acquireCount: { w: 1 } }, oplog: { acquireCount: { W: 1 } } } 118ms
[js_test:replset7] 2016-06-24T23:45:41.030+0000 d20760| 2016-06-24T23:45:41.031+0000 I COMMAND [conn1] command d.$cmd command: delete { delete: "c", deletes: [ { q: { _id: 3331.0, x: 3331.0 }, limit: 0.0 } ], ordered: false } numYields:0 reslen:89 locks:{ Global: { acquireCount: { r: 2, w: 2 } }, MMAPV1Journal: { acquireCount: { w: 2 }, acquireWaitCount: { w: 1 }, timeAcquiringMicros: { w: 118138 } }, Database: { acquireCount: { w: 2 } }, Collection: { acquireCount: { W: 1 } }, Metadata: { acquireCount: { w: 1 } }, oplog: { acquireCount: { W: 1 } } } protocol:op_command 119ms
[js_test:replset7] 2016-06-24T23:45:42.217+0000 d20760| 2016-06-24T23:45:42.144+0000 I WRITE [conn1] remove d.c query: { _id: 3739.0, x: 3739.0 } planSummary: IXSCAN { _id: 1 } keysExamined:1 docsExamined:1 ndeleted:1 keysDeleted:2 numYields:0 locks:{ Global: { acquireCount: { r: 2, w: 2 } }, MMAPV1Journal: { acquireCount: { w: 2 }, acquireWaitCount: { w: 1 }, timeAcquiringMicros: { w: 222094 } }, Database: { acquireCount: { w: 2 } }, Collection: { acquireCount: { W: 1 } }, Metadata: { acquireCount: { w: 1 } }, oplog: { acquireCount: { W: 1 } } } 223ms
[js_test:replset7] 2016-06-24T23:45:42.520+0000 d20760| 2016-06-24T23:45:42.144+0000 I COMMAND [conn1] command d.$cmd command: delete { delete: "c", deletes: [ { q: { _id: 3739.0, x: 3739.0 }, limit: 0.0 } ], ordered: false } numYields:0 reslen:89 locks:{ Global: { acquireCount: { r: 2, w: 2 } }, MMAPV1Journal: { acquireCount: { w: 2 }, acquireWaitCount: { w: 1 }, timeAcquiringMicros: { w: 222094 } }, Database: { acquireCount: { w: 2 } }, Collection: { acquireCount: { W: 1 } }, Metadata: { acquireCount: { w: 1 } }, oplog: { acquireCount: { W: 1 } } } protocol:op_command 223ms
[js_test:replset7] 2016-06-24T23:45:42.648+0000 d20761| 2016-06-24T23:45:42.148+0000 I CONTROL [initial sync] KERNELBASE.dll RaiseException+0x3d
[js_test:replset7] 2016-06-24T23:45:42.729+0000 d20761| 2016-06-24T23:45:42.148+0000 I CONTROL [initial sync] mongod.exe ...\src\mongo\util\signal_handlers_synchronous.cpp(238) mongo::`anonymous namespace'::abruptQuit+0x9b
[js_test:replset7] 2016-06-24T23:45:42.801+0000 d20761| 2016-06-24T23:45:42.148+0000 I CONTROL [initial sync] mongod.exe d:\th\minkernel\crts\ucrt\src\appcrt\misc\signal.cpp(522) raise+0x468
[js_test:replset7] 2016-06-24T23:45:42.825+0000 d20761| 2016-06-24T23:45:42.148+0000 I CONTROL [initial sync] mongod.exe d:\th\minkernel\crts\ucrt\src\appcrt\startup\abort.cpp(71) abort+0x39
[js_test:replset7] 2016-06-24T23:45:42.828+0000 d20761| 2016-06-24T23:45:42.148+0000 I CONTROL [initial sync] mongod.exe ...\src\mongo\util\assert_util.cpp(154) mongo::invariantFailed+0x20c
[js_test:replset7] 2016-06-24T23:45:42.882+0000 d20761| 2016-06-24T23:45:42.148+0000 I CONTROL [initial sync] mongod.exe ...\src\mongo\executor\connection_pool.cpp(295) mongo::executor::ConnectionPool::SpecificPool::returnConnection+0x98
[js_test:replset7] 2016-06-24T23:45:42.973+0000 d20761| 2016-06-24T23:45:42.148+0000 I CONTROL [initial sync] mongod.exe ...\src\mongo\executor\connection_pool.cpp(237) mongo::executor::ConnectionPool::returnConnection+0x1eb
[js_test:replset7] 2016-06-24T23:45:43.075+0000 d20761| 2016-06-24T23:45:42.148+0000 I CONTROL [initial sync] mongod.exe mongo::executor::NetworkInterfaceASIO::AsyncOp::~AsyncOp+0xe0
[js_test:replset7] 2016-06-24T23:45:43.278+0000 d20761| 2016-06-24T23:45:42.148+0000 I CONTROL [initial sync] mongod.exe c:\program files (x86)\microsoft visual studio 14.0\vc\include\list(1514) std::list<std::pair<mongo::executor::NetworkInterfaceASIO::AsyncOp * __ptr64 const,std::unique_ptr<mongo::executor::NetworkInterfaceASIO::AsyncOp,std::default_delete<mongo::executor::NetworkInterfaceASIO::AsyncOp> > >,std::allocator<std::pair<mongo::executor::NetworkInterfaceASIO::AsyncOp * __ptr64 const,std::unique_ptr<mongo::executor::NetworkInterfaceASIO::AsyncOp,std::default_delete<mongo::executor::NetworkInterfaceASIO::AsyncOp> > > > >::clear+0xb4
[js_test:replset7] 2016-06-24T23:45:43.394+0000 d20761| 2016-06-24T23:45:42.148+0000 I CONTROL [initial sync] mongod.exe c:\program files (x86)\microsoft visual studio 14.0\vc\include\xhash(269) std::_Hash<std::_Umap_traits<mongo::executor::NetworkInterfaceASIO::AsyncOp * __ptr64,std::unique_ptr<mongo::executor::NetworkInterfaceASIO::AsyncOp,std::default_delete<mongo::executor::NetworkInterfaceASIO::AsyncOp> >,std::_Uhash_compare<mongo::executor::NetworkInterfaceASIO::AsyncOp * __ptr64,std::hash<mongo::executor::NetworkInterfaceASIO::AsyncOp * __ptr64>,std::equal_to<mongo::executor::NetworkInterfaceASIO::AsyncOp * __ptr64> >,std::allocator<std::pair<mongo::executor::NetworkInterfaceASIO::AsyncOp * __ptr64 const,std::unique_ptr<mongo::executor::NetworkInterfaceASIO::AsyncOp,std::default_delete<mongo::executor::NetworkInterfaceASIO::AsyncOp> > > >,0> >::~_Hash<std::_Umap_traits<mongo::executor::NetworkInterfaceASIO::AsyncOp * __ptr64,std::unique_ptr<mongo::executor::NetworkInterfaceASIO::AsyncOp,std::default_delete<mongo::executor::NetworkInterfaceASIO::AsyncOp> >,std::_Uhash_compare<mongo::executor::NetworkInterfaceASIO::AsyncOp * __ptr64,std::hash<mongo::executor::NetworkInterfaceASIO::AsyncOp * __pt+0x3e
[js_test:replset7] 2016-06-24T23:45:43.566+0000 d20761| 2016-06-24T23:45:42.149+0000 I CONTROL [initial sync] mongod.exe mongo::executor::NetworkInterfaceASIO::~NetworkInterfaceASIO+0x4a
[js_test:replset7] 2016-06-24T23:45:43.956+0000 d20761| 2016-06-24T23:45:42.149+0000 I CONTROL [initial sync] mongod.exe mongo::executor::NetworkInterfaceASIO::`scalar deleting destructor'+0x14
[js_test:replset7] 2016-06-24T23:45:44.167+0000 d20761| 2016-06-24T23:45:42.149+0000 I CONTROL [initial sync] mongod.exe ...\src\mongo\executor\thread_pool_task_executor.cpp(129) mongo::executor::ThreadPoolTaskExecutor::~ThreadPoolTaskExecutor+0x13a
[js_test:replset7] 2016-06-24T23:45:44.358+0000 d20761| 2016-06-24T23:45:42.149+0000 I CONTROL [initial sync] mongod.exe mongo::repl::BackgroundSync::~BackgroundSync+0x74
[js_test:replset7] 2016-06-24T23:45:44.361+0000 d20761| 2016-06-24T23:45:42.149+0000 I CONTROL [initial sync] mongod.exe ...\src\mongo\db\repl\rs_initialsync.cpp(576) mongo::repl::syncDoInitialSync+0x1ee
[js_test:replset7] 2016-06-24T23:45:44.362+0000 d20761| 2016-06-24T23:45:42.149+0000 I CONTROL [initial sync] mongod.exe c:\program files (x86)\microsoft visual studio 14.0\vc\include\thr\xthread(247) std::_LaunchPad<std::unique_ptr<std::tuple<<lambda_cfeef22a5b4e32645af7062ebc0b0bdc> >,std::default_delete<std::tuple<<lambda_cfeef22a5b4e32645af7062ebc0b0bdc> > > > >::_Run+0x7f
[js_test:replset7] 2016-06-24T23:45:44.365+0000 d20761| 2016-06-24T23:45:42.149+0000 I CONTROL [initial sync] mongod.exe c:\program files (x86)\microsoft visual studio 14.0\vc\include\thr\xthread(210) std::_Pad::_Call_func+0x9
[js_test:replset7] 2016-06-24T23:45:44.367+0000 d20761| 2016-06-24T23:45:42.149+0000 I CONTROL [initial sync] mongod.exe d:\th\minkernel\crts\ucrt\src\appcrt\startup\thread.cpp(92) invoke_thread_procedure+0x2c
[js_test:replset7] 2016-06-24T23:45:44.368+0000 d20761| 2016-06-24T23:45:42.149+0000 I CONTROL [initial sync] mongod.exe d:\th\minkernel\crts\ucrt\src\appcrt\startup\thread.cpp(115) thread_start<unsigned int (__cdecl*)(void * __ptr64)>+0x93
[js_test:replset7] 2016-06-24T23:45:44.371+0000 d20761| 2016-06-24T23:45:42.149+0000 I CONTROL [initial sync] kernel32.dll BaseThreadInitThunk+0xd
[js_test:replset7] 2016-06-24T23:45:44.372+0000 d20761| 2016-06-24T23:45:42.149+0000 I - [initial sync]
[js_test:replset7] 2016-06-24T23:45:44.374+0000 d20761| 2016-06-24T23:45:42.150+0000 I CONTROL [initial sync] writing minidump diagnostic file C:\data\mci\a5401a952c0a9a5ef0cfbc5949babba3\src\mongod.2016-06-24T23-45-42.mdmp
- is related to
-
SERVER-24784 Oplog as Buffer: initial sync should shutdown BackgroundSync before transitioning to steady state replication
-
- Closed
-