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

"Reading from replicated collection without read timestamp or PBWM lock" crash with clock changes

    XMLWordPrintable

Details

    • Bug
    • Status: Closed
    • Blocker - P1
    • Resolution: Fixed
    • 4.4.9
    • 4.4.16
    • None
    • Fully Compatible
    • ALL
    • Hide

      You can reproduce this with https://github.com/jepsen-io/mongodb at commit 90f88cebe37f8d0579d880177929941af83c65a9, by running (e.g.)

      lein run test-all --txn-write-concern majority --txn-read-concern snapshot --write-concern majority --read-concern linearizable --concurrency 3n --rate 500 --nemesis clock --time-limit 600

      Show
      You can reproduce this with https://github.com/jepsen-io/mongodb at commit 90f88cebe37f8d0579d880177929941af83c65a9, by running (e.g.) lein run test-all --txn-write-concern majority --txn-read-concern snapshot --write-concern majority --read-concern linearizable --concurrency 3n --rate 500 --nemesis clock --time-limit 600
    • Repl 2022-06-27

    Description

      I've found what appears to be a fairly reliable crash in MongoDB 4.4.9, running a single five-node replica set on Debian Stable. When we set CLOCK_REALTIME forward and back by anywhere from a few millis to a hundred-odd seconds, it has a tendency to throw a fatal assertion like:

      {"t":{"$date":"2022-06-15T13:16:50.606+00:00"},"s":"I",  "c":"REPL",     "id":21215,   "ctx":"ReplCoord-3","msg":"Member is in new state","attr":{"hostAndPort":"ec2-54-90-123-74.compute-1.amazonaws.com:27018","newState":"SECONDARY"}}
      {"t":{"$date":"2022-06-15T13:17:18.237+00:00"},"s":"I",  "c":"REPL",     "id":21365,   "ctx":"ReplCoord-6","msg":"Heartbeats updated catchup target optime","attr":{"targetOpTime":{"ts":{"$timestamp":{"t":1655299041,"i":73}},"t":30}}}
      {"t":{"$date":"2022-06-15T13:17:18.237+00:00"},"s":"I",  "c":"REPL",     "id":21366,   "ctx":"ReplCoord-6","msg":"Latest known optime per replica set member"}
      {"t":{"$date":"2022-06-15T13:17:18.237+00:00"},"s":"I",  "c":"REPL",     "id":21367,   "ctx":"ReplCoord-6","msg":"Latest known optime","attr":{"memberId":"MemberId(0)","latestKnownOpTime":"{ ts: Timestamp(1655299041, 73), t: 30 }"}}
      {"t":{"$date":"2022-06-15T13:17:18.237+00:00"},"s":"I",  "c":"REPL",     "id":21367,   "ctx":"ReplCoord-6","msg":"Latest known optime","attr":{"memberId":"MemberId(1)","latestKnownOpTime":"{ ts: Timestamp(1655299041, 69), t: 29 }"}}
      {"t":{"$date":"2022-06-15T13:17:18.237+00:00"},"s":"I",  "c":"REPL",     "id":21367,   "ctx":"ReplCoord-6","msg":"Latest known optime","attr":{"memberId":"MemberId(2)","latestKnownOpTime":"{ ts: Timestamp(1655299041, 59), t: 28 }"}}
      {"t":{"$date":"2022-06-15T13:17:18.237+00:00"},"s":"I",  "c":"REPL",     "id":21367,   "ctx":"ReplCoord-6","msg":"Latest known optime","attr":{"memberId":"MemberId(3)","latestKnownOpTime":"unknown"}}
      {"t":{"$date":"2022-06-15T13:17:18.237+00:00"},"s":"I",  "c":"REPL",     "id":21367,   "ctx":"ReplCoord-6","msg":"Latest known optime","attr":{"memberId":"MemberId(4)","latestKnownOpTime":"unknown"}}
      {"t":{"$date":"2022-06-15T13:17:18.674+00:00"},"s":"F",  "c":"STORAGE",  "id":4728700, "ctx":"conn22143","msg":"Reading from replicated collection without read timestamp or PBWM lock","attr":{"collection":"jepsendb.jepsencoll"}}
      {"t":{"$date":"2022-06-15T13:17:18.674+00:00"},"s":"F",  "c":"-",        "id":23089,   "ctx":"conn22143","msg":"Fatal assertion","attr":{"msgid":4728700,"file":"src/mongo/db/db_raii.cpp","line":160}}
      {"t":{"$date":"2022-06-15T13:17:18.674+00:00"},"s":"F",  "c":"-",        "id":23090,   "ctx":"conn22143","msg":"\n\n***aborting after fassert() failure\n\n"}
      {"t":{"$date":"2022-06-15T13:17:18.674+00:00"},"s":"F",  "c":"CONTROL",  "id":4757800, "ctx":"conn22143","msg":"Writing fatal message","attr":{"message":"Got signal: 6 (Aborted).\n"}}
      {"t":{"$date":"2022-06-15T13:16:51.050+00:00"},"s":"I",  "c":"NETWORK",  "id":22943,   "ctx":"listener","msg":"Connection accepted","attr":{"remote":"172.31.11.147:35176","connectionId":22156,"connectionCount":22}}
      {"t":{"$date":"2022-06-15T13:16:51.051+00:00"},"s":"I",  "c":"NETWORK",  "id":22943,   "ctx":"listener","msg":"Connection accepted","attr":{"remote":"172.31.11.147:35174","connectionId":22157,"connectionCount":23}}
      {"t":{"$date":"2022-06-15T13:17:18.686+00:00"},"s":"I",  "c":"NETWORK",  "id":51800,   "ctx":"conn22157","msg":"client metadata","attr":{"remote":"172.31.11.147:35174","client":"conn22157","doc":{"driver":{"name":"mongo-java-driver|sync","version":"4.6.0"},"os":{"type":"Linux","name":"Linux","architecture":"amd64","version":"5.10.0-13-cloud-amd64"},"platform":"Java/Debian/11.0.15+10-post-Debian-1deb11u1"}}}
      {"t":{"$date":"2022-06-15T13:17:18.686+00:00"},"s":"I",  "c":"NETWORK",  "id":51800,   "ctx":"conn22156","msg":"client metadata","attr":{"remote":"172.31.11.147:35176","client":"conn22156","doc":{"driver":{"name":"mongo-java-driver|sync","version":"4.6.0"},"os":{"type":"Linux","name":"Linux","architecture":"amd64","version":"5.10.0-13-cloud-amd64"},"platform":"Java/Debian/11.0.15+10-post-Debian-1deb11u1"}}}
      {"t":{"$date":"2022-06-15T13:16:51.059+00:00"},"s":"I",  "c":"NETWORK",  "id":22943,   "ctx":"listener","msg":"Connection accepted","attr":{"remote":"172.31.11.147:35186","connectionId":22158,"connectionCount":24}}
      {"t":{"$date":"2022-06-15T13:16:51.059+00:00"},"s":"I",  "c":"NETWORK",  "id":51800,   "ctx":"conn22158","msg":"client metadata","attr":{"remote":"172.31.11.147:35186","client":"conn22158","doc":{"driver":{"name":"mongo-java-driver|sync","version":"4.6.0"},"os":{"type":"Linux","name":"Linux","architecture":"amd64","version":"5.10.0-13-cloud-amd64"},"platform":"Java/Debian/11.0.15+10-post-Debian-1deb11u1"}}}
      {"t":{"$date":"2022-06-15T13:16:51.062+00:00"},"s":"I",  "c":"-",        "id":20883,   "ctx":"conn22157","msg":"Interrupted operation as its client disconnected","attr":{"opId":1131629}}
      {"t":{"$date":"2022-06-15T13:16:51.063+00:00"},"s":"I",  "c":"NETWORK",  "id":22944,   "ctx":"conn22156","msg":"Connection ended","attr":{"remote":"172.31.11.147:35176","connectionId":22156,"connectionCount":22}}
      {"t":{"$date":"2022-06-15T13:16:51.063+00:00"},"s":"I",  "c":"NETWORK",  "id":22944,   "ctx":"conn22157","msg":"Connection ended","attr":{"remote":"172.31.11.147:35174","connectionId":22157,"connectionCount":21}}
      {"t":{"$date":"2022-06-15T13:16:51.062+00:00"},"s":"I",  "c":"NETWORK",  "id":22944,   "ctx":"conn22158","msg":"Connection ended","attr":{"remote":"172.31.11.147:35186","connectionId":22158,"connectionCount":23}}
      {"t":{"$date":"2022-06-15T13:17:18.729+00:00"},"s":"I",  "c":"REPL",     "id":21799,   "ctx":"BackgroundSync","msg":"Sync source candidate chosen","attr":{"syncSource":"ec2-54-90-123-74.compute-1.amazonaws.com:27018"}}
      {"t":{"$date":"2022-06-15T13:16:51.101+00:00"},"s":"I",  "c":"REPL",     "id":21088,   "ctx":"BackgroundSync","msg":"Changed sync source","attr":{"oldSyncSource":"empty","newSyncSource":"ec2-54-90-123-74.compute-1.amazonaws.com:27018"}}
      {"t":{"$date":"2022-06-15T13:16:51.105+00:00"},"s":"I",  "c":"REPL",     "id":21368,   "ctx":"OplogApplier-0","msg":"Caught up to the latest known optime successfully after becoming primary","attr":{"targetOpTime":{"ts":{"$timestamp":{"t":1655299041,"i":73}},"t":30},"myLastApplied":{"ts":{"$timestamp":{"t":1655299041,"i":73}},"t":30}}}
      {"t":{"$date":"2022-06-15T13:16:51.105+00:00"},"s":"I",  "c":"REPL",     "id":21363,   "ctx":"OplogApplier-0","msg":"Exited primary catch-up mode"}
      {"t":{"$date":"2022-06-15T13:16:51.105+00:00"},"s":"I",  "c":"REPL",     "id":21107,   "ctx":"OplogApplier-0","msg":"Stopping replication producer"}
      {"t":{"$date":"2022-06-15T13:16:51.105+00:00"},"s":"I",  "c":"REPL",     "id":21239,   "ctx":"ReplBatcher","msg":"Oplog buffer has been drained","attr":{"term":31}}
      {"t":{"$date":"2022-06-15T13:16:51.105+00:00"},"s":"I",  "c":"NETWORK",  "id":20125,   "ctx":"ReplCoordExtern-2","msg":"DBClientConnection failed to receive message","attr":{"connString":"ec2-54-90-123-74.compute-1.amazonaws.com:27018","error":"HostUnreachable: Connection closed by peer"}}
      {"t":{"$date":"2022-06-15T13:16:51.105+00:00"},"s":"I",  "c":"REPL",     "id":21239,   "ctx":"ReplBatcher","msg":"Oplog buffer has been drained","attr":{"term":31}}
      {"t":{"$date":"2022-06-15T13:16:51.105+00:00"},"s":"I",  "c":"REPL",     "id":21275,   "ctx":"ReplCoordExtern-2","msg":"Recreating cursor for oplog fetcher due to error","attr":{"lastOpTimeFetched":{"ts":{"$timestamp":{"t":1655299041,"i":73}},"t":30},"attemptsRemaining":1,"error":"HostUnreachable: Error while getting the next batch in the oplog fetcher :: caused by :: dbclient error communicating with server ec2-54-90-123-74.compute-1.amazonaws.com:27018 :: caused by :: Connection closed by peer"}}
      {"t":{"$date":"2022-06-15T13:16:51.106+00:00"},"s":"I",  "c":"NETWORK",  "id":20120,   "ctx":"ReplCoordExtern-2","msg":"Trying to reconnect","attr":{"connString":"ec2-54-90-123-74.compute-1.amazonaws.com:27018 failed"}}
      {"t":{"$date":"2022-06-15T13:17:18.735+00:00"},"s":"I",  "c":"NETWORK",  "id":20121,   "ctx":"ReplCoordExtern-2","msg":"Reconnect attempt failed","attr":{"connString":"ec2-54-90-123-74.compute-1.amazonaws.com:27018 failed","error":""}}
      {"t":{"$date":"2022-06-15T13:17:18.736+00:00"},"s":"I",  "c":"-",        "id":4615600, "ctx":"ReplCoordExtern-2","msg":"caught exception in destructor","attr":{"exception":"socket exception [CONNECT_ERROR] server [socket exception [FAILED_STATE] server [ec2-54-90-123-74.compute-1.amazonaws.com:27018 failed]]","function":"kill"}}
      {"t":{"$date":"2022-06-15T13:17:18.736+00:00"},"s":"I",  "c":"REPL",     "id":21094,   "ctx":"BackgroundSync","msg":"Replication producer stopped after oplog fetcher finished returning a batch from our sync source. Abandoning this batch of oplog entries and re-evaluating our sync source"}
      {"t":{"$date":"2022-06-15T13:16:51.109+00:00"},"s":"I",  "c":"REPL",     "id":21343,   "ctx":"RstlKillOpThread","msg":"Starting to kill user operations"}
      {"t":{"$date":"2022-06-15T13:16:51.297+00:00"},"s":"I",  "c":"CONTROL",  "id":31431,   "ctx":"conn22143","msg":"BACKTRACE: {bt}","attr":{"bt":{"backtrace":[{"a":"5577795A50BA","b":"5577767DC000","o":"2DC90BA","s":"_ZN5mongo18stack_trace_detail12_GLOBAL__N_119printStackTraceImplERKNS1_7OptionsEPNS_14StackTraceSinkE.constprop.606","s+":"1EA"},{"a":"5577795A6B49","b":"5577767DC000","o":"2DCAB49","s":"_ZN5mongo15printStackTraceEv","s+":"29"},{"a":"5577795A3ED6","b":"5577767DC000","o":"2DC7ED6","s":"_ZN5mongo12_GLOBAL__N_116abruptQuitActionEiP9siginfo_tPv","s+":"66"},{"a":"7FA09F198140","b":"7FA09F184000","o":"14140","s":"funlockfile","s+":"50"},{"a":"7FA09EFFACE1","b":"7FA09EFBF000","o":"3BCE1","s":"gsignal","s+":"141"},{"a":"7FA09EFE4537","b":"7FA09EFBF000","o":"25537","s":"abort","s+":"123"},{"a":"55777771A18E","b":"5577767DC000","o":"F3E18E","s":"_ZN5mongo25fassertFailedWithLocationEiPKcj","s+":"12B"},{"a":"5577782FB2F0","b":"5577767DC000","o":"1B1F2F0","s":"_ZN5mongo24AutoGetCollectionForReadC2EPNS_16OperationContextERKNS_21NamespaceStringOrUUIDENS_17AutoGetCollection8ViewModeENS_6Date_tE","s+":"DE0"},{"a":"5577782FB362","b":"5577767DC000","o":"1B1F362","s":"_ZN5mongo31AutoGetCollectionForReadCommandC2EPNS_16OperationContextERKNS_21NamespaceStringOrUUIDENS_17AutoGetCollection8ViewModeENS_6Date_tENS_16AutoStatsTracker7LogModeE","s+":"32"},{"a":"557777EF70AD","b":"5577767DC000","o":"171B0AD","s":"_ZN5mongo12_GLOBAL__N_17FindCmd10Invocation3runEPNS_16OperationContextEPNS_3rpc21ReplyBuilderInterfaceE","s+":"39D"},{"a":"5577784F101F","b":"5577767DC000","o":"1D1501F","s":"_ZN5mongo14CommandHelpers20runCommandInvocationEPNS_16OperationContextERKNS_12OpMsgRequestEPNS_17CommandInvocationEPNS_3rpc21ReplyBuilderInterfaceE","s+":"7F"},{"a":"557777C2E0F8","b":"5577767DC000","o":"14520F8","s":"_ZN5mongo12_GLOBAL__N_114runCommandImplEPNS_16OperationContextEPNS_17CommandInvocationERKNS_12OpMsgRequestEPNS_3rpc21ReplyBuilderInterfaceENS_11LogicalTimeERKNS_23ServiceEntryPointCommon5HooksEPNS_14BSONObjBuilderERKNS_30OperationSessionInfoFromClientE","s+":"138"},{"a":"557777C31BFF","b":"5577767DC000","o":"1455BFF","s":"_ZZN5mongo12_GLOBAL__N_116receivedCommandsEPNS_16OperationContextERKNS_7MessageERKNS_23ServiceEntryPointCommon5HooksEENKUlvE_clEv","s+":"1E8F"},{"a":"557777C32AAB","b":"5577767DC000","o":"1456AAB","s":"_ZN5mongo23ServiceEntryPointCommon13handleRequestEPNS_16OperationContextERKNS_7MessageERKNS0_5HooksE","s+":"52B"},{"a":"557777C208AC","b":"5577767DC000","o":"14448AC","s":"_ZN5mongo23ServiceEntryPointMongod13handleRequestEPNS_16OperationContextERKNS_7MessageE","s+":"3C"},{"a":"557777C2B7E2","b":"5577767DC000","o":"144F7E2","s":"_ZN5mongo19ServiceStateMachine15_processMessageENS0_11ThreadGuardE","s+":"F2"},{"a":"557777C29525","b":"5577767DC000","o":"144D525","s":"_ZN5mongo19ServiceStateMachine15_runNextInGuardENS0_11ThreadGuardE","s+":"125"},{"a":"557777C2A3B6","b":"5577767DC000","o":"144E3B6","s":"_ZNSt17_Function_handlerIFvvEZN5mongo19ServiceStateMachine22_scheduleNextWithGuardENS2_11ThreadGuardENS1_9transport15ServiceExecutor13ScheduleFlagsENS4_23ServiceExecutorTaskNameENS2_9OwnershipEEUlvE_E9_M_invokeERKSt9_Any_data","s+":"56"},{"a":"557778F5BA1A","b":"5577767DC000","o":"277FA1A","s":"_ZN5mongo9transport26ServiceExecutorSynchronous8scheduleESt8functionIFvvEENS0_15ServiceExecutor13ScheduleFlagsENS0_23ServiceExecutorTaskNameE","s+":"18A"},{"a":"557777C2883B","b":"5577767DC000","o":"144C83B","s":"_ZN5mongo19ServiceStateMachine22_scheduleNextWithGuardENS0_11ThreadGuardENS_9transport15ServiceExecutor13ScheduleFlagsENS2_23ServiceExecutorTaskNameENS0_9OwnershipE","s+":"DB"},{"a":"557777C29AFD","b":"5577767DC000","o":"144DAFD","s":"_ZN5mongo19ServiceStateMachine15_sourceCallbackENS_6StatusE","s+":"50D"},{"a":"557777C29BE0","b":"5577767DC000","o":"144DBE0","s":"_ZN5mongo14future_details4callIRZNS_19ServiceStateMachine14_sourceMessageENS2_11ThreadGuardEEUlNS_10StatusWithINS_7MessageEEEE0_S6_EEDaOT_OT0_","s+":"60"},{"a":"557777C29E85","b":"5577767DC000","o":"144DE85","s":"_ZN5mongo19ServiceStateMachine14_sourceMessageENS0_11ThreadGuardE","s+":"145"},{"a":"557777C2959A","b":"5577767DC000","o":"144D59A","s":"_ZN5mongo19ServiceStateMachine15_runNextInGuardENS0_11ThreadGuardE","s+":"19A"},{"a":"557777C2A3B6","b":"5577767DC000","o":"144E3B6","s":"_ZNSt17_Function_handlerIFvvEZN5mongo19ServiceStateMachine22_scheduleNextWithGuardENS2_11ThreadGuardENS1_9transport15ServiceExecutor13ScheduleFlagsENS4_23ServiceExecutorTaskNameENS2_9OwnershipEEUlvE_E9_M_invokeERKSt9_Any_data","s+":"56"},{"a":"557778F5C094","b":"5577767DC000","o":"2780094","s":"_ZNSt17_Function_handlerIFvvEZN5mongo9transport26ServiceExecutorSynchronous8scheduleESt8functionIS0_ENS2_15ServiceExecutor13ScheduleFlagsENS2_23ServiceExecutorTaskNameEEUlvE0_E9_M_invokeERKSt9_Any_data","s+":"D4"},{"a":"5577792B2346","b":"5577767DC000","o":"2AD6346","s":"_ZNSt17_Function_handlerIFvvEZN5mongo25launchServiceWorkerThreadESt8functionIS0_EEUlvE1_E9_M_invokeERKSt9_Any_data","s+":"56"},{"a":"5577792B23B4","b":"5577767DC000","o":"2AD63B4","s":"_ZN5mongo12_GLOBAL__N_17runFuncEPv","s+":"14"},{"a":"7FA09F18CEA7","b":"7FA09F184000","o":"8EA7","s":"start_thread","s+":"D7"},{"a":"7FA09F0BCDEF","b":"7FA09EFBF000","o":"FDDEF","s":"clone","s+":"3F"}],"processInfo":{"mongodbVersion":"4.4.9","gitVersion":"b4048e19814bfebac717cf5a880076aa69aba481","compiledModules":[],"uname":{"sysname":"Linux","release":"5.10.0-13-cloud-amd64","version":"#1 SMP Debian 5.10.106-1 (2022-03-17)","machine":"x86_64"},"somap":[{"b":"5577767DC000","elfType":3,"buildId":"9A6590441FB6C557F74376593D798584AA772D5F"},{"b":"7FA09F184000","path":"/lib/x86_64-linux-gnu/libpthread.so.0","elfType":3,"buildId":"5018237BBF012B4094027FD0B96FC22A24496EA4"},{"b":"7FA09EFBF000","path":"/lib/x86_64-linux-gnu/libc.so.6","elfType":3,"buildId":"2E5ABCEE94F3BCBED7BBA094F341070A2585A2BA"}]}}}}
      {"t":{"$date":"2022-06-15T13:16:51.297+00:00"},"s":"I",  "c":"CONTROL",  "id":31427,   "ctx":"conn22143","msg":"  Frame: {frame}","attr":{"frame":{"a":"5577795A50BA","b":"5577767DC000","o":"2DC90BA","s":"_ZN5mongo18stack_trace_detail12_GLOBAL__N_119printStackTraceImplERKNS1_7OptionsEPNS_14StackTraceSinkE.constprop.606","s+":"1EA"}}}
      {"t":{"$date":"2022-06-15T13:16:51.297+00:00"},"s":"I",  "c":"CONTROL",  "id":31427,   "ctx":"conn22143","msg":"  Frame: {frame}","attr":{"frame":{"a":"5577795A6B49","b":"5577767DC000","o":"2DCAB49","s":"_ZN5mongo15printStackTraceEv","s+":"29"}}}
      {"t":{"$date":"2022-06-15T13:16:51.297+00:00"},"s":"I",  "c":"CONTROL",  "id":31427,   "ctx":"conn22143","msg":"  Frame: {frame}","attr":{"frame":{"a":"5577795A3ED6","b":"5577767DC000","o":"2DC7ED6","s":"_ZN5mongo12_GLOBAL__N_116abruptQuitActionEiP9siginfo_tPv","s+":"66"}}}
      {"t":{"$date":"2022-06-15T13:16:51.297+00:00"},"s":"I",  "c":"CONTROL",  "id":31427,   "ctx":"conn22143","msg":"  Frame: {frame}","attr":{"frame":{"a":"7FA09F198140","b":"7FA09F184000","o":"14140","s":"funlockfile","s+":"50"}}}
      {"t":{"$date":"2022-06-15T13:16:51.298+00:00"},"s":"I",  "c":"CONTROL",  "id":31427,   "ctx":"conn22143","msg":"  Frame: {frame}","attr":{"frame":{"a":"7FA09EFFACE1","b":"7FA09EFBF000","o":"3BCE1","s":"gsignal","s+":"141"}}}
      {"t":{"$date":"2022-06-15T13:16:51.298+00:00"},"s":"I",  "c":"CONTROL",  "id":31427,   "ctx":"conn22143","msg":"  Frame: {frame}","attr":{"frame":{"a":"7FA09EFE4537","b":"7FA09EFBF000","o":"25537","s":"abort","s+":"123"}}}
      {"t":{"$date":"2022-06-15T13:16:51.298+00:00"},"s":"I",  "c":"CONTROL",  "id":31427,   "ctx":"conn22143","msg":"  Frame: {frame}","attr":{"frame":{"a":"55777771A18E","b":"5577767DC000","o":"F3E18E","s":"_ZN5mongo25fassertFailedWithLocationEiPKcj","s+":"12B"}}}
      {"t":{"$date":"2022-06-15T13:16:51.298+00:00"},"s":"I",  "c":"CONTROL",  "id":31427,   "ctx":"conn22143","msg":"  Frame: {frame}","attr":{"frame":{"a":"5577782FB2F0","b":"5577767DC000","o":"1B1F2F0","s":"_ZN5mongo24AutoGetCollectionForReadC2EPNS_16OperationContextERKNS_21NamespaceStringOrUUIDENS_17AutoGetCollection8ViewModeENS_6Date_tE","s+":"DE0"}}}
      {"t":{"$date":"2022-06-15T13:16:51.298+00:00"},"s":"I",  "c":"CONTROL",  "id":31427,   "ctx":"conn22143","msg":"  Frame: {frame}","attr":{"frame":{"a":"5577782FB362","b":"5577767DC000","o":"1B1F362","s":"_ZN5mongo31AutoGetCollectionForReadCommandC2EPNS_16OperationContextERKNS_21NamespaceStringOrUUIDENS_17AutoGetCollection8ViewModeENS_6Date_tENS_16AutoStatsTracker7LogModeE","s+":"32"}}}
      {"t":{"$date":"2022-06-15T13:16:51.298+00:00"},"s":"I",  "c":"CONTROL",  "id":31427,   "ctx":"conn22143","msg":"  Frame: {frame}","attr":{"frame":{"a":"557777EF70AD","b":"5577767DC000","o":"171B0AD","s":"_ZN5mongo12_GLOBAL__N_17FindCmd10Invocation3runEPNS_16OperationContextEPNS_3rpc21ReplyBuilderInterfaceE","s+":"39D"}}}
      {"t":{"$date":"2022-06-15T13:16:51.298+00:00"},"s":"I",  "c":"CONTROL",  "id":31427,   "ctx":"conn22143","msg":"  Frame: {frame}","attr":{"frame":{"a":"5577784F101F","b":"5577767DC000","o":"1D1501F","s":"_ZN5mongo14CommandHelpers20runCommandInvocationEPNS_16OperationContextERKNS_12OpMsgRequestEPNS_17CommandInvocationEPNS_3rpc21ReplyBuilderInterfaceE","s+":"7F"}}}
      {"t":{"$date":"2022-06-15T13:16:51.298+00:00"},"s":"I",  "c":"CONTROL",  "id":31427,   "ctx":"conn22143","msg":"  Frame: {frame}","attr":{"frame":{"a":"557777C2E0F8","b":"5577767DC000","o":"14520F8","s":"_ZN5mongo12_GLOBAL__N_114runCommandImplEPNS_16OperationContextEPNS_17CommandInvocationERKNS_12OpMsgRequestEPNS_3rpc21ReplyBuilderInterfaceENS_11LogicalTimeERKNS_23ServiceEntryPointCommon5HooksEPNS_14BSONObjBuilderERKNS_30OperationSessionInfoFromClientE","s+":"138"}}}
      {"t":{"$date":"2022-06-15T13:16:51.298+00:00"},"s":"I",  "c":"CONTROL",  "id":31427,   "ctx":"conn22143","msg":"  Frame: {frame}","attr":{"frame":{"a":"557777C31BFF","b":"5577767DC000","o":"1455BFF","s":"_ZZN5mongo12_GLOBAL__N_116receivedCommandsEPNS_16OperationContextERKNS_7MessageERKNS_23ServiceEntryPointCommon5HooksEENKUlvE_clEv","s+":"1E8F"}}}
      {"t":{"$date":"2022-06-15T13:16:51.298+00:00"},"s":"I",  "c":"CONTROL",  "id":31427,   "ctx":"conn22143","msg":"  Frame: {frame}","attr":{"frame":{"a":"557777C32AAB","b":"5577767DC000","o":"1456AAB","s":"_ZN5mongo23ServiceEntryPointCommon13handleRequestEPNS_16OperationContextERKNS_7MessageERKNS0_5HooksE","s+":"52B"}}}
      {"t":{"$date":"2022-06-15T13:16:51.298+00:00"},"s":"I",  "c":"CONTROL",  "id":31427,   "ctx":"conn22143","msg":"  Frame: {frame}","attr":{"frame":{"a":"557777C208AC","b":"5577767DC000","o":"14448AC","s":"_ZN5mongo23ServiceEntryPointMongod13handleRequestEPNS_16OperationContextERKNS_7MessageE","s+":"3C"}}}
      {"t":{"$date":"2022-06-15T13:16:51.298+00:00"},"s":"I",  "c":"CONTROL",  "id":31427,   "ctx":"conn22143","msg":"  Frame: {frame}","attr":{"frame":{"a":"557777C2B7E2","b":"5577767DC000","o":"144F7E2","s":"_ZN5mongo19ServiceStateMachine15_processMessageENS0_11ThreadGuardE","s+":"F2"}}}
      {"t":{"$date":"2022-06-15T13:16:51.298+00:00"},"s":"I",  "c":"CONTROL",  "id":31427,   "ctx":"conn22143","msg":"  Frame: {frame}","attr":{"frame":{"a":"557777C29525","b":"5577767DC000","o":"144D525","s":"_ZN5mongo19ServiceStateMachine15_runNextInGuardENS0_11ThreadGuardE","s+":"125"}}}
      {"t":{"$date":"2022-06-15T13:16:51.298+00:00"},"s":"I",  "c":"CONTROL",  "id":31427,   "ctx":"conn22143","msg":"  Frame: {frame}","attr":{"frame":{"a":"557777C2A3B6","b":"5577767DC000","o":"144E3B6","s":"_ZNSt17_Function_handlerIFvvEZN5mongo19ServiceStateMachine22_scheduleNextWithGuardENS2_11ThreadGuardENS1_9transport15ServiceExecutor13ScheduleFlagsENS4_23ServiceExecutorTaskNameENS2_9OwnershipEEUlvE_E9_M_invokeERKSt9_Any_data","s+":"56"}}}
      {"t":{"$date":"2022-06-15T13:16:51.298+00:00"},"s":"I",  "c":"CONTROL",  "id":31427,   "ctx":"conn22143","msg":"  Frame: {frame}","attr":{"frame":{"a":"557778F5BA1A","b":"5577767DC000","o":"277FA1A","s":"_ZN5mongo9transport26ServiceExecutorSynchronous8scheduleESt8functionIFvvEENS0_15ServiceExecutor13ScheduleFlagsENS0_23ServiceExecutorTaskNameE","s+":"18A"}}}
      {"t":{"$date":"2022-06-15T13:16:51.298+00:00"},"s":"I",  "c":"CONTROL",  "id":31427,   "ctx":"conn22143","msg":"  Frame: {frame}","attr":{"frame":{"a":"557777C2883B","b":"5577767DC000","o":"144C83B","s":"_ZN5mongo19ServiceStateMachine22_scheduleNextWithGuardENS0_11ThreadGuardENS_9transport15ServiceExecutor13ScheduleFlagsENS2_23ServiceExecutorTaskNameENS0_9OwnershipE","s+":"DB"}}}
      {"t":{"$date":"2022-06-15T13:16:51.298+00:00"},"s":"I",  "c":"CONTROL",  "id":31427,   "ctx":"conn22143","msg":"  Frame: {frame}","attr":{"frame":{"a":"557777C29AFD","b":"5577767DC000","o":"144DAFD","s":"_ZN5mongo19ServiceStateMachine15_sourceCallbackENS_6StatusE","s+":"50D"}}}
      {"t":{"$date":"2022-06-15T13:16:51.298+00:00"},"s":"I",  "c":"CONTROL",  "id":31427,   "ctx":"conn22143","msg":"  Frame: {frame}","attr":{"frame":{"a":"557777C29BE0","b":"5577767DC000","o":"144DBE0","s":"_ZN5mongo14future_details4callIRZNS_19ServiceStateMachine14_sourceMessageENS2_11ThreadGuardEEUlNS_10StatusWithINS_7MessageEEEE0_S6_EEDaOT_OT0_","s+":"60"}}}
      {"t":{"$date":"2022-06-15T13:16:51.298+00:00"},"s":"I",  "c":"CONTROL",  "id":31427,   "ctx":"conn22143","msg":"  Frame: {frame}","attr":{"frame":{"a":"557777C29E85","b":"5577767DC000","o":"144DE85","s":"_ZN5mongo19ServiceStateMachine14_sourceMessageENS0_11ThreadGuardE","s+":"145"}}}
      {"t":{"$date":"2022-06-15T13:16:51.298+00:00"},"s":"I",  "c":"CONTROL",  "id":31427,   "ctx":"conn22143","msg":"  Frame: {frame}","attr":{"frame":{"a":"557777C2959A","b":"5577767DC000","o":"144D59A","s":"_ZN5mongo19ServiceStateMachine15_runNextInGuardENS0_11ThreadGuardE","s+":"19A"}}}
      {"t":{"$date":"2022-06-15T13:16:51.298+00:00"},"s":"I",  "c":"CONTROL",  "id":31427,   "ctx":"conn22143","msg":"  Frame: {frame}","attr":{"frame":{"a":"557777C2A3B6","b":"5577767DC000","o":"144E3B6","s":"_ZNSt17_Function_handlerIFvvEZN5mongo19ServiceStateMachine22_scheduleNextWithGuardENS2_11ThreadGuardENS1_9transport15ServiceExecutor13ScheduleFlagsENS4_23ServiceExecutorTaskNameENS2_9OwnershipEEUlvE_E9_M_invokeERKSt9_Any_data","s+":"56"}}}
      {"t":{"$date":"2022-06-15T13:16:51.298+00:00"},"s":"I",  "c":"CONTROL",  "id":31427,   "ctx":"conn22143","msg":"  Frame: {frame}","attr":{"frame":{"a":"557778F5C094","b":"5577767DC000","o":"2780094","s":"_ZNSt17_Function_handlerIFvvEZN5mongo9transport26ServiceExecutorSynchronous8scheduleESt8functionIS0_ENS2_15ServiceExecutor13ScheduleFlagsENS2_23ServiceExecutorTaskNameEEUlvE0_E9_M_invokeERKSt9_Any_data","s+":"D4"}}}
      {"t":{"$date":"2022-06-15T13:16:51.298+00:00"},"s":"I",  "c":"CONTROL",  "id":31427,   "ctx":"conn22143","msg":"  Frame: {frame}","attr":{"frame":{"a":"5577792B2346","b":"5577767DC000","o":"2AD6346","s":"_ZNSt17_Function_handlerIFvvEZN5mongo25launchServiceWorkerThreadESt8functionIS0_EEUlvE1_E9_M_invokeERKSt9_Any_data","s+":"56"}}}
      {"t":{"$date":"2022-06-15T13:16:51.298+00:00"},"s":"I",  "c":"CONTROL",  "id":31427,   "ctx":"conn22143","msg":"  Frame: {frame}","attr":{"frame":{"a":"5577792B23B4","b":"5577767DC000","o":"2AD63B4","s":"_ZN5mongo12_GLOBAL__N_17runFuncEPv","s+":"14"}}}
      {"t":{"$date":"2022-06-15T13:16:51.298+00:00"},"s":"I",  "c":"CONTROL",  "id":31427,   "ctx":"conn22143","msg":"  Frame: {frame}","attr":{"frame":{"a":"7FA09F18CEA7","b":"7FA09F184000","o":"8EA7","s":"start_thread","s+":"D7"}}}
      {"t":{"$date":"2022-06-15T13:16:51.298+00:00"},"s":"I",  "c":"CONTROL",  "id":31427,   "ctx":"conn22143","msg":"  Frame: {frame}","attr":{"frame":{"a":"7FA09F0BCDEF","b":"7FA09EFBF000","o":"FDDEF","s":"clone","s+":"3F"}}} 

      Here's an example Jepsen test run with full logs from each server: http://jepsen.io.s3.amazonaws.com/analyses/mongodb-4.4.9/20220615T131343.000Z.zip

      Attachments

        Activity

          People

            matthew.russotto@mongodb.com Matthew Russotto
            aphyr@jepsen.io Kyle Kingsbury
            Votes:
            1 Vote for this issue
            Watchers:
            21 Start watching this issue

            Dates

              Created:
              Updated:
              Resolved: