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

Document not returned: "Didn't find DiskLoc in WiredTigerRecordStore"

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

      wiredtiger primary:

      mmsdev:PRIMARY> db.app.migrations.findOne({_id: 'DownloadBaseWindowsMigration'});
      2014-11-26T19:12:29.880+0000 I QUERY    Error: error: { "$err" : "Didn't find DiskLoc in WiredTigerRecordStore", "code" : 28556 }
          at Error (<anonymous>)
          at DBQuery.next (src/mongo/shell/query.js:259:15)
          at DBCollection.findOne (src/mongo/shell/collection.js:187:22)
          at (shell):1:19 at src/mongo/shell/query.js:259
      

      In the logs:

      2014-11-26T19:12:29.874+0000 I -        [conn1829] Assertion: 28556:Didn't find DiskLoc in WiredTigerRecordStore
      2014-11-26T19:12:29.879+0000 I CONTROL  [conn1829] 
       0xf41389 0xee8d61 0xece71f 0xd5833e 0x8f1506 0x9ecba3 0xbcbaba 0xbb90bc 0xa9db93 0x7e0290 0xefd9c1 0x7f79b3a79182 0x7f79b2b79fbd
      ----- BEGIN BACKTRACE -----
      {"backtrace":[{"b":"400000","o":"B41389"},{"b":"400000","o":"AE8D61"},{"b":"400000","o":"ACE71F"},{"b":"400000","o":"95833E"},{"b":"400000","o":"4F1506"},{"b":"400000","o":"5ECBA3"},{"b":"400000","o":"7CBABA"},{"b":"400000","o":"7B90BC"},{"b":"400000","o":"69DB93"},{"b":"400000","o":"3E0290"},{"b":"400000","o":"AFD9C1"},{"b":"7F79B3A71000","o":"8182"},{"b":"7F79B2A7F000","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" : "7FFF89EAE000", "elfType" : 3 }, { "b" : "7F79B3A71000", "path" : "/lib/x86_64-linux-gnu/libpthread.so.0", "elfType" : 3 }, { "b" : "7F79B3869000", "path" : "/lib/x86_64-linux-gnu/librt.so.1", "elfType" : 3 }, { "b" : "7F79B3665000", "path" : "/lib/x86_64-linux-gnu/libdl.so.2", "elfType" : 3 }, { "b" : "7F79B3361000", "path" : "/usr/lib/x86_64-linux-gnu/libstdc++.so.6", "elfType" : 3 }, { "b" : "7F79B305B000", "path" : "/lib/x86_64-linux-gnu/libm.so.6", "elfType" : 3 }, { "b" : "7F79B2E45000", "path" : "/lib/x86_64-linux-gnu/libgcc_s.so.1", "elfType" : 3 }, { "b" : "7F79B2A7F000", "path" : "/lib/x86_64-linux-gnu/libc.so.6", "elfType" : 3 }, { "b" : "7F79B3C8F000", "path" : "/lib64/ld-linux-x86-64.so.2", "elfType" : 3 } ] }}
       mongod(_ZN5mongo15printStackTraceERSo+0x29) [0xf41389]
       mongod(_ZN5mongo10logContextEPKc+0xE1) [0xee8d61]
       mongod(_ZN5mongo11msgassertedEiPKc+0xAF) [0xece71f]
       mongod(+0x95833E) [0xd5833e]
       mongod(_ZNK5mongo10Collection6docForEPNS_16OperationContextERKNS_7DiskLocE+0x16) [0x8f1506]
       mongod(_ZN5mongo11IDHackStage4workEPm+0x1A3) [0x9ecba3]
       mongod(_ZN5mongo12PlanExecutor7getNextEPNS_7BSONObjEPNS_7DiskLocE+0x9A) [0xbcbaba]
       mongod(_ZN5mongo11newRunQueryEPNS_16OperationContextERNS_7MessageERNS_12QueryMessageERNS_5CurOpES3_b+0x99C) [0xbb90bc]
       mongod(_ZN5mongo16assembleResponseEPNS_16OperationContextERNS_7MessageERNS_10DbResponseERKNS_11HostAndPortEb+0xBB3) [0xa9db93]
       mongod(_ZN5mongo16MyMessageHandler7processERNS_7MessageEPNS_21AbstractMessagingPortEPNS_9LastErrorE+0xE0) [0x7e0290]
       mongod(_ZN5mongo17PortMessageServer17handleIncomingMsgEPv+0x421) [0xefd9c1]
       libpthread.so.0(+0x8182) [0x7f79b3a79182]
       libc.so.6(clone+0x6D) [0x7f79b2b79fbd]
      -----  END BACKTRACE  -----
      2014-11-26T19:12:29.879+0000 I COMMAND  [conn1829] assertion 28556 Didn't find DiskLoc in WiredTigerRecordStore ns:cloudconf.app.migrations query:{ _id: "DownloadBaseWindowsMigration" }
      2014-11-26T19:12:29.879+0000 I COMMAND  [conn1829]  ntoskip:0 ntoreturn:-1
      2014-11-26T19:13:38.306+0000 I QUERY    [conn521] command admin.$cmd command: listDatabases { listDatabases: 1 } keyUpdates:0  reslen:4505 4430ms
      

      On the mmapv1 secondary:

      mmsdev:SECONDARY> db.app.migrations.findOne({_id: 'DownloadBaseWindowsMigration'});
      null
      

      This document is unusual in that we know when it should have been created. According to the app server logs it was created here:

      ubuntu@ip-10-167-150-115:/log$ grep DownloadBaseWindowsMigration mms-server.log*
      mms-server.log:     [java] 2014-11-25T19:30:31.674+0000 [main] gid: INFO  com.xgen.svc.common.migration.MigrationSvc [runOne:72] - Running migration DownloadBaseWindowsMigration
      mms-server.log:     [java] 2014-11-25T19:30:31.712+0000 [main] gid: INFO  com.xgen.svc.common.migration.impl.DownloadBaseWindowsMigration [runInternal:28] - Finished migrating 26 documents
      mms-server.log:     [java] 2014-11-25T19:30:31.713+0000 [main] gid: INFO  com.xgen.svc.common.migration.MigrationSvc [runOne:74] - Completed migration DownloadBaseWindowsMigration in 37msec
      

      Furthermore, the app servers would have validated the existence of this document on every start up. They did this successfully on several occasions before hitting this error. According to the log snippets below I would expect the existence of this document to have been validated on 10 occasions, before hitting the error.

       [java] 2014-11-25T19:32:07.661+0000 [main] gid: INFO  com.xgen.svc.core.ServerMain [start:329] - Started mms in: 14886 (ms)
           [java] 2014-11-25T21:32:17.503+0000 [main] gid: INFO  com.xgen.svc.core.ServerMain [start:329] - Started mms in: 29046 (ms)
           [java] 2014-11-25T22:31:59.308+0000 [main] gid: INFO  com.xgen.svc.core.ServerMain [start:329] - Started mms in: 10328 (ms)
           [java] 2014-11-25T22:47:17.483+0000 [main] gid: INFO  com.xgen.svc.core.ServerMain [start:329] - Started mms in: 29441 (ms)
           [java] 2014-11-26T00:02:20.766+0000 [main] gid: INFO  com.xgen.svc.core.ServerMain [start:329] - Started mms in: 31003 (ms)
           [java] 2014-11-26T14:32:41.533+0000 [main] gid: INFO  com.xgen.svc.core.ServerMain [start:329] - Started mms in: 49895 (ms)
           [java] 2014-11-26T14:47:01.686+0000 [main] gid: INFO  com.xgen.svc.core.ServerMain [start:329] - Started mms in: 13590 (ms)
           [java] 2014-11-26T15:01:59.900+0000 [main] gid: INFO  com.xgen.svc.core.ServerMain [start:329] - Started mms in: 10134 (ms)
           [java] 2014-11-26T15:16:58.646+0000 [main] gid: INFO  com.xgen.svc.core.ServerMain [start:329] - Started mms in: 10882 (ms)
           [java] 2014-11-26T15:46:56.920+0000 [main] gid: INFO  com.xgen.svc.core.ServerMain [start:329] - Started mms in: 9591 (ms)
           [java] 2014-11-26T17:15:26.277+0000 [main] gid: ERROR com.xgen.svc.common.migration.MigrationRunner [run:183] - An unexpected error occurred: Didn't find DiskLoc in WiredTigerRecordStore
      

      Finally, the expected shape of this document is:

      {
      	"_id" : "DownloadBaseWindowsMigration",
      	"status" : "COMPLETE",
      	"numInserted" : 0,
      	"numDeleted" : 0,
      	"numUpdated" : 26,
      	"startDate" : ISODate("2014-11-25T19:30:31.676Z"),
      	"completedDate" : ISODate("2014-11-25T19:30:31.713Z")
      }
      

      Please note that the -id is not an ObjectId.

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

              Created:
              Updated:
              Resolved: