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

WiredTiger primary died with: Fatal DBException in logOp(): 112 WriteConflict (mms-qa)

    • Type: Icon: Bug Bug
    • Resolution: Duplicate
    • Priority: Icon: Major - P3 Major - P3
    • None
    • Affects Version/s: 2.8.0-rc1
    • Component/s: Storage
    • Fully Compatible
    • ALL

      Log snippet below, will upload full logs as well:

      2014-11-26T16:00:01.029+0000 I CONTROL  [conn7960] pid=20435 port=27017 64-bit host=ip-10-167-172-82
      2014-11-26T16:00:01.029+0000 I CONTROL  [conn7960] db version v2.8.0-rc1
      2014-11-26T16:00:01.029+0000 I CONTROL  [conn7960] git version: c8171e7f969519af8b87a43425ae291ee69a0191
      2014-11-26T16:00:01.029+0000 I CONTROL  [conn7960] build info: Linux build14.nj1.10gen.cc 2.6.32-431.3.1.el6.x86_64 #1 SMP Fri Jan 3 21:39:27 UTC 2014 x86_64 BOOST_LIB_VERSION=1_49
      2014-11-26T16:00:01.029+0000 I CONTROL  [conn7960] allocator: tcmalloc
      2014-11-26T16:00:01.029+0000 I CONTROL  [conn7960] options: { config: "/data/mmsqa_6/automation-mongod.conf", net: { port: 27017 }, processManagement: { fork: true }, replication: { replSetName: "mmsqa" }, storage: { dbPath: "/data/mmsqa_6", engine: "wiredTiger" }, systemLog: { destination: "file", path: "/data/mmsqa_6/mongodb.log" } }
      2014-11-26T16:01:38.173+0000 I WRITE    [conn8125] update backupjobs.sdlocks query: { resource: "com.xgen.svc.brs.svc.AssignmentThread
      

      ...

      2014-11-27T12:12:50.814+0000 I WRITE    [conn16684] update mongo-distributed-lock.locks query: { _id: "com.xgen.svc.mms.cronLock", lockId: ObjectId('5476eac4e4b0681e68702179'), lockState: "locked" } update: { $set: { lastHeartbeat: new Date(1417090370539), lockTimeoutTime: new Date(1417090550539) } } nscanned:1 nscannedObjects:1 nMatched:1 nModified:1 keyUpdates:3  274ms
      2014-11-27T12:12:50.815+0000 I QUERY    [conn16684] command mongo-distributed-lock.$cmd command: update { update: "locks", ordered: true, updates: [ { q: { _id: "com.xgen.svc.mms.cronLock", lockId: ObjectId('5476eac4e4b0681e68702179'), lockState: "locked" }, u: { $set: { lastHeartbeat: new Date(1417090370539), lockTimeoutTime: new Date(1417090550539) } } } ] } keyUpdates:0  reslen:95 275ms
      2014-11-27T12:12:50.838+0000 I WRITE    [conn16709] update mmsdbminutes-even.rrdMinutes2014112712 query: { _id: "1b32a8677eb84033ad8b19147ae8e2e0-59f8a2d2e7026c1eaa8a6e2464d9a398-2014112712-dataSize-xgendbValsmmsdblogs-52805cb07ec5df2d7b0c9da7" } update: { $set: { mn.12.n: 1417090347, mn.12.t: 7668788, d: "2014112712", d2: new Date(1417089600000), g: "xgendbValsmmsdblogs-52805cb07ec5df2d7b0c9da7", i: "dataSize", cid: ObjectId('539a52d45cfcb7ae831e13f8'), hid: "59f8a2d2e7026c1eaa8a6e2464d9a398" } } nscanned:0 nscannedObjects:0 nMatched:1 nModified:1 upsert:1 keyUpdates:0  3067ms
      2014-11-27T12:12:50.864+0000 I QUERY    [conn16077] command mmsdbautomationlog.$cmd command: insert { $msg: "query not recording (too large)" } keyUpdates:0  reslen:80 1207ms
      2014-11-27T12:12:51.012+0000 I QUERY    [conn16196] query backupjobs.jobs query: { query: { broken: false, workingOn: false, rollback: false, theft.eligible: false, machine.owned: { machine: "mms-qa-daemon-1", head: "/data2/backups/daemon/" }, state.action: "applyOps", $where: this.lastOplogPush && this.lastOplogPush.t > this.head.t }, orderby: { finished: 1 } } planSummary: IXSCAN { machine.owned: 1, workingOn: 1, state.action: 1, finished: 1 } ntoreturn:1 ntoskip:0 nscanned:0 nscannedObjects:0 keyUpdates:0  nreturned:0 reslen:20 175ms
      2014-11-27T12:12:51.013+0000 I QUERY    [conn16200] command backupjobs.$cmd command: findAndModify { findandmodify: "jobs", query: { broken: false, workingOn: false, rollback: false, theft.eligible: false, machine.bound: { machine: "mms-qa-daemon-1", head: "/data/backups/daemon/" }, state.action: "initialSync" }, update: { $set: { workingOn: { heartbeat: 1417090283598, machine: { machine: "mms-qa-daemon-1", head: "/data/backups/daemon/" }, type: "initialSync", startedAt: new Date(1417090283598), recoveryAttempts: 0 } } } } keyUpdates:0  reslen:44 177ms
      2014-11-27T12:12:51.014+0000 I QUERY    [conn16196] command backupjobs.$cmd command: findAndModify { findandmodify: "jobs", query: { broken: false, workingOn: false, rollback: false, theft.eligible: false, machine.owned: { machine: "mms-qa-daemon-1", head: "/data2/backups/daemon/" }, state.action: "applyOps", $where: this.lastOplogPush && this.lastOplogPush.t > this.head.t }, sort: { finished: 1 }, update: { $set: { workingOn: { heartbeat: 1417090283597, machine: { machine: "mms-qa-daemon-1", head: "/data2/backups/daemon/" }, type: "applyOps", startedAt: new Date(1417090283597), recoveryAttempts: 0 } } } } keyUpdates:0  reslen:44 180ms
      2014-11-27T12:12:51.696+0000 F REPL     [conn16714] Fatal DBException in logOp(): 112 WriteConflict
      2014-11-27T12:12:51.704+0000 F -        [conn16714] terminate() called.
      
       0xf41389 0xf410d8 0x7f80fe9a5836 0x7f80fe9a5863 0xc33d5c 0xa19b42 0xa1a18d 0xbcbaba 0xbcc89d 0xb16db4 0xa9a80c 0xa9e76e 0x7e0290 0xefd9c1 0x7f80ff05f182 0x7f80fe15ffbd
      ----- BEGIN BACKTRACE -----
      {"backtrace":[{"b":"400000","o":"B41389"},{"b":"400000","o":"B410D8"},{"b":"7F80FE947000","o":"5E836"},{"b":"7F80FE947000","o":"5E863"},{"b":"400000","o":"833D5C"},{"b":"400000","o":"619B42"},{"b":"400000","o":"61A18D"},{"b":"400000","o":"7CBABA"},{"b":"400000","o":"7CC89D"},{"b":"400000","o":"716DB4"},{"b":"400000","o":"69A80C"},{"b":"400000","o":"69E76E"},{"b":"400000","o":"3E0290"},{"b":"400000","o":"AFD9C1"},{"b":"7F80FF057000","o":"8182"},{"b":"7F80FE065000","o":"FAFBD"}],"processInfo":{ "mongodbVersion" : "2.8.0-rc1", "gitVersion" : "c8171e7f969519af8b87a43425ae291ee69a0191", "uname" : { "sysname" : "Linux", "release" : "3.13.0-36-generic", "version" : "#63-Ubuntu SMP Wed Sep 3 21:30:07 UTC 2014", "machine" : "x86_64" }, "somap" : [ { "elfType" : 2, "b" : "400000" }, { "b" : "7FFF3DE16000", "elfType" : 3 }, { "b" : "7F80FF057000", "path" : "/lib/x86_64-linux-gnu/libpthread.so.0", "elfType" : 3 }, { "b" : "7F80FEE4F000", "path" : "/lib/x86_64-linux-gnu/librt.so.1", "elfType" : 3 }, { "b" : "7F80FEC4B000", "path" : "/lib/x86_64-linux-gnu/libdl.so.2", "elfType" : 3 }, { "b" : "7F80FE947000", "path" : "/usr/lib/x86_64-linux-gnu/libstdc++.so.6", "elfType" : 3 }, { "b" : "7F80FE641000", "path" : "/lib/x86_64-linux-gnu/libm.so.6", "elfType" : 3 }, { "b" : "7F80FE42B000", "path" : "/lib/x86_64-linux-gnu/libgcc_s.so.1", "elfType" : 3 }, { "b" : "7F80FE065000", "path" : "/lib/x86_64-linux-gnu/libc.so.6", "elfType" : 3 }, { "b" : "7F80FF275000", "path" : "/lib64/ld-linux-x86-64.so.2", "elfType" : 3 } ] }}
       mongod(_ZN5mongo15printStackTraceERSo+0x29) [0xf41389]
       mongod(+0xB410D8) [0xf410d8]
       libstdc++.so.6(+0x5E836) [0x7f80fe9a5836]
       libstdc++.so.6(+0x5E863) [0x7f80fe9a5863]
       mongod(_ZN5mongo4repl5logOpEPNS_16OperationContextEPKcS4_RKNS_7BSONObjEPS5_Pbb+0x1DC) [0xc33d5c]
       mongod(_ZN5mongo11UpdateStage18transformAndUpdateERNS_7BSONObjERNS_7DiskLocE+0x5F2) [0xa19b42]
       mongod(_ZN5mongo11UpdateStage4workEPm+0x2AD) [0xa1a18d]
       mongod(_ZN5mongo12PlanExecutor7getNextEPNS_7BSONObjEPNS_7DiskLocE+0x9A) [0xbcbaba]
       mongod(_ZN5mongo12PlanExecutor11executePlanEv+0x3D) [0xbcc89d]
       mongod(_ZN5mongo14UpdateExecutor7executeEPNS_8DatabaseE+0x134) [0xb16db4]
       mongod(_ZN5mongo14receivedUpdateEPNS_16OperationContextERNS_7MessageERNS_5CurOpE+0x58C) [0xa9a80c]
       mongod(_ZN5mongo16assembleResponseEPNS_16OperationContextERNS_7MessageERNS_10DbResponseERKNS_11HostAndPortEb+0x178E) [0xa9e76e]
       mongod(_ZN5mongo16MyMessageHandler7processERNS_7MessageEPNS_21AbstractMessagingPortEPNS_9LastErrorE+0xE0) [0x7e0290]
       mongod(_ZN5mongo17PortMessageServer17handleIncomingMsgEPv+0x421) [0xefd9c1]
       libpthread.so.0(+0x8182) [0x7f80ff05f182]
       libc.so.6(clone+0x6D) [0x7f80fe15ffbd]
      -----  END BACKTRACE  -----
      

      Attempts to restart the server fail with:

      2014-11-27T12:13:14.988+0000 I CONTROL  [initandlisten] MongoDB starting : pid=1485 port=27017 dbpath=/data/mmsqa_6 64-bit host=ip-10-167-172-82
      2014-11-27T12:13:14.988+0000 I CONTROL  [initandlisten] 
      2014-11-27T12:13:14.988+0000 I CONTROL  [initandlisten] ** WARNING: /sys/kernel/mm/transparent_hugepage/enabled is 'always'.
      2014-11-27T12:13:14.988+0000 I CONTROL  [initandlisten] **        We suggest setting it to 'never'
      2014-11-27T12:13:14.988+0000 I CONTROL  [initandlisten] 
      2014-11-27T12:13:14.988+0000 I CONTROL  [initandlisten] db version v2.8.0-rc1
      2014-11-27T12:13:14.988+0000 I CONTROL  [initandlisten] git version: c8171e7f969519af8b87a43425ae291ee69a0191
      2014-11-27T12:13:14.988+0000 I CONTROL  [initandlisten] build info: Linux build14.nj1.10gen.cc 2.6.32-431.3.1.el6.x86_64 #1 SMP Fri Jan 3 21:39:27 UTC 2014 x86_64 BOOST_LIB_VERSION=1_49
      2014-11-27T12:13:14.988+0000 I CONTROL  [initandlisten] allocator: tcmalloc
      2014-11-27T12:13:14.988+0000 I CONTROL  [initandlisten] options: { config: "/data/mmsqa_6/automation-mongod.conf", net: { port: 27017 }, processManagement: { fork: true }, replication: { replSetName: "mmsqa" }, storage: { dbPath: "/data/mmsqa_6", engine: "wiredTiger" }, systemLog: { destination: "file", path: "/data/mmsqa_6/mongodb.log" } }
      2014-11-27T12:13:14.988+0000 I STORAGE  [initandlisten] wiredtiger_open config: create,cache_size=3G,session_max=20000,extensions=[local=(entry=index_collator_extension)],statistics=(all),log=(enabled=true,archive=true,path=journal),checkpoint=(wait=60,log_size=2GB),
      2014-11-27T12:13:15.331+0000 E STORAGE  [initandlisten] no cursor for uri: table:collection-355-919330507046748388
      2014-11-27T12:13:15.331+0000 I -        [initandlisten] Invariant failure c src/mongo/db/storage/wiredtiger/wiredtiger_record_store.cpp 909
      2014-11-27T12:13:15.338+0000 I CONTROL  [initandlisten] 
       0xf41389 0xee8d61 0xecdf82 0xd59471 0xd59577 0xd59613 0xd59fec 0xd538d2 0xce176b 0xce57e4 0xd52f90 0xa6a708 0x7da5ec 0x7df304 0x7f9f41246ec5 0x7d8259
      ----- BEGIN BACKTRACE -----
      {"backtrace":[{"b":"400000","o":"B41389"},{"b":"400000","o":"AE8D61"},{"b":"400000","o":"ACDF82"},{"b":"400000","o":"959471"},{"b":"400000","o":"959577"},{"b":"400000","o":"959613"},{"b":"400000","o":"959FEC"},{"b":"400000","o":"9538D2"},{"b":"400000","o":"8E176B"},{"b":"400000","o":"8E57E4"},{"b":"400000","o":"952F90"},{"b":"400000","o":"66A708"},{"b":"400000","o":"3DA5EC"},{"b":"400000","o":"3DF304"},{"b":"7F9F41225000","o":"21EC5"},{"b":"400000","o":"3D8259"}],"processInfo":{ "mongodbVersion" : "2.8.0-rc1", "gitVersion" : "c8171e7f969519af8b87a43425ae291ee69a0191", "uname" : { "sysname" : "Linux", "release" : "3.13.0-36-generic", "version" : "#63-Ubuntu SMP Wed Sep 3 21:30:07 UTC 2014", "machine" : "x86_64" }, "somap" : [ { "elfType" : 2, "b" : "400000" }, { "b" : "7FFF698FE000", "elfType" : 3 }, { "b" : "7F9F42217000", "path" : "/lib/x86_64-linux-gnu/libpthread.so.0", "elfType" : 3 }, { "b" : "7F9F4200F000", "path" : "/lib/x86_64-linux-gnu/librt.so.1", "elfType" : 3 }, { "b" : "7F9F41E0B000", "path" : "/lib/x86_64-linux-gnu/libdl.so.2", "elfType" : 3 }, { "b" : "7F9F41B07000", "path" : "/usr/lib/x86_64-linux-gnu/libstdc++.so.6", "elfType" : 3 }, { "b" : "7F9F41801000", "path" : "/lib/x86_64-linux-gnu/libm.so.6", "elfType" : 3 }, { "b" : "7F9F415EB000", "path" : "/lib/x86_64-linux-gnu/libgcc_s.so.1", "elfType" : 3 }, { "b" : "7F9F41225000", "path" : "/lib/x86_64-linux-gnu/libc.so.6", "elfType" : 3 }, { "b" : "7F9F42435000", "path" : "/lib64/ld-linux-x86-64.so.2", "elfType" : 3 } ] }}
       mongod(_ZN5mongo15printStackTraceERSo+0x29) [0xf41389]
       mongod(_ZN5mongo10logContextEPKc+0xE1) [0xee8d61]
       mongod(_ZN5mongo15invariantFailedEPKcS1_j+0xB2) [0xecdf82]
       mongod(_ZN5mongo21WiredTigerRecordStore8Iterator7_locateERKNS_7DiskLocEb+0x181) [0xd59471]
       mongod(_ZN5mongo21WiredTigerRecordStore8IteratorC2ERKS0_PNS_16OperationContextERKNS_7DiskLocERKNS_20CollectionScanParams9DirectionEb+0xA7) [0xd59577]
       mongod(_ZNK5mongo21WiredTigerRecordStore11getIteratorEPNS_16OperationContextERKNS_7DiskLocERKNS_20CollectionScanParams9DirectionE+0x43) [0xd59613]
       mongod(_ZN5mongo21WiredTigerRecordStoreC1EPNS_16OperationContextERKNS_10StringDataES5_bllPNS_28CappedDocumentDeleteCallbackEPNS_20WiredTigerSizeStorerE+0x33C) [0xd59fec]
       mongod(_ZN5mongo18WiredTigerKVEngine14getRecordStoreEPNS_16OperationContextERKNS_10StringDataES5_RKNS_17CollectionOptionsE+0x132) [0xd538d2]
       mongod(_ZN5mongo22KVDatabaseCatalogEntry14initCollectionEPNS_16OperationContextERKSs+0xEB) [0xce176b]
       mongod(_ZN5mongo15KVStorageEngineC2EPNS_8KVEngineE+0x684) [0xce57e4]
       mongod(+0x952F90) [0xd52f90]
       mongod(_ZN5mongo23GlobalEnvironmentMongoD22setGlobalStorageEngineERKSs+0x138) [0xa6a708]
       mongod(_ZN5mongo13initAndListenEi+0x6EC) [0x7da5ec]
       mongod(main+0x134) [0x7df304]
       libc.so.6(__libc_start_main+0xF5) [0x7f9f41246ec5]
       mongod(+0x3D8259) [0x7d8259]
      -----  END BACKTRACE  -----
      2014-11-27T12:13:15.338+0000 I -        [initandlisten] 
      
      ***aborting after invariant() failure
      2014-11-27T12:13:15.346+0000 F -        [initandlisten] Got signal: 6 (Aborted).
      
       0xf41389 0xf40cf2 0xf41076 0x7f9f4125bc30 0x7f9f4125bbb9 0x7f9f4125efc8 0xecdfc7 0xd59471 0xd59577 0xd59613 0xd59fec 0xd538d2 0xce176b 0xce57e4 0xd52f90 0xa6a708 0x7da5ec 0x7df304 0x7f9f41246ec5 0x7d8259
      ----- BEGIN BACKTRACE -----
      {"backtrace":[{"b":"400000","o":"B41389"},{"b":"400000","o":"B40CF2"},{"b":"400000","o":"B41076"},{"b":"7F9F41225000","o":"36C30"},{"b":"7F9F41225000","o":"36BB9"},{"b":"7F9F41225000","o":"39FC8"},{"b":"400000","o":"ACDFC7"},{"b":"400000","o":"959471"},{"b":"400000","o":"959577"},{"b":"400000","o":"959613"},{"b":"400000","o":"959FEC"},{"b":"400000","o":"9538D2"},{"b":"400000","o":"8E176B"},{"b":"400000","o":"8E57E4"},{"b":"400000","o":"952F90"},{"b":"400000","o":"66A708"},{"b":"400000","o":"3DA5EC"},{"b":"400000","o":"3DF304"},{"b":"7F9F41225000","o":"21EC5"},{"b":"400000","o":"3D8259"}],"processInfo":{ "mongodbVersion" : "2.8.0-rc1", "gitVersion" : "c8171e7f969519af8b87a43425ae291ee69a0191", "uname" : { "sysname" : "Linux", "release" : "3.13.0-36-generic", "version" : "#63-Ubuntu SMP Wed Sep 3 21:30:07 UTC 2014", "machine" : "x86_64" }, "somap" : [ { "elfType" : 2, "b" : "400000" }, { "b" : "7FFF698FE000", "elfType" : 3 }, { "b" : "7F9F42217000", "path" : "/lib/x86_64-linux-gnu/libpthread.so.0", "elfType" : 3 }, { "b" : "7F9F4200F000", "path" : "/lib/x86_64-linux-gnu/librt.so.1", "elfType" : 3 }, { "b" : "7F9F41E0B000", "path" : "/lib/x86_64-linux-gnu/libdl.so.2", "elfType" : 3 }, { "b" : "7F9F41B07000", "path" : "/usr/lib/x86_64-linux-gnu/libstdc++.so.6", "elfType" : 3 }, { "b" : "7F9F41801000", "path" : "/lib/x86_64-linux-gnu/libm.so.6", "elfType" : 3 }, { "b" : "7F9F415EB000", "path" : "/lib/x86_64-linux-gnu/libgcc_s.so.1", "elfType" : 3 }, { "b" : "7F9F41225000", "path" : "/lib/x86_64-linux-gnu/libc.so.6", "elfType" : 3 }, { "b" : "7F9F42435000", "path" : "/lib64/ld-linux-x86-64.so.2", "elfType" : 3 } ] }}
       mongod(_ZN5mongo15printStackTraceERSo+0x29) [0xf41389]
       mongod(+0xB40CF2) [0xf40cf2]
       mongod(+0xB41076) [0xf41076]
       libc.so.6(+0x36C30) [0x7f9f4125bc30]
       libc.so.6(gsignal+0x39) [0x7f9f4125bbb9]
       libc.so.6(abort+0x148) [0x7f9f4125efc8]
       mongod(_ZN5mongo15invariantFailedEPKcS1_j+0xF7) [0xecdfc7]
       mongod(_ZN5mongo21WiredTigerRecordStore8Iterator7_locateERKNS_7DiskLocEb+0x181) [0xd59471]
       mongod(_ZN5mongo21WiredTigerRecordStore8IteratorC2ERKS0_PNS_16OperationContextERKNS_7DiskLocERKNS_20CollectionScanParams9DirectionEb+0xA7) [0xd59577]
       mongod(_ZNK5mongo21WiredTigerRecordStore11getIteratorEPNS_16OperationContextERKNS_7DiskLocERKNS_20CollectionScanParams9DirectionE+0x43) [0xd59613]
       mongod(_ZN5mongo21WiredTigerRecordStoreC1EPNS_16OperationContextERKNS_10StringDataES5_bllPNS_28CappedDocumentDeleteCallbackEPNS_20WiredTigerSizeStorerE+0x33C) [0xd59fec]
       mongod(_ZN5mongo18WiredTigerKVEngine14getRecordStoreEPNS_16OperationContextERKNS_10StringDataES5_RKNS_17CollectionOptionsE+0x132) [0xd538d2]
       mongod(_ZN5mongo22KVDatabaseCatalogEntry14initCollectionEPNS_16OperationContextERKSs+0xEB) [0xce176b]
       mongod(_ZN5mongo15KVStorageEngineC2EPNS_8KVEngineE+0x684) [0xce57e4]
       mongod(+0x952F90) [0xd52f90]
       mongod(_ZN5mongo23GlobalEnvironmentMongoD22setGlobalStorageEngineERKSs+0x138) [0xa6a708]
       mongod(_ZN5mongo13initAndListenEi+0x6EC) [0x7da5ec]
       mongod(main+0x134) [0x7df304]
       libc.so.6(__libc_start_main+0xF5) [0x7f9f41246ec5]
       mongod(+0x3D8259) [0x7d8259]
      -----  END BACKTRACE  -----
      

            Assignee:
            matt.kangas Matt Kangas
            Reporter:
            cailin.nelson@mongodb.com Cailin Nelson (Inactive)
            Votes:
            0 Vote for this issue
            Watchers:
            13 Start watching this issue

              Created:
              Updated:
              Resolved: