[SERVER-9921] db.coll.find() returns nothing after drop and recreate Created: 13/Jun/13  Updated: 10/Dec/14  Resolved: 17/Feb/14

Status: Closed
Project: Core Server
Component/s: Querying
Affects Version/s: 2.4.2
Fix Version/s: None

Type: Bug Priority: Major - P3
Reporter: Anton V. Volokhov Assignee: Unassigned
Resolution: Done Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Operating System: ALL
Steps To Reproduce:

drop a collection via mongos
insert data to the collection via mongos
run db.collection.find() via mongos

Participants:

 Description   

2 shards, 2replica+arbiter each, connecting via mongos.

Hi there. I've dropped a collection, then continued to write data there(it was a lot of stale data, that I had to remove).
However, newly written data cannot be read from mongos, via mongod everything looks ok.

here some logs:

mongos>use vertis-creativework
mongos>db.pused.drop()

mongod logs:
Thu Jun 13 13:20:54 [conn1571507] command vertis-creativework.$cmd command: { drop: "pushed", $auth: { admin:

{ root: 2 }

} } ntoreturn:1 keyUpdates:0 locks(micros) w:12584 reslen:133 12ms
Thu Jun 13 13:20:54 [conn1408958] CoveredIndexMatcher::matches() {} 9:70c84318 0
Thu Jun 13 13:20:54 [conn1408966] CoveredIndexMatcher::matches() {} 9:70c84318 0
Thu Jun 13 13:20:54 [conn1408958] Matcher::matches() { ts: Timestamp 1371115254000|1, h: 630211948944288504, v: 2, op: "c", ns: "vertis-creativework.$cmd", o: { drop: "pushed", $auth: { admin:

{ root: 2 }

} } }
Thu Jun 13 13:20:54 [conn1408966] Matcher::matches() { ts: Timestamp 1371115254000|1, h: 630211948944288504, v: 2, op: "c", ns: "vertis-creativework.$cmd", o: { drop: "pushed", $auth: { admin:

{ root: 2 }

} } }
Thu Jun 13 13:20:54 [conn1408958] CoveredIndexMatcher _docMatcher->matches() returns 1
Thu Jun 13 13:20:54 [conn1408966] CoveredIndexMatcher _docMatcher->matches() returns 1

mongos>db.pushed.insert({_id:1})

mongod logs:

Thu Jun 13 13:23:08 [conn1571507] _reuse extent was:vertis-creativework.pushed now:vertis-creativework.pushed
Thu Jun 13 13:23:08 [conn1571507] allocExtent vertis-creativework.pushed size 1024 1
Thu Jun 13 13:23:08 [conn1571507] adding _id index for collection vertis-creativework.pushed
Thu Jun 13 13:23:08 [conn1571507] build index vertis-creativework.pushed

{ _id: 1 }

