[SERVER-3049] com.mongodb.MongoException: setShardVersion failed host[mongodb04.example.com:27018] { errmsg: "not master", ok: 0.0 } Created: 05/May/11 Updated: 12/Jul/16 Resolved: 12/May/11 |
|
| Status: | Closed |
| Project: | Core Server |
| Component/s: | Sharding |
| Affects Version/s: | 1.8.1 |
| Fix Version/s: | 1.8.3, 1.9.1 |
| Type: | Bug | Priority: | Major - P3 |
| Reporter: | Michael Conigliaro | Assignee: | Greg Studer |
| Resolution: | Done | Votes: | 0 |
| Labels: | failed, master, not, setShardVersion | ||
| Remaining Estimate: | 0 minutes | ||
| Time Spent: | Not Specified | ||
| Original Estimate: | 0 minutes | ||
| Environment: |
Ubuntu LInux on EC2 |
||
| Attachments: |
|
||||
| Issue Links: |
|
||||
| Operating System: | Linux | ||||
| Participants: | |||||
| Description |
|
After replica set failover, I get the following exception in my apps: com.mongodb.MongoException: setShardVersion failed host[mongodb04.example.com:27018] { errmsg: "not master", ok: 0.0 }Strangely, I do not get this message for every request. It seems to happen about 50% of the time. The other 50% of the requests succeed without errors. I have seen this go on for several minutes (e.g. 15-20). The only way I can resolve it is by failing back to the original master, or by restarting the mongos on the appserver. Reproducing this problem is very simple: 1.) Run "watch -n 1 curl -v http://example.com/something/that/queries/mongodb" on the appserver Additionally after failover, I see several messages like this in my mongos.log (on the order of 30-40 per second): Thu May 5 16:34:43 [conn78] ReplicaSetMonitor::_checkConnection: mongodb05.example.com:27018 { setName: "2", ismaster: true, secondary: false, hosts: [ "mongodb05.example.com:27018", "mongodb04.example.com:27018" ], arbiters: [ "mongodb06.example.com:27018" ], maxBsonObjectSize: 16777216, ok: 1.0 }These go away as soon as I fail back to the original master. I don't know if this is related to the same issue, so I created another ticket for this: https://jira.mongodb.org/browse/SERVER-3040 |
| Comments |
| Comment by Greg Studer [ 08/Jul/11 ] |
|
The fix for this will be in 1.8.3, and should be in the 1.8 nightlies now. |
| Comment by Raymond Lu [ 08/Jul/11 ] |
|
So has this been backported? If I downloaded mongodb from the downloads page, does it include the fix? |
| Comment by Greg Studer [ 12/May/11 ] |
|
a fix which we're backporting to 1.8.2 should solve this problem - pretty sure it's a bad combination of old random slave choice behavior with an edge case that allows duplicate replica set nodes... |
| Comment by Michael Conigliaro [ 09/May/11 ] |
|
I was finally able to fail back to the original master. Here's what that looked like. That insane amount of logging also stopped: Mon May 9 21:02:55 [conn18] ReplicaSetMonitor::_checkConnection: mongodb05.example.com:27018 { setName: "2", ismaster: true, secondary: false, hosts: [ "mongodb05.example.com:27018", "mongodb04.example.com:27018" ], arbiters: [ "mongodb06.example.com:27018" ], maxBsonObjectSize: 16777216, ok: 1.0 }_check : 2/mongodb05.example.com:27018,mongodb04.example.com:27018,mongodb04.example.com:27018 _check : 2/mongodb05.example.com:27018,mongodb04.example.com:27018,mongodb04.example.com:27018 _check : 2/mongodb05.example.com:27018,mongodb04.example.com:27018,mongodb04.example.com:27018 _check : 2/mongodb05.example.com:27018,mongodb04.example.com:27018,mongodb04.example.com:27018 _check : 2/mongodb05.example.com:27018,mongodb04.example.com:27018,mongodb04.example.com:27018 Mon May 9 21:02:55 [conn18] ReplicaSetMonitor::_checkConnection: mongodb05.example.com:27018 { setName: "2", ismaster: true, secondary: false, hosts: [ "mongodb05.example.com:27018", "mongodb04.example.com:27018" ], arbiters: [ "mongodb06.example.com:27018" ], maxBsonObjectSize: 16777216, ok: 1.0 }MessagingPort recv() errno:104 Connection reset by peer 10.120.14.79:27018 Mon May 9 21:02:55 [conn21] ReplicaSetMonitor::_checkConnection: mongodb05.example.com:27018 { setName: "2", ismaster: true, secondary: false, hosts: [ "mongodb05.example.com:27018", "mongodb04.example.com:27018" ], arbiters: [ "mongodb06.example.com:27018" ], maxBsonObjectSize: 16777216, ok: 1.0 }_check : 2/mongodb05.example.com:27018,mongodb04.example.com:27018,mongodb04.example.com:27018 Mon May 9 21:02:55 [conn21] SocketException: remote: error: 9001 socket exception [0] Mon May 9 21:02:55 [conn21] SocketException: remote: error: 9001 socket exception [0] Mon May 9 21:02:55 [conn18] _check : 2/mongodb05.example.com:27018,mongodb04.example.com:27018,mongodb04.example.com:27018 trying reconnect to mongodb04.example.com:27018 trying reconnect to mongodb04.example.com:27018 Mon May 9 21:02:56 [conn23] ReplicaSetMonitor::_checkConnection: mongodb05.example.com:27018 { setName: "2", ismaster: true, secondary: false, hosts: [ "mongodb05.example.com:27018", "mongodb04.example.com:27018" ], arbiters: [ "mongodb06.example.com:27018" ], maxBsonObjectSize: 16777216, ok: 1.0 }_check : 2/mongodb05.example.com:27018,mongodb04.example.com:27018,mongodb04.example.com:27018 checking replica set: 1 checking replica set: 2 checking replica set: 3 checking replica set: 4 Mon May 9 21:03:17 [WriteBackListener] writebacklisten result: { noop: true, ok: 1.0 }Mon May 9 21:03:18 [WriteBackListener] writebacklisten result: { noop: true, ok: 1.0 }Mon May 9 21:03:19 [WriteBackListener] writebacklisten result: { noop: true, ok: 1.0 }Mon May 9 21:03:19 [WriteBackListener] writebacklisten result: { noop: true, ok: 1.0 }Mon May 9 21:03:21 [WriteBackListener] writebacklisten result: { noop: true, ok: 1.0 } |
| Comment by Greg Studer [ 09/May/11 ] |
|
i'm investigating that duplicate now - if you have a chance, can you send additional mongos logs for the period before and after that duplicate host is added? |
| Comment by Michael Conigliaro [ 09/May/11 ] |
|
No chunks should have migrated. I actually have that disabled at the moment, since we experienced performance problems with it in the past. I've actually never noticed that duplicate host in there. When I look back in the logs, the only time I see that message with the duplicate host is immediately after a failover. I just restarted the mongos on one machine, and the message looked like this instead: Mon May 9 20:33:18 [conn1] _check : 2/mongodb05.example.com:27018,mongodb04.example.com:27018 |
| Comment by Greg Studer [ 09/May/11 ] |
|
has a chunk recently migrated to/from that rs? There's an issue where processing a migration (all at once) can put a lot of load on the slave. Also, this line of your mongos logs - |
| Comment by Michael Conigliaro [ 09/May/11 ] |
|
Additionally, I see that the replica set slave delay is slowly climbing (1688 seconds and counting), so I can't fail back to the original master, because it's too far behind. There are no errors in the mongodb.log on either the master or slave. Here's en example of what I'm looking at. Everything seems normal to me. Mon May 9 19:48:22 [dur] lsn set 213147014 reslen:60 300006ms reslen:60 300008ms reslen:60 300005ms reslen:60 300008ms reslen:60 300006ms reslen:60 300003ms reslen:60 300006ms reslen:60 300005ms reslen:60 300005ms reslen:60 300004ms reslen:60 300007ms reslen:60 300005ms EDIT: I take it back. There are some errors in the slave about a cusror now. I've seen these before, but I don't know if they mean anything: Mon May 9 19:50:37 [replica set sync] example.userEventsJournal warning: cursor loc null does not match byLoc position a:711ba56c ! reslen:1643 101ms EDIT: Just for the record, here's the output of rs.status(). Nothing wrong there that I can see... 2:PRIMARY> rs.status() , , , EDIT: Shard status looks OK to me too... > db.printShardingStatus() shards: example.stats chunks: } -->> { "userId" : "000009a6-02e5-4277-90a3-fb38264440f9" }on : 4 { "t" : 7000, "i" : 0 }{ "userId" : "000009a6-02e5-4277-90a3-fb38264440f9" } -->> { "userId" : "3295759f-14d4-46b3-bcac-22e6b8c35400" }on : 2 { "t" : 8000, "i" : 2 }{ "userId" : "3295759f-14d4-46b3-bcac-22e6b8c35400" } -->> { "userId" : "651a8cb3-7df8-43bf-bbee-6c58a1f88b28" }on : 2 { "t" : 8000, "i" : 4 }{ "userId" : "651a8cb3-7df8-43bf-bbee-6c58a1f88b28" } -->> { "userId" : "97cf4d36-c30d-4888-bd26-6a3ef8dcb662" }on : 2 { "t" : 8000, "i" : 6 }{ "userId" : "97cf4d36-c30d-4888-bd26-6a3ef8dcb662" } -->> { "userId" : "ca921ed8-67bb-44e7-a802-8c48a8ae8c8d" }on : 2 { "t" : 8000, "i" : 8 }{ "userId" : "ca921ed8-67bb-44e7-a802-8c48a8ae8c8d" } -->> { "userId" : "testuser2" }on : 2 { "t" : 8000, "i" : 9 }{ "userId" : "testuser2" } -->> { "userId" : { $maxKey : 1 }} on : 4 { "t" : 8000, "i" : 0 } { "_id" : "local", "partitioned" : false, "primary" : "2" }EDIT: Looks like I'm IO-bound on the slave, so that would explain why it can't catch up. Though I have no idea what the slave is doing to cause all that IO... Device: rrqm/s wrqm/s r/s w/s rsec/s wsec/s avgrq-sz avgqu-sz await svctm %util |
| Comment by Michael Conigliaro [ 09/May/11 ] |
|
This is appearing in some of my other logs. That little piece of a stack trace looks scary: Mon May 9 19:24:21 [conn22] going to retry checkShardVersion Mon May 9 19:24:21 [conn22] setShardVersion 2 mongodb04.example.com:27018 example.userfile { setShardVersion: "example.userfile", configdb: "mongodb-config03.example.com:27019,mongodb-config02.example.co...", version: Timestamp 8000|9, serverID: ObjectId('4dc46ef31dc02d61ad0bcce3'), authoritative: true, shard: "2", shardHost: "2/mongodb05.example.com:27018,mongodb04.example.com:27018" } 0x7fbfa0002750 Mon May 9 19:24:21 [conn22] setShardVersion failed host[mongodb04.example.com:27018] { errmsg: "not master", ok: 0.0 }Mon May 9 19:24:21 [conn22] Assertion: 10429:setShardVersion failed host[mongodb04.example.com:27018] { errmsg: "not master", ok: 0.0 }0x51fc59 0x69ca53 0x69c5e2 |
| Comment by Michael Conigliaro [ 09/May/11 ] |
|
OK, I reproduced the problem. The log file is ridiculous due to this problem: https://jira.mongodb.org/browse/SERVER-3040 |
| Comment by Greg Studer [ 06/May/11 ] |
|
been there |
| Comment by Michael Conigliaro [ 06/May/11 ] |
|
And of course, now I can't reproduce the problem, even though I could reproduce it easily yesterday afternoon. The only thing that's changed is that I truncated all the mongos logs before restarting all the mongos processes. I wonder if they need to be running for a long time before I can get them stuck in that state. Anyway, I'll keep trying... |
| Comment by Michael Conigliaro [ 06/May/11 ] |
|
Yes, this is a web app with a RESTful interface that communicates with a local mongos instance that points to 4 replica set shards. We're using a Sinatra-like framework called BlueEyes for Scala which was actually developed in-house, so there may be issues with the way we're using the MongoDB driver (I know I've found some issues with what they were doing in the past). Here's a link to the source for reference: https://github.com/jdegoes/blueeyes/tree/master/src/main/scala/blueeyes/persistence/mongo I'll try reproducing this again with more log output... |
| Comment by Greg Studer [ 06/May/11 ] |
|
can't reproduce here, it would be really helpful to see the full logs from the time period slightly before you stepDown() until you run the second stepDown() to restore the master. also, is your app doing writes or reads to the db, and is slaveOk set? I assume your setup is an app connected to a mongos instance with replica set shards... |