[SERVER-16336] Document not returned: "Didn't find DiskLoc in WiredTigerRecordStore" Created: 26/Nov/14  Updated: 27/Dec/14  Resolved: 16/Dec/14

Status: Closed
Project: Core Server
Component/s: Storage
Affects Version/s: 2.8.0-rc1
Fix Version/s: None

Type: Bug Priority: Major - P3
Reporter: Cailin Nelson Assignee: Matt Kangas
Resolution: Duplicate Votes: 0
Labels: wiredtiger
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Issue Links:
Duplicate
duplicates SERVER-16351 Erroneous document returned in query ... Closed
Related
is related to SERVER-16649 mongos_rs_auth_shard_failure_toleranc... Closed
Operating System: ALL
Participants:

 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.



 Comments   
Comment by Matt Kangas [ 16/Dec/14 ]

Closed as dup of SERVER-16351

Generated at Thu Feb 08 03:40:42 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.