mem info: before index start vsize: 241624 resident: 6123 mapped: 119344
Thu Jun 13 13:23:08 [conn1571507] external sort root: /var/lib/mongodb/_tmp/esort.1371115388.220/
mem info: before final sort vsize: 241624 resident: 6123 mapped: 119344
mem info: after final sort vsize: 241624 resident: 6123 mapped: 119344
Thu Jun 13 13:23:08 [conn1571507] external sort used : 0 files in 0 secs
Thu Jun 13 13:23:08 [conn1571507] reuse extent was:vertis-creativework.pushed.$_id now:vertis-creativework.pushed.$id
Thu Jun 13 13:23:08 [conn1571507] allocExtent vertis-creativework.pushed.$id size 36864 1
Thu Jun 13 13:23:08 [conn1571507] New namespace: vertis-creativework.pushed.$id
Thu Jun 13 13:23:08 [conn1571507] done building bottom layer, going to commit
Thu Jun 13 13:23:08 [conn1571507] build index done. scanned 0 total records. 0.002 secs
Thu Jun 13 13:23:08 [conn1571507] New namespace: vertis-creativework.pushed
Thu Jun 13 13:23:08 [conn1571507] insert vertis-creativework.pushed keyUpdates:0 locks(micros) w:3851 3ms
Thu Jun 13 13:23:08 [conn1408958] CoveredIndexMatcher::matches() {} 9:70c85470 0
Thu Jun 13 13:23:08 [conn1571507] runQuery called vertis-creativework.$cmd { getlasterror: 1.0, w: 1.0, $auth: { admin:

{ root: 2 }

} }
Thu Jun 13 13:23:08 [conn1408958] Matcher::matches() { ts: Timestamp 1371115388000|1, h: -1867873785266695569, v: 2, op: "i", ns: "vertis-creativework.pushed", o:

{ _id: 1.0 }

}
Thu Jun 13 13:23:08 [conn1571507] run command vertis-creativework.$cmd { getlasterror: 1.0, w: 1.0, $auth: { admin:

{ root: 2 }

} }
Thu Jun 13 13:23:08 [conn1408958] CoveredIndexMatcher _docMatcher->matches() returns 1
Thu Jun 13 13:23:08 [conn1571507] Setting temporary authorization to: { admin:

{ root: 2 }

}
Thu Jun 13 13:23:08 [conn1571507] command vertis-creativework.$cmd command: { getlasterror: 1.0, w: 1.0, $auth: { admin:

{ root: 2 }

} } ntoreturn:1 keyUpdates:0 reslen:94 0ms
Thu Jun 13 13:23:08 [conn1408958] getmore local.oplog.rs query: { ts:

{ $gte: new Date(5880820189783654401) }

} cursorid:2864578847244946404 ntoreturn:0 keyUpdates:0 locks(micros) r:478 nreturned:1 reslen:121 169ms
Thu Jun 13 13:23:08 [conn1408966] CoveredIndexMatcher::matches() {} 9:70c85470 0
Thu Jun 13 13:23:08 [conn1408966] Matcher::matches() { ts: Timestamp 1371115388000|1, h: -1867873785266695569, v: 2, op: "i", ns: "vertis-creativework.pushed", o:

{ _id: 1.0 }

}
Thu Jun 13 13:23:08 [conn1408966] CoveredIndexMatcher _docMatcher->matches() returns 1

mongos>db.pushed.find()

mongod:
Thu Jun 13 13:24:35 [conn1571507] query vertis-creativework.pushed ntoreturn:0 keyUpdates:0 locks(micros) r:89 nreturned:0 reslen:20 0ms

mongos>db.pushed.stats()
{
"sharded" : false,
"primary" : "cs_mongodb-sh2-testing",
"ns" : "vertis-creativework.pushed",
"count" : 1,
"size" : 20,
"avgObjSize" : 20,
"storageSize" : 4096,
"numExtents" : 1,
"nindexes" : 1,
"lastExtentSize" : 4096,
"paddingFactor" : 1,
"systemFlags" : 1,
"userFlags" : 0,
"totalIndexSize" : 8176,
"indexSizes" :

{ "_id_" : 8176 }

,
"ok" : 1
}

mongos>db.pushed.find().explain()
{
"cursor" : "BasicCursor",
"isMultiKey" : false,
"n" : 0,
"nscannedObjects" : 1,
"nscanned" : 1,
"nscannedObjectsAllPlans" : 1,
"nscannedAllPlans" : 1,
"scanAndOrder" : false,
"indexOnly" : false,
"nYields" : 0,
"nChunkSkips" : 1,
"millis" : 0,
"indexBounds" : {

},
"server" : "cs-mongodb02gt.yandex.ru:27017",
"millis" : 0
}

in config.collections there is no document for mentioned collection.



 Comments   
Comment by Stennie Steneker (Inactive) [ 17/Feb/14 ]

Hi Anton,

Please be advised that I'm closing this issue due to inactivity.

If you are still able to reproduce the problem, please feel free to reopen with:

  • current details of your sharding configuration
  • MongoDB server version
  • logs from the mongos and primary mongod servers after following the steps suggested in Duraid's previous comment.

Thanks,
Stephen

Comment by Duraid Madina [ 09/Sep/13 ]

Hi Anton,

We've taken a look at the dump, but unfortunately can't find anything in it that conclusively explains the issue you're seeing.

Our working hypothesis here is that somehow, something has gone wrong with the collection drop.

Would you be able to restart the shard 2 mongod on host04gt.load.net:27017 (the primary shard) and then repeat the db.pushed.find().explain()?

Finally, I'd appreciate it if you could send us your mongos and primary mongod logs, after running the above command.

Thank you,
Duraid

Comment by Anton V. Volokhov [ 18/Aug/13 ]

Hi Duraid,

I've uploaded the dump.

Comment by Anton V. Volokhov [ 14/Aug/13 ]

Hi!
Seems, it was sharded once, yes.
The dump do contain private information. Provide some secure way to upload it, please.

Comment by Duraid Madina [ 14/Aug/13 ]

Hi Anton,

Has the pushed collection ever been sharded?

Also, would you be to run:

mongodump --host <mongos host> --port <mongos port> -d config 

and upload the contents of the dump/ directory which this command will create? (Just attach it to this ticket.) Please be aware that there may be private or sensitive information in this dump. If that is the case, please let us know, and we will arrange another way for you to send us that data.

Thanks,
Duraid

Comment by James Blackburn [ 13/Aug/13 ]

We see this in 2.2.3: SERVER-9243

Still trying to come up with a reliable reproducer.

Comment by Anton V. Volokhov [ 13/Aug/13 ]

mongos output:
mongos> sh.status()
— Sharding Status —
sharding version:

{ "_id" : 1, "version" : 3 }

shards:

{ "_id" : "cs_mongodb-sh1-testing", "host" : "cs_mongodb-sh1-testing/host01gt.load.net:27017,host03gt.load.net:27017", "tags" : [ "shard1" ] } { "_id" : "cs_mongodb-sh2-testing", "host" : "cs_mongodb-sh2-testing/host02gt.load.net:27017,host04gt.load.net:27017", "tags" : [ "shard2" ] }

databases:

{ "_id" : "admin", "partitioned" : false, "primary" : "config" }

<........> lots of information about other databases

{ "_id" : "vertis-creativework", "partitioned" : true, "primary" : "cs_mongodb-sh2-testing" }

mongos> db.pushed.find().explain()
{
"cursor" : "BasicCursor",
"isMultiKey" : false,
"n" : 0,
"nscannedObjects" : 1701681,
"nscanned" : 1701681,
"nscannedObjectsAllPlans" : 1701681,
"nscannedAllPlans" : 1701681,
"scanAndOrder" : false,
"indexOnly" : false,
"nYields" : 8864,
"nChunkSkips" : 1701681,
"millis" : 43631,
"indexBounds" : {

},
"server" : "host02gt.load.net:27017",
"millis" : 43631
}

mongod output:
cs_mongodb-sh1-testing:PRIMARY> db.stats()
{
"db" : "vertis-creativework",
"collections" : 2,
"objects" : 1,
"avgObjSize" : 52,
"dataSize" : 52,
"storageSize" : 12288,
"numExtents" : 2,
"indexes" : 0,
"indexSize" : 0,
"fileSize" : 10666115072,
"nsSizeMB" : 16,
"ok" : 1
}

cs_mongodb-sh2-testing:PRIMARY> db.stats()
{
"db" : "vertis-creativework",
"collections" : 5,
"objects" : 38768528,
"avgObjSize" : 515.7137615335821,
"dataSize" : 19993463404,
"storageSize" : 20824547232,
"numExtents" : 49,
"indexes" : 4,
"indexSize" : 3622352272,
"fileSize" : 29984030720,
"nsSizeMB" : 16,
"ok" : 1
}

Comment by Duraid Madina [ 13/Aug/13 ]

Hi Anton,

Can you please tell me the output of:

sh.status()
db.pushed.find().explain()

Also, can you please connect to each of your shards directly, and on each, tell me the output of:

db.status()

Thank you,
Duraid

Comment by Anton V. Volokhov [ 13/Aug/13 ]

Hi,

I can't drop and recreate table once more, but it is still in inconsistent state:

mongos> db.pushed.findOne()
null
mongos> db.pushed.count()
1701681
mongos> db.pushed.stats()
{
"sharded" : false,
"primary" : "cs_mongodb-sh2-testing",
"ns" : "vertis-creativework.pushed",
"count" : 1701681,
"size" : 656890596,
"avgObjSize" : 386.0245228100919,
"storageSize" : 786972672,
"numExtents" : 16,
"nindexes" : 1,
"lastExtentSize" : 210907136,
"paddingFactor" : 1.0000000000000466,
"systemFlags" : 1,
"userFlags" : 0,
"totalIndexSize" : 159857152,
"indexSizes" :

{ "_id_" : 159857152 }

,
"ok" : 1
}
mongos>

Comment by Duraid Madina [ 13/Aug/13 ]

Hi Anton,

I tried to reproduce your issue, but could not.

I'm concerned that one or more of your commands might have had a collection name with a small error. All of the commands you've used would succeed in this case, but might lead to unexpected results.

Are you still able to reproduce this issue? If you can, could you please capture the exact commands you use, and attach them to this case?

Many thanks,
Duraid

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