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

HMAC keys thread hits Invariant failure !_committedSnapshot || *_committedSnapshot < nameU64 during replset startup (RocksDB)

    • Type: Icon: Bug Bug
    • Resolution: Won't Fix
    • Priority: Icon: Major - P3 Major - P3
    • None
    • Affects Version/s: None
    • Component/s: Storage
    • Labels:
    • Storage Execution
    • ALL
    • 95

      jstestfuzz_concurrent_replication_WT failed on Ubuntu 14.04 (RocksDB)

      Project: MongoDB (master)
      Commit: diff: SERVER-31313 Prohibit creating a view with $changeStream

      The "monitoring keys for HMAC" thread hits this invariant failure while we are spinning up a replica set. No fuzzer tests were run.

      [ReplicaSetFixture:job0:primary] 2017-10-10T16:58:01.683+0000 I COMMAND  [monitoring keys for HMAC] command admin.system.keys command: find { find: "system.keys", filter: { purpose: "HMAC", expiresAt: { $gt: Timestamp 1507654681000|1 } }, sort: { expiresAt: 1 }, $readPreference: { mode: "nearest", tags: [] }, $db: "admin" } planSummary: EOF keysExamined:0 docsExamined:0 cursorExhausted:1 numYields:0 nreturned:0 reslen:215 locks:{ Global: { acquireCount: { r: 2 }, acquireWaitCount: { r: 1 }, timeAcquiringMicros: { r: 489 } }, Database: { acquireCount: { r: 1 } }, Collection: { acquireCount: { r: 1 } } } protocol:op_msg 0ms
      [ReplicaSetFixture:job0:primary] 2017-10-10T16:58:01.685+0000 D STORAGE  [monitoring keys for HMAC] create collection admin.system.keys {}
      [ReplicaSetFixture:job0:primary] 2017-10-10T16:58:01.685+0000 I STORAGE  [monitoring keys for HMAC] createCollection: admin.system.keys with UUID: ed5e50d1-947b-4145-a8e8-0affc8ffeae8
      [ReplicaSetFixture:job0:primary] 2017-10-10T16:58:01.685+0000 D STORAGE  [monitoring keys for HMAC] stored meta data for admin.system.keys @ RecordId(11)
      [ReplicaSetFixture:job0:primary] 2017-10-10T16:58:01.685+0000 D STORAGE  [monitoring keys for HMAC] opening collection admin.system.keys with prefix 00000015
      [ReplicaSetFixture:job0:primary] 2017-10-10T16:58:01.685+0000 D STORAGE  [monitoring keys for HMAC] admin.system.keys: clearing plan cache - collection info cache reset
      [ReplicaSetFixture:job0:primary] 2017-10-10T16:58:01.685+0000 D STORAGE  [monitoring keys for HMAC] admin.system.keys: clearing plan cache - collection info cache reset
      [ReplicaSetFixture:job0:primary] 2017-10-10T16:58:01.685+0000 D REPL     [monitoring keys for HMAC] Ignoring older committed snapshot from before I became primary, optime: { ts: Timestamp 1507654679000|1, t: -1 }, firstOpTimeOfMyTerm: { ts: Timestamp 1507654681000|1, t: 1 }
      [ReplicaSetFixture:job0:primary] 2017-10-10T16:58:01.685+0000 D REPL     [monitoring keys for HMAC] Ignoring older committed snapshot from before I became primary, optime: { ts: Timestamp 1507654679000|1, t: -1 }, firstOpTimeOfMyTerm: { ts: Timestamp 1507654681000|1, t: 1 }
      [ReplicaSetFixture:job0:primary] 2017-10-10T16:58:01.686+0000 I COMMAND  [monitoring keys for HMAC] command admin.system.keys command: insert { insert: "system.keys", bypassDocumentValidation: false, ordered: true, documents: [ { _id: 6475327548556312577, purpose: "HMAC", key: BinData(0, DB7BECC32465824E084A8C40CD67415CE0214F3D), expiresAt: Timestamp 1515430681000|0 } ], writeConcern: { w: "majority", wtimeout: 15000 }, $db: "admin" } ninserted:1 keysInserted:1 numYields:0 reslen:214 locks:{ Global: { acquireCount: { r: 7, w: 5 }, acquireWaitCount: { r: 1 }, timeAcquiringMicros: { r: 489 } }, Database: { acquireCount: { r: 1, w: 2, W: 3 } }, Collection: { acquireCount: { r: 1, w: 2 } }, Metadata: { acquireCount: { w: 2 } }, oplog: { acquireCount: { w: 2 } } } protocol:op_msg 1ms
      [ReplicaSetFixture:job0:primary] 2017-10-10T16:58:01.687+0000 F -        [monitoring keys for HMAC] Invariant failure !_committedSnapshot || *_committedSnapshot < nameU64 src/mongo/db/modules/rocksdb/src/rocks_snapshot_manager.cpp 52
      [ReplicaSetFixture:job0:primary] 2017-10-10T16:58:01.687+0000 F -        [monitoring keys for HMAC]
      [ReplicaSetFixture:job0:primary] 
      [ReplicaSetFixture:job0:primary] ***aborting after invariant() failure
      [ReplicaSetFixture:job0:primary] 
      [ReplicaSetFixture:job0:primary] 
      [ReplicaSetFixture:job0] Waiting for primary on port 20000 to be elected.
      [ReplicaSetFixture:job0:primary] 2017-10-10T16:58:01.713+0000 F -        [monitoring keys for HMAC] Got signal: 6 (Aborted).
      [ReplicaSetFixture:job0:primary] 
      [ReplicaSetFixture:job0:primary]  0x241ce08 0x241c24d 0x241c654 0x7f99c7f78330 0x7f99c7bd5c37 0x7f99c7bd9028 0xb8942c 0xed3558 0x107d9bf 0x1446935 0x144f677 0x14502a2 0x14506a3 0x11e0c2e 0xec8d09 0xfc971a 0xfcfe42 0xfb53fb 0xfaebd7 0x1f11ddf 0xeed998 0xeee5d9 0xeef310 0x142db78 0x142e190 0x1df6a2f 0x142bb14 0xefac83 0xefbbcf 0x1fdf5ff 0x1fdf972 0x1fdd2e9 0x1fdd814 0x1fdca25 0x1fdd991 0x26f0d60 0x7f99c7f70184 0x7f99c7c9cffd
      [ReplicaSetFixture:job0:primary] ----- BEGIN BACKTRACE -----
      [ReplicaSetFixture:job0:primary] {"backtrace":[{"b":"400000","o":"201CE08","s":"_ZN5mongo15printStackTraceERSo"},{"b":"400000","o":"201C24D"},{"b":"400000","o":"201C654"},{"b":"7F99C7F68000","o":"10330"},{"b":"7F99C7B9F000","o":"36C37","s":"gsignal"},{"b":"7F99C7B9F000","o":"3A028","s":"abort"},{"b":"400000","o":"78942C","s":"_ZN5mongo17invariantOKFailedEPKcRKNS_6StatusES1_j"},{"b":"400000","o":"AD3558","s":"_ZN5mongo20RocksSnapshotManager20setCommittedSnapshotERKNS_12SnapshotNameENS_9TimestampE"},{"b":"400000","o":"C7D9BF","s":"_ZN5mongo4repl39ReplicationCoordinatorExternalStateImpl23updateCommittedSnapshotENS0_12SnapshotInfoE"},{"b":"400000","o":"1046935","s":"_ZN5mongo4repl26ReplicationCoordinatorImpl31_updateCommittedSnapshot_inlockENS0_12SnapshotInfoE"},{"b":"400000","o":"104F677","s":"_ZN5mongo4repl26ReplicationCoordinatorImpl36_setStableTimestampForStorage_inlockEv"},{"b":"400000","o":"10502A2","s":"_ZN5mongo4repl26ReplicationCoordinatorImpl30_setMyLastAppliedOpTime_inlockERKNS0_6OpTimeEb"},{"b":"400000","o":"10506A3","s":"_ZN5mongo4repl26ReplicationCoordinatorImpl29setMyLastAppliedOpTimeForwardERKNS0_6OpTimeE"},{"b":"400000","o":"DE0C2E"},{"b":"400000","o":"AC8D09","s":"_ZN5mongo17RocksRecoveryUnit16commitUnitOfWorkEv"},{"b":"400000","o":"BC971A"},{"b":"400000","o":"BCFE42","s":"_ZN5mongo14performInsertsEPNS_16OperationContextERKNS_9write_ops6InsertE"},{"b":"400000","o":"BB53FB"},{"b":"400000","o":"BAEBD7"},{"b":"400000","o":"1B11DDF","s":"_ZN5mongo7Command9publicRunEPNS_16OperationContextERKNS_12OpMsgRequestERNS_14BSONObjBuilderE"},{"b":"400000","o":"AED998"},{"b":"400000","o":"AEE5D9"},{"b":"400000","o":"AEF310","s":"_ZN5mongo23ServiceEntryPointMongod13handleRequestEPNS_16OperationContextERKNS_7MessageE"},{"b":"400000","o":"102DB78"},{"b":"400000","o":"102E190","s":"_ZN5mongo14DBDirectClient4callERNS_7MessageES2_bPNSt7__cxx1112basic_stringIcSt11char_traitsIcESaIcEEE"},{"b":"400000","o":"19F6A2F","s":"_ZN5mongo12DBClientBase20runCommandWithTargetENS_12OpMsgRequestE"},{"b":"400000","o":"102BB14","s":"_ZN5mongo13RSLocalClient14runCommandOnceEPNS_16OperationContextERKNSt7__cxx1112basic_stringIcSt11char_traitsIcESaIcEEERKNS_7BSONObjE"},{"b":"400000","o":"AFAC83","s":"_ZN5mongo26KeysCollectionClientDirect7_insertEPNS_16OperationContextERKNSt7__cxx1112basic_stringIcSt11char_traitsIcESaIcEEERKNS_7BSONObjERKNS_19WriteConcernOptionsE"},{"b":"400000","o":"AFBBCF","s":"_ZN5mongo26KeysCollectionClientDirect12insertNewKeyEPNS_16OperationContextERKNS_7BSONObjE"},{"b":"400000","o":"1BDF5FF"},{"b":"400000","o":"1BDF972","s":"_ZN5mongo35KeysCollectionCacheReaderAndUpdater7refreshEPNS_16OperationContextE"},{"b":"400000","o":"1BDD2E9"},{"b":"400000","o":"1BDD814"},{"b":"400000","o":"1BDCA25","s":"_ZN5mongo29KeysCollectionManagerSharding14PeriodicRunner18_doPeriodicRefreshEPNS_14ServiceContextENSt7__cxx1112basic_stringIcSt11char_traitsIcESaIcEEENS_8DurationISt5ratioILl1ELl1000EEEE"},{"b":"400000","o":"1BDD991","s":"_ZNSt6thread5_ImplISt12_Bind_simpleIFSt5_BindIFSt7_Mem_fnIMN5mongo29KeysCollectionManagerSharding14PeriodicRunnerEFvPNS4_14ServiceContextENSt7__cxx1112basic_stringIcSt11char_traitsIcESaIcEEENS4_8DurationISt5ratioILl1ELl1000EEEEEEPS6_S8_SE_SI_EEvEEE6_M_runEv"},{"b":"400000","o":"22F0D60"},{"b":"7F99C7F68000","o":"8184"},{"b":"7F99C7B9F000","o":"FDFFD","s":"clone"}],"processInfo":{ "mongodbVersion" : "3.5.13-353-g9c3da7f", "gitVersion" : "9c3da7fb167fdcc2326abfcef7ee2320463b6712", "compiledModules" : [ "rocksdb" ], "uname" : { "sysname" : "Linux", "release" : "3.13.0-24-generic", "version" : "#46-Ubuntu SMP Thu Apr 10 19:11:08 UTC 2014", "machine" : "x86_64" }, "somap" : [ { "elfType" : 2, "b" : "400000", "buildId" : "8C0F6A6DA8DF7837DFCA29EA73F2103D5A0D05B0" }, { "b" : "7FFFE0AFE000", "elfType" : 3, "buildId" : "6755FAD2CADACDF1667E5B57FF1EDFC28DD1C976" }, { "b" : "7F99C8CBE000", "path" : "/lib/x86_64-linux-gnu/libz.so.1", "elfType" : 3, "buildId" : "7EE9BC42787A0F9A793BDBFCB0671FD12C52BC2A" }, { "b" : "7F99C8AAE000", "path" : "/lib/x86_64-linux-gnu/libbz2.so.1.0", "elfType" : 3, "buildId" : "E1031DDBFFE20367E874B7093EEC0C8D9F3B43F6" }, { "b" : "7F99C88A6000", "path" : "/lib/x86_64-linux-gnu/librt.so.1", "elfType" : 3, "buildId" : "AC72654C6338205F30190061C0D781CB0039B793" }, { "b" : "7F99C86A2000", "path" : "/lib/x86_64-linux-gnu/libdl.so.2", "elfType" : 3, "buildId" : "EED41ABB999C74882F001C53979CC820ED15BA82" }, { "b" : "7F99C839C000", "path" : "/lib/x86_64-linux-gnu/libm.so.6", "elfType" : 3, "buildId" : "8F0318B9CC6FD523C2587A15C5447ABBB8CD813D" }, { "b" : "7F99C8186000", "path" : "/lib/x86_64-linux-gnu/libgcc_s.so.1", "elfType" : 3, "buildId" : "36311B4457710AE5578C4BF00791DED7359DBB92" }, { "b" : "7F99C7F68000", "path" : "/lib/x86_64-linux-gnu/libpthread.so.0", "elfType" : 3, "buildId" : "F48E96A1F4A549776CA4167095AD7527720D4B0E" }, { "b" : "7F99C7B9F000", "path" : "/lib/x86_64-linux-gnu/libc.so.6", "elfType" : 3, "buildId" : "3217CA3A53A930C7BB1E5C83789D09B30B0F3B39" }, { "b" : "7F99C8ED7000", "path" : "/lib64/ld-linux-x86-64.so.2", "elfType" : 3, "buildId" : "37AFDBB933B8409476E845DF5FB11BC77CBCEEE6" } ] }}
      [ReplicaSetFixture:job0:primary]  mongod(_ZN5mongo15printStackTraceERSo+0x28) [0x241ce08]
      [ReplicaSetFixture:job0:primary]  mongod(+0x201C24D) [0x241c24d]
      [ReplicaSetFixture:job0:primary]  mongod(+0x201C654) [0x241c654]
      [ReplicaSetFixture:job0:primary]  libpthread.so.0(+0x10330) [0x7f99c7f78330]
      [ReplicaSetFixture:job0:primary]  libc.so.6(gsignal+0x37) [0x7f99c7bd5c37]
      [ReplicaSetFixture:job0:primary]  libc.so.6(abort+0x148) [0x7f99c7bd9028]
      [ReplicaSetFixture:job0:primary]  mongod(_ZN5mongo17invariantOKFailedEPKcRKNS_6StatusES1_j+0x0) [0xb8942c]
      [ReplicaSetFixture:job0:primary]  mongod(_ZN5mongo20RocksSnapshotManager20setCommittedSnapshotERKNS_12SnapshotNameENS_9TimestampE+0x88) [0xed3558]
      [ReplicaSetFixture:job0:primary]  mongod(_ZN5mongo4repl39ReplicationCoordinatorExternalStateImpl23updateCommittedSnapshotENS0_12SnapshotInfoE+0x6F) [0x107d9bf]
      [ReplicaSetFixture:job0:primary]  mongod(_ZN5mongo4repl26ReplicationCoordinatorImpl31_updateCommittedSnapshot_inlockENS0_12SnapshotInfoE+0xF5) [0x1446935]
      [ReplicaSetFixture:job0:primary]  mongod(_ZN5mongo4repl26ReplicationCoordinatorImpl36_setStableTimestampForStorage_inlockEv+0x1E7) [0x144f677]
      [ReplicaSetFixture:job0:primary]  mongod(_ZN5mongo4repl26ReplicationCoordinatorImpl30_setMyLastAppliedOpTime_inlockERKNS0_6OpTimeEb+0x152) [0x14502a2]
      [ReplicaSetFixture:job0:primary]  mongod(_ZN5mongo4repl26ReplicationCoordinatorImpl29setMyLastAppliedOpTimeForwardERKNS0_6OpTimeE+0xA3) [0x14506a3]
      [ReplicaSetFixture:job0:primary]  mongod(+0xDE0C2E) [0x11e0c2e]
      [ReplicaSetFixture:job0:primary]  mongod(_ZN5mongo17RocksRecoveryUnit16commitUnitOfWorkEv+0x39) [0xec8d09]
      [ReplicaSetFixture:job0:primary]  mongod(+0xBC971A) [0xfc971a]
      [ReplicaSetFixture:job0:primary]  mongod(_ZN5mongo14performInsertsEPNS_16OperationContextERKNS_9write_ops6InsertE+0x11F2) [0xfcfe42]
      [ReplicaSetFixture:job0:primary]  mongod(+0xBB53FB) [0xfb53fb]
      [ReplicaSetFixture:job0:primary]  mongod(+0xBAEBD7) [0xfaebd7]
      [ReplicaSetFixture:job0:primary]  mongod(_ZN5mongo7Command9publicRunEPNS_16OperationContextERKNS_12OpMsgRequestERNS_14BSONObjBuilderE+0x1F) [0x1f11ddf]
      [ReplicaSetFixture:job0:primary]  mongod(+0xAED998) [0xeed998]
      [ReplicaSetFixture:job0:primary]  mongod(+0xAEE5D9) [0xeee5d9]
      [ReplicaSetFixture:job0:primary]  mongod(_ZN5mongo23ServiceEntryPointMongod13handleRequestEPNS_16OperationContextERKNS_7MessageE+0x280) [0xeef310]
      [ReplicaSetFixture:job0:primary]  mongod(+0x102DB78) [0x142db78]
      [ReplicaSetFixture:job0:primary]  mongod(_ZN5mongo14DBDirectClient4callERNS_7MessageES2_bPNSt7__cxx1112basic_stringIcSt11char_traitsIcESaIcEEE+0x20) [0x142e190]
      [ReplicaSetFixture:job0:primary]  mongod(_ZN5mongo12DBClientBase20runCommandWithTargetENS_12OpMsgRequestE+0x1CF) [0x1df6a2f]
      [ReplicaSetFixture:job0:primary]  mongod(_ZN5mongo13RSLocalClient14runCommandOnceEPNS_16OperationContextERKNSt7__cxx1112basic_stringIcSt11char_traitsIcESaIcEEERKNS_7BSONObjE+0xD64) [0x142bb14]
      [ReplicaSetFixture:job0:primary]  mongod(_ZN5mongo26KeysCollectionClientDirect7_insertEPNS_16OperationContextERKNSt7__cxx1112basic_stringIcSt11char_traitsIcESaIcEEERKNS_7BSONObjERKNS_19WriteConcernOptionsE+0x4A3) [0xefac83]
      [ReplicaSetFixture:job0:primary]  mongod(_ZN5mongo26KeysCollectionClientDirect12insertNewKeyEPNS_16OperationContextERKNS_7BSONObjE+0x1F) [0xefbbcf]
      [ReplicaSetFixture:job0:primary]  mongod(+0x1BDF5FF) [0x1fdf5ff]
      [ReplicaSetFixture:job0:primary]  mongod(_ZN5mongo35KeysCollectionCacheReaderAndUpdater7refreshEPNS_16OperationContextE+0x1B2) [0x1fdf972]
      [ReplicaSetFixture:job0:primary]  mongod(+0x1BDD2E9) [0x1fdd2e9]
      [ReplicaSetFixture:job0:primary]  mongod(+0x1BDD814) [0x1fdd814]
      [ReplicaSetFixture:job0:primary]  mongod(_ZN5mongo29KeysCollectionManagerSharding14PeriodicRunner18_doPeriodicRefreshEPNS_14ServiceContextENSt7__cxx1112basic_stringIcSt11char_traitsIcESaIcEEENS_8DurationISt5ratioILl1ELl1000EEEE+0x385) [0x1fdca25]
      [ReplicaSetFixture:job0:primary]  mongod(_ZNSt6thread5_ImplISt12_Bind_simpleIFSt5_BindIFSt7_Mem_fnIMN5mongo29KeysCollectionManagerSharding14PeriodicRunnerEFvPNS4_14ServiceContextENSt7__cxx1112basic_stringIcSt11char_traitsIcESaIcEEENS4_8DurationISt5ratioILl1ELl1000EEEEEEPS6_S8_SE_SI_EEvEEE6_M_runEv+0x61) [0x1fdd991]
      [ReplicaSetFixture:job0:primary]  mongod(+0x22F0D60) [0x26f0d60]
      [ReplicaSetFixture:job0:primary]  libpthread.so.0(+0x8184) [0x7f99c7f70184]
      [ReplicaSetFixture:job0:primary]  libc.so.6(clone+0x6D) [0x7f99c7c9cffd]
      [ReplicaSetFixture:job0:primary] -----  END BACKTRACE  -----
      

            Assignee:
            backlog-server-execution [DO NOT USE] Backlog - Storage Execution Team
            Reporter:
            xgen-evg-user Xgen-Evergreen-User
            Votes:
            0 Vote for this issue
            Watchers:
            6 Start watching this issue

              Created:
              Updated:
              Resolved: