[SERVER-23124] db.collection.count() returns -1 Created: 14/Mar/16  Updated: 16/Jul/19  Resolved: 16/Mar/16

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

Type: Bug Priority: Major - P3
Reporter: airs0urce Assignee: Kelsey Schubert
Resolution: Duplicate Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Attachments: File test.bson    
Issue Links:
Duplicate
duplicates SERVER-20063 WiredTiger collection size cache can ... Closed
is duplicated by SERVER-23123 db.collection.count() returns -1 Closed
Operating System: ALL
Steps To Reproduce:

Get dump of "swipes" collection from attached test.bson
Run mongorestore --collection swipes --db databasename /Users/airs0urce/Desktop/test.bson

Participants:

 Description   

I have several collections in db. Mongo uses WiredTiger engine.
I removed all records in "swipes" collection (all at once).

then tried to run db.swipes.count() and it returned -1.
https://dl.dropboxusercontent.com/u/1875424/1_count_returns_minus_1.png

Then I made dump of swipes collection on remote server:
https://dl.dropboxusercontent.com/u/1875424/2_dump_buggy_collection.png

Downloaded, unpacked and tried to restore that collection on local machine:
https://dl.dropboxusercontent.com/u/1875424/3_attemt_to_restore.png

On remote and local machines I use Mongo 3.2.4.



 Comments   
Comment by airs0urce [ 16/Jul/19 ]

I was able to reproduce it on 4.0.10 and validate() fixed it btw:

rs0:PRIMARY> db.error_log.count({})
-1
rs0:PRIMARY> version()
4.0.10
rs0:PRIMARY> db.error_log.validate()
{
"ns" : "nearby_main.error_log",
"nInvalidDocuments" : NumberLong(0),
"nrecords" : 0,
"nIndexes" : 1,
"keysPerIndex" :

{ "_id_" : 0 }

,
"valid" : true,
"warnings" : [
"Some checks omitted for speed. use

{full:true}

option to do more thorough scan."
],
"errors" : [ ],
"extraIndexEntries" : [ ],
"missingIndexEntries" : [ ],
"ok" : 1,
"operationTime" : Timestamp(1563252522, 16),
"$clusterTime" : {
"clusterTime" : Timestamp(1563252522, 16),
"signature" :

{ "hash" : BinData(0,"AAAAAAAAAAAAAAAAAAAAAAAAAAA="), "keyId" : NumberLong(0) }

}
}
rs0:PRIMARY> db.error_log.count({})
0
rs0:PRIMARY>

Comment by Kelsey Schubert [ 16/Mar/16 ]

Hi airs0urce,

Thank you for help investigating this issue. We are tracking this behavior in SERVER-20063, and I have recently attached a script which reproduces this behavior on that ticket. Please watch SERVER-20063 for updates and feel free to vote for it.

If you encounter this behavior in the future, I would recommend executing db.collection.validate() to correct the issue. Additional information about the behavior of count() can be found in our documentation here.

Thank you,
Thomas

Comment by airs0urce [ 16/Mar/16 ]

Unfortunately now I can't as this is development server and somebody did some actions and added records in that collection.
The only thing I can tell that after adding record it works as before. I can clear it again and it shows 0 records, but not -1.

Comment by Kelsey Schubert [ 16/Mar/16 ]

Hi airs0urce,

Can you please execute db.swipes.validate() and provide the output? Please confirm if the issue persists after validating the collection.

Thank you,
Thomas

Comment by airs0urce [ 15/Mar/16 ]

Yes, it still returns -1.
This is stats:
https://dl.dropboxusercontent.com/u/1875424/mongo_collection_stats.txt

Note: I replaced db name by

{DATABASE_NAME_HERE}
Comment by Kelsey Schubert [ 14/Mar/16 ]

Hi airs0urce,

Please include the --archive parameter when restoring the dump attached to this ticket:

mongorestore --archive=test.bson
2016-03-14T17:11:23.433-0400	setting number of parallel collections to number of parallel collections in archive (8)
2016-03-14T17:11:23.458-0400	creating intents for archive
2016-03-14T17:11:23.521-0400	reading metadata for nearby_afriflirt.swipes from archive 'test.bson'
2016-03-14T17:11:23.567-0400	restoring nearby_afriflirt.swipes from archive 'test.bson'
2016-03-14T17:11:23.875-0400	restoring indexes for collection nearby_afriflirt.swipes from metadata
2016-03-14T17:11:24.000-0400	finished restoring nearby_afriflirt.swipes (0 documents)
2016-03-14T17:11:24.000-0400	done

I successfully started a mongod with files from your dbpath. However, I was unable to observe the issue you describe where db.swipes.count() returns -1. On my instance it consistently returned 0. Since I was unable to reproduce this issue with your dataset, I will need some more information to continue to investigate this behavior.

  • Can you please confirm that you are still seeing this result on your remote server?
  • If so, can you please post the output of db.swipes.stats() from your remote server?

Thank you,
Thomas

Comment by airs0urce [ 14/Mar/16 ]

Thomas,

Tried to upload, but no luck: https://dl.dropboxusercontent.com/u/1875424/Screen%20Shot%202016-03-15%20at%201.24.15%20AM.png
May be because this is 3.3GB.

Instead I uploaded "dbpath_archive_with_auth.txt". Inside this file you can see URL of gzipped dbpath folder.
So, download this file. I'll keep it on server for couple weeks.

Comment by airs0urce [ 14/Mar/16 ]

Ok, packing dbpath folder, will upload after done.

Comment by airs0urce [ 14/Mar/16 ]

> How did you remove the documents in the swipes collection?
I did it using Rockmongo PHP gui. There is "Clear" link:
https://dl.dropboxusercontent.com/u/1875424/Screen%20Shot%202016-03-15%20at%2012.25.13%20AM.png
I check source code and it runs "delete" on collection (with PHP driver) with empty criteria:
https://dl.dropboxusercontent.com/u/1875424/Screen%20Shot%202016-03-15%20at%2012.50.17%20AM.png

Also:

  • in that collection I had about 3 millions records.
  • When I click Clear I closed that tab with rockmongo when deletion is not finished. But usually it keeps running until all records removed (I can even see how amount of records decreases even if I closed tab), I did it many times before.

> Were there long running operations on the swipes collection when the documents were removed? eg. background index build?
There were no index creations for sure. And I almost sure that there were no any long operations.
This is development server and usually nothing big happens there.

> Were there any unclean shutdowns or other errors logged by the server around this time?

$ uptime
13:32:11 up 156 days, 20:11, 3 users, load average: 0.10, 0.06, 0.09
I also asked our admins to send me system logs as I don't have access to them.

> Have you manipulated (copied or moved) the underling database files?
Only thing - this database was moved from production server may be 5 months ago, can't tell you exactly.
But we use same mongo version on dev and production servers and I moved data with mongodump/mongorestore.

> If this node is part of a replica set, are other members affected?
This node is not part of replica set

Comment by Kelsey Schubert [ 14/Mar/16 ]

Hi airs0urce,

Additionally, can you please upload the dbpath of your remote server?

I have created a secure upload portal. Files uploaded to this portal will only be visible to MongoDB employees investigating this issue and are routinely deleted after some time.

Thank you,
Thomas

Comment by Kelsey Schubert [ 14/Mar/16 ]

Hi airs0urce,

Thank you for opening this ticket. To get a better idea of what is going on here, please answer the following questions:

  1. How did you remove the documents in the swipes collection?
  2. Were there long running operations on the swipes collection when the documents were removed? eg. background index build?
  3. Were there any unclean shutdowns or other errors logged by the server around this time?
  4. Have you manipulated (copied or moved) the underling database files?
  5. If this node is part of a replica set, are other members affected?

Kind regards,
Thomas

Comment by airs0urce [ 14/Mar/16 ]

I don't remove that collection from remote server for about next 15 hours. So if you need any additional information - I'm ready to help.
You can write me in Telegram or Skype, my username: airs0urce.

Generated at Thu Feb 08 04:02:27 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.