[SERVER-4340] Query not returning data from specific shard when querying on anything but "_id" only Created: 21/Nov/11  Updated: 08/Mar/13  Resolved: 05/Sep/12

Status: Closed
Project: Core Server
Component/s: Querying, Replication, Sharding
Affects Version/s: 2.0.1
Fix Version/s: None

Type: Bug Priority: Major - P3
Reporter: Koen Calliauw Assignee: Spencer Brody (Inactive)
Resolution: Cannot Reproduce Votes: 0
Labels: limit, replicaset, sharding, skip
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified
Environment:

Debian Squeeze


Attachments: File mongologs.tar.gz    
Operating System: Linux
Participants:

 Description   

Hi,

We've noticed that on one of our sharded collection we cannot do any non-specific queries. For example:

db.log_service.find() returns nothing, querying on anything other than only _id fails.
db.log_service.find(

{"_id":ObjectId("4eb3bf877961dc244d008235")}

) returns the document.

The environment is sharded over 3 replicaton sets, all of which currently only have a primary and an arbiter. The secondary has been taken down due to issues non-related to this. The configuration of the replicasets has been adjusted and rs.reconfig() has been run on all primaries. We have noticed however that mongos keeps complaining in the logs about not being able to reach these servers. Not sure if this is related to the issue.

Having previously discussed this on IRC, I've prepared a few pastes:

db.printShardingStatus();
http://pastie.org/private/pufkfflhtkwifmgcq8aq

mongos log extract:
http://pastie.org/private/93el01g9nocz9ocfiqzdw

