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

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

    Details

    • Type: Bug
    • Status: Closed
    • Priority: Major - P3
    • Resolution: Duplicate
    • Affects Version/s: 2.8.0-rc1
    • Fix Version/s: None
    • Component/s: Storage
    • Labels:
    • Operating System:
      ALL

      Description

      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.

        Issue Links

          Activity

          • Comments
          Hide
          matt.kangas Matt Kangas (Inactive) added a comment -

          Closed as dup of SERVER-16351

          Show
          matt.kangas Matt Kangas (Inactive) added a comment - Closed as dup of SERVER-16351

            People

            • Votes:
              0 Vote for this issue
              Watchers:
              13 Start watching this issue

              Dates

              • Created:
                Updated:
                Resolved: