[SERVER-22971] Operations on some sharded collections fail with bogus error Created: 04/Mar/16 Updated: 21/Apr/16 Resolved: 21/Apr/16 |
|
| Status: | Closed |
| Project: | Core Server |
| Component/s: | Sharding |
| Affects Version/s: | 3.2.3 |
| Fix Version/s: | None |
| Type: | Bug | Priority: | Major - P3 |
| Reporter: | Robert Bandl | Assignee: | Kaloian Manassiev |
| Resolution: | Duplicate | Votes: | 0 |
| Labels: | None | ||
| Remaining Estimate: | Not Specified | ||
| Time Spent: | Not Specified | ||
| Original Estimate: | Not Specified | ||
| Issue Links: |
|
||||||||||||||||||||
| Operating System: | ALL | ||||||||||||||||||||
| Sprint: | Sharding 12 (04/01/16), Sharding 13 (04/22/16) | ||||||||||||||||||||
| Participants: | |||||||||||||||||||||
| Description |
|
We have a 3 member config replica set rs0 + data replica sets rs1 rs2.
To summarize, 'aggregate' works with any match criteria and operations and yields accurate results (best I can tell), 'find' works only with some criteria.
Only error I can see in log is on startup
but also says afterwards
Obviously "None of the hosts for replica set rs0 could be contacted." error message is nonsense and this is not a connectivity issue, but rather something else. Please advise on how to debug this issue. |
| Comments |
| Comment by Kaloian Manassiev [ 21/Apr/16 ] | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Hi cikovd, Thank you again for reporting this issue and for your patience while we investigate. Based on our investigation, there are two things we can improve here in order to prevent this problem from happening in the future and I have filed tickets for both. The first (and larger) problem is described in The second problem is described in I am going to resolve this ticket and link it to these two tickets, which you can monitor for progress. Again, thank you for reporting this problem. Best regards, | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Robert Bandl [ 10/Mar/16 ] | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Well resulting output is all
at 30 second intervals for a week. No other messages. It seems that there was a connectivity issue between the shard and config server unrelated to mongod which we didn't notice because mongoses had no problem connecting to shards and configs from their hosts. It's all good now I guess, I suppose you can close this ticket and just make sure logged errors indicate which host is having a problem and why (instead of having it say on all nodes 'None of the hosts for replica set rs0 could be contacted.' when error is actually that log file disk on one of the shards is full). | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Kaloian Manassiev [ 10/Mar/16 ] | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Thanks Robert. The presence of this many locks, which need to be released indicates that there is some task, which is continuously trying to acquire a lock and fails for some reason so the list of locks to be freed keeps growing. Would it be possible that you grep the mongos log for any lines which contain one of these lock ids and attach the output? For example:
I feel that we can do a better job of not trying to unlock locks, which we know that we definitely not acquired in the first place. This will significantly reduce the size of the list that we need to print. Thank you very much in advance for your help and patience while we get to the bottom of this. Best regards, | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Robert Bandl [ 10/Mar/16 ] | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Message you referred to as being written to log every 30 seconds is 'pinging failed' message as seen below. You need to throttle the 'Failed to unlock lock' message.
| |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Robert Bandl [ 10/Mar/16 ] | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Hi, as you can see in tiny snippet below 'failed to unlock' message was definately not being written at most once every 30 seconds:
A couple of per millisecond warning counts:
| |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Kaloian Manassiev [ 10/Mar/16 ] | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Hi cikovd, The "failed to unlock" warning message should be printed at most once every 30 seconds for a very small number of locks and at this frequency it is unlikely to cause the disk drive to get full. We could certainly make it print less like you suggested, but is it possible that your disk got full for an unrelated reason? Would it be possible to attach a snippet of the log which includes timestamps and which shows this message getting printed more frequently? Best regards, | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Andy Schwerin [ 08/Mar/16 ] | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
This particular suggestion is a duplicate of SERVER-9552. Feel free to vote, watch and comment there. I believe kaloian.manassiev is going to respond to your other suggestions under separate cover. Thanks for the report and suggestions. | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Robert Bandl [ 04/Mar/16 ] | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Found the problem. Issue is seems to be resolved after telling primary on rs1 to step down, primary disk drive is full (not data drive, data is on other drive). mongod has flooded the log which is on primary drive with a gazzilion messages like
It has been writing more than thousands of messages per second to log with incrementing ts I guess at some point it had a problem connecting and disk got filled up now. I was sure problem is between mongos and config servers due to misleading error message given by mongos. and I should improve platform monitoring Thanks for your efforts in resolving this problem. | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Robert Bandl [ 04/Mar/16 ] | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Found something very interesting, this is partial sh.status() on mongos.
Every find with criteria on '_id.u' I tried that resolves to chunk on rs2 works. So:
| |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Robert Bandl [ 04/Mar/16 ] | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Thats correct. rs0 is config server's replica set, rs1 and rs2 are shard replica sets. All of the mongos instances are having the same problem - here's a log from freshly restarted mongos - only ran db.zzz.find() on db 'squid' after restart which errored with "None of the hosts for replica set rs0 could be contacted." (test collection I created earlier as described above).
| |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Kaloian Manassiev [ 04/Mar/16 ] | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Apologies for misreading your original description. Just to make sure I understand correctly - rs0 is your config server's replica set, not one of the shards, correct? Would it be possible to attach the logs from the mongos instance, which is having these problems? I want to search for any messages from the the component which monitors the replica sets. Thank you for your patience while we investigate this problem. Best regards, | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Robert Bandl [ 04/Mar/16 ] | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
As I said - I upgraded mongos and all config nodes from 3.2.1 to 3.2.3 after first encountering the problem to see if that resolves the issue - that process restarted all of those instances. I also tried flushRouterConfig command now - still same results with above examples. | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Kaloian Manassiev [ 04/Mar/16 ] | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Hi Robert, The error which you are seeing indicates that none of the hosts for the replica set named 'rs0' (which stores the key PLXYOAOBYD) was unavailable for some time and the mongos instance gave up on monitoring it. Does this sound in line with what might have happened in the past? That being said, my hypothesis is that the aggregation pipeline is more aggressive in contacting potentially failed hosts than the find command (different code path) and that's why it succeeds. While we investigate further, would it be possible that you run the 'flushRouterConfig' command and see if your find operations work? This is how to run the command:
If this doesn't work, would it be possible that you restart the mongos instance and see if this gets the find command to work? Best regards, |