rs.status() on replSetB primary (the only shard that has data for that collection as an automated script removed the data from the other shards, not from this one as aparently it couldn't find any):
http://pastie.org/private/an8g0gun7l6kevffusmytw

explain() on the working query:
db.log_service.find(

{"_id":ObjectId("4eb3bf877961dc244d008235")}

)
http://pastie.org/private/edfgbh9vkhlwf7o8tjmdq

explain() on the failing query:
db.log_service.find()
http://pastie.org/private/igeth69f84agwdjhmycyqa

We first noticed the issue when we couldn't query data with skip() set to a number higher than what was available on replSetA. At that time find() without limit and skip worked. Now, replSetA is empty and these stopped working.
Queries with skip() higher than item count on replSetA for different collections works without issues.

Best regards,
Koen



 Comments   
Comment by Spencer Brody (Inactive) [ 20/Jun/12 ]

Hi Koen,
Is this still happening for you? I have not been able to reproduce this successfully...
Would it be possible to upload a dump of your data? Or a smaller dataset that reproduces the problem?

Comment by Koen Calliauw [ 07/Feb/12 ]

Hi Spencer,

This is still the case, however, something changed, please see the explain() below, which was ran from mongos. Notice how n: is now 0. We've upgraded everything to 2.0.2 in the meantime.

explain() from mongos: http://pastie.org/private/pmwbd1ov1r7f8pzdjmucg
explain() from mongo2: http://pastie.org/private/p2nvw8qqhm8amaa7ftrnea (primary of ReplSetB and the only shard with data in it)

mongos log (LogLevel 10):
http://pastie.org/private/nleq4fluaig5y9gdcl3uw

The mongod's I can't set the LogLevel to 10 (error: http://pastie.org/private/lhzxcjw6g1jlq8sqknsra)
mongod1 log:
http://pastie.org/private/zuf43urxsppl6uj9k0tqg
mongod2 log:
http://pastie.org/private/1l1iii1efwmb2iukba67cg
mongod3 log:
http://pastie.org/private/hwzy630izsjy8otkvq3req

So, to answer your question, this is still happening but we can only reproduce it on this collection with this specific data (hasn't happened anywhere else yet).
Hope this helps.

Kind regards,
Koen

Comment by Spencer Brody (Inactive) [ 19/Jan/12 ]

Hi Koen. Is this still happening for you? Have you tried upgrading to 2.0.2?

Comment by Spencer Brody (Inactive) [ 19/Dec/11 ]

This is the same paste you attached earlier in the ticket using log level of 5. Can you capture a new log of trying the query and having it fail while running with loglevel 10? I'd also like logs form the primary of every shard. You can attach files to this ticket, and if you zip/tar the log files you should be able to just attach the full files directly.

Comment by Koen Calliauw [ 16/Dec/11 ]

Hi Spencer,

You can find the paste here:
http://pastie.org/private/p1frdlftdmbxxuqqq18rbg

The actual query happened at 09:58:53

Best regards,
Koen Calliauw
Layer7 v.o.f.
DDI: +32 50 704 415
Cell: +32 499 74 28 73

Comment by Spencer Brody (Inactive) [ 09/Dec/11 ]

Actually, for good measure, please attach the logs from the primaries of each shard for the same period as well. To confirm, you're not doing slaveOk queries, right?

Comment by Spencer Brody (Inactive) [ 09/Dec/11 ]

I want the logs from the mongos running 2.0.1 at log level 10 for when you try to do a generic query and it fails.

Comment by Koen Calliauw [ 09/Dec/11 ]

Hi Spencer,

Can you tell me from which timeframe you need these logs and from which servers? Also, on 1.8.4 or 2.0.1?

/Koen

Comment by Spencer Brody (Inactive) [ 07/Dec/11 ]

Can you attach the logs from log level 10? There's one specific message I'm looking for. As for the "shard version not ok" error, that's from SERVER-4020 which is fixed in 2.0.2 - you can either try upgrading your mongos to the 2.0.2 release candidate or wait for the official 2.0.2 release that should be happening in about a week. As you've already figured out, the workaround is to run flushRouterConfig whenever it happens.

Comment by Koen Calliauw [ 07/Dec/11 ]

Believe it or not, but the query works fine with 1.8.4 mongos! (waiting about 1 minute after mongos was started. Any earlier again didn't return anything)

after reverting back to 2.0.1, query stopped working again.

I actually don't see any additional stuff in the logs when setting the loglevel to 10. I ran the command through mongos.

What I also noticed the last few days is that I get these messages:
Wed Dec 7 09:06:08 [conn176] Assertion: 13388:[betrobot_production.bets] shard version not ok in Client::Context: client in sharded mode, but doesn't have version set for this collection: betrobot_production.bets myVersion: 9|0
on a specific primary (only one at a time usually) at a very fast rate (also filling up disk). Running the flushRouterConfig fixes that, but having to run that every time on all mongos is a pain in the backside to say the least

/Koen

Comment by Spencer Brody (Inactive) [ 05/Dec/11 ]

Also, could you try it one more time on 2.0.1 after setting the log level to 10 (sorry for making you do that twice, I thought 5 was the highest log level but actually realized that there's some useful information at levels higher than that). After getting the log output with level 10 verbosity you can set the log level back to normal to avoid filling up your disk too quickly.

Comment by Spencer Brody (Inactive) [ 05/Dec/11 ]

Could you try bringing up a 1.8.4 mongos and see if you see the same problem when querying through it or if any different errors are thrown when using 1.8.4? It should be fine to use mongos from 1.8.4 with a 2.0.1 cluster.

Comment by Koen Calliauw [ 05/Dec/11 ]

Hi,

Anything else I can try? Data is still stuck on this server.

/Koen

PS: I also reset the loglevel back now. Disk filled up after a few hours.

Comment by Koen Calliauw [ 29/Nov/11 ]

Hi Spencer,

You can find the paste here:
http://pastie.org/private/p1frdlftdmbxxuqqq18rbg

/Koen

Comment by Spencer Brody (Inactive) [ 28/Nov/11 ]

Can you try upping the logging verbosity on the mongos by running

db.adminCommand( { setParameter : 1 , logLevel : 5 } )

And then try querying and send the log output?

Comment by Koen Calliauw [ 28/Nov/11 ]

Yes, everything has even been rebooted in the meantime, so all mongod, mongos and config servers have been restarted at least once or twice since the issue started showing.

/Koen

Comment by Eliot Horowitz (Inactive) [ 28/Nov/11 ]

Have you tried bouncing all mongod and mongos?

Comment by Koen Calliauw [ 27/Nov/11 ]

Also, I doubt that removing the secondaries has anything to do with this issue, since we were able to query the 2 other shards perfectly, also after removing the replset secondaries there.

/Koen

Comment by Koen Calliauw [ 27/Nov/11 ]

Hi Eliot,

Right now, we don't have an active secondary, no. Due to technical issues we had to take them offline temporary. We won't be able to add them back in until this issue is fixed.

We don't know precisely when it started happening. We had a script that emptied these collections and puts it on another server. The issue was only visible when the script had finished and we noticed that there was still data left on replSetB which we could not query in the usual way. The replicaset secondaries were removed somewhere at the same time.

Repairs happened on several occasions to make some diskspace.

/Koen

Comment by Eliot Horowitz (Inactive) [ 27/Nov/11 ]

You have a secondary for each shard though, right?

When did this error start happening?

Was there ever a repair()?

Sorry for all the questions - just hard to understand exactly what's going on.

Comment by Koen Calliauw [ 26/Nov/11 ]

Hi Eliot,

The bets and log_service were sharded at the same time if I remember correctly. Every shard is a replica set. As mentioned previously every replica set only has a primary and an arbiter for the time being. This isn't an issue I suppose? We only implemented the replicasets for redundancy, for now, we never queried with the option to prefer slaves.

Besides the technical issues (diskspace) we had no previous issues with the replicasets.
The only issue we had previously with this setup was a bug in Shanty (a mongodb adaptor for Zend Framework). We've worked around this issue by adapting our code (not using the export() function of Shanty). The issue here was that cursors didn't get closed correctly and the mongos processes grew bigger and bigger in resident memory size during times of high load.

/Koen

Comment by Eliot Horowitz (Inactive) [ 26/Nov/11 ]

When did you shard bets and log_service?

What about the replica sets?

Any issues on those recently?

Comment by Koen Calliauw [ 26/Nov/11 ]

Hi,

The db.stats() printout of the primaries of the 3 shards can be found here:

http://pastie.org/private/ketwnaca5ufrar3mwlfq

A bit of history, well, we've been running this sharded setup for about 3 months in production now, give or take a few days, but due to disk space constraints we had to turn logappend off, so unfortunately I don't have logs going back further than yesterday
Before the sharded production setup we ran the same code (php) on a single mongodb node for another 2 months (estimate again). So basically sharding has been added on the collections from day 1 in this setup. Before that, it was on a totally different server.
Basically every server fulfills 4 roles:

  • primary of shard x
  • secondary of shard y
  • arbiter of shard z
  • config server

We chose this type of config on this setup because we are quite restrained on budget and resources. This is running on a hosted environment based on KVM virtualization without overcommitment of cpu or memory.

If you need more history, can you please be a bit more specific on what you mean by that? I'll gladly provide you with any and all information I can give you.

/Koen

Comment by Eliot Horowitz (Inactive) [ 26/Nov/11 ]

Can you run db.stats() on each of the shards?

Can you explain a bit more of the history.

When did you add sharding for example.

Do you have the logs going back that far?

Comment by Koen Calliauw [ 26/Nov/11 ]

Yesterday we rebooted the app servers and all mongo servers for some hardware changes. All stayed the same afterward. Still cannot query data from that collection.

Comment by Koen Calliauw [ 23/Nov/11 ]

mongod logs from replSet primaries
mongos log

Comment by Koen Calliauw [ 23/Nov/11 ]

From the mailinglist:

Everything (all mongos and mongod's) is running 2.0.1.
Here are the explain()s for the failing query against the shards, but please note that only the second shard (replSetB) has data in it.

Primary of replSetA: http://pastie.org/2907612
Primary of replSetB: http://pastie.org/2907616
Primary of replSetC: http://pastie.org/2907620

  • I don't know why the chunks are still there on replSetA and replSetC (as seen in printShardingStatus()). I assumed this was normal and that on deletes these chunks stayed there as preallocation for future data. Also, when I mentioned replSetA (and replSetC) were empty, I meant that there are no documents in the collection in question (log_service).
  • I'll attach the requested logs to the issue.
Comment by Spencer Brody (Inactive) [ 22/Nov/11 ]

You said that replSetB is the shard with the data, and you also mentioned that replSetA is empty. What do you mean by that? The output of printShardingStatus() shows many chunks living on replSetA.

Can you also attach the full mongos log as well as the full logs from the primaries of all 3 replSets? Log files generally compress very well, so if you zip/tar the files they should be quite small and can be attached to this ticket no problem.

Comment by Koen Calliauw [ 22/Nov/11 ]

In the mongod log if the primary in shard replSetB (the one with the data) we see the queries:
Tue Nov 22 09:03:01 [conn6] query betrobot_production.log_service nscanned:138718 reslen:20 293ms

I've also noticed this warning. Don't know if it's important:
Tue Nov 22 09:03:18 [conn110] warning: bad serverID set in setShardVersion and none in info: EOO

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