[SERVER-3031] Replication fails with "objects in a capped ns cannot grow" Created: 02/May/11 Updated: 12/Jul/16 Resolved: 05/May/11 |
|
| Status: | Closed |
| Project: | Core Server |
| Component/s: | Replication |
| Affects Version/s: | 1.8.1 |
| Fix Version/s: | 1.9.1 |
| Type: | Bug | Priority: | Major - P3 |
| Reporter: | Tejaswi Nadahalli | Assignee: | Kristina Chodorow (Inactive) |
| Resolution: | Done | Votes: | 0 |
| Labels: | None | ||
| Remaining Estimate: | Not Specified | ||
| Time Spent: | Not Specified | ||
| Original Estimate: | Not Specified | ||
| Environment: |
Linux Kernel 2.6.32-309-ec2, x86_64, EC2 m2.2xlarge with Raid0 created using mdadm on EBS volumes of 1TB each. |
||
| Operating System: | Linux |
| Participants: |
| Description |
|
I have two secondaries, both of which stopped replication at around the same time with the following messages: ---------------------------------------------------------------------------------------------------------------------------------------------- Mon May 2 02:11:02 [replica set sync] replSet syncThread: 10003 failing update: objects in a capped ns cannot grow I didn't have any alerts setup on these, and this caused the replicas to go stale and I am now getting them back up with a full resync, etc. I use a lot of capped collections in my code, but I don't update any of them in place. This looks like a MongoDB oplog capped collection issue. Any help would be appreciated. |
| Comments |
| Comment by Eliot Horowitz (Inactive) [ 30/May/11 ] |
|
drop collection |
| Comment by Tejaswi Nadahalli [ 30/May/11 ] |
|
Can you elaborate on that? 2 - Drop == drop collection? drop DB? drop Indexes? And why are are mongodump and mongorestore processes required? -T |
| Comment by Eliot Horowitz (Inactive) [ 30/May/11 ] |
|
Dropping and re-creating is best.
|
| Comment by Tejaswi Nadahalli [ 30/May/11 ] |
|
Well, the problem is _id indexes, if they exist, cannot be dropped. Is there a way to convert each _id index in the capped collection to be Unique? Or is my only option to delete all capped collections and re-create them with a unique _id index? -T |
| Comment by Eliot Horowitz (Inactive) [ 30/May/11 ] |
|
You need to make the _id index unique on the master capped collection. |
| Comment by Tejaswi Nadahalli [ 29/May/11 ] |
|
Replication stopped again for me in production. I have indexes on _id on ALL my tables. It's still stopping replication with the same bug. Is it possible that the bug has something to do with the oplog capped collection and not my own DB capped collections? This is getting to a point now that having replica sets is completely useless. I sync from scratch every 3 days or so. -T |
| Comment by Tejaswi Nadahalli [ 26/May/11 ] |
|
You can see that the unique index could be subsumed by the search index. Below, I am creating indexes on two separate capped collections. One has unique:true, and the other doesn't. But showIndexes doesn't distinguish between them. ) , test_mongo:PRIMARY> db.coll_4.ensureIndex({_id:1}) , -T |
| Comment by Kristina Chodorow (Inactive) [ 26/May/11 ] |
|
Creating an index builds a tree of values for a given key, so that you can find a value (or range of values) in ~O(log MongoDB automatically creates a unique _id index on non-capped collections, but does not for capped ones. |
| Comment by Tejaswi Nadahalli [ 26/May/11 ] |
|
No, my question was slightly different. What's the difference between a unique index and a regular vanilla index on the _id key with no other fields involved? As in, what's the difference between db.collection.ensureIndex({_id:1}, {unique=true}) and db.collection.ensureIndex({_id:1}})? -T |
| Comment by Kristina Chodorow (Inactive) [ 26/May/11 ] |
|
If you have a unique index on _id, the script you gave above (to reproduce the replication halt) won't work. Maybe you created a non-unique _id index or something on one of your capped collections? |
| Comment by Tejaswi Nadahalli [ 25/May/11 ] |
|
Are _id indexes 'unique' by default? I am using http://pastebin.com/5EBRhZKc to figure out what tables to index. Every collection in my database has an _id index. What gives? -T |
| Comment by Tejaswi Nadahalli [ 25/May/11 ] |
|
Ok. Thanks for the input. Let me see if I can create these indexes on all my capped collections on the primary, replicate from scratch, and see if it works. -T |
| Comment by Kristina Chodorow (Inactive) [ 25/May/11 ] |
|
The problem is that, if you're going to use _id in a capped collection, you need to create a unique index on the _id field (because it isn't done automatically for you with capped collections). I'll add some documentation about it, but this is a weird "works as intended" edge case. |
| Comment by Kristina Chodorow (Inactive) [ 25/May/11 ] |
|
Perfect, thanks! I'll let you know. |
| Comment by Tejaswi Nadahalli [ 25/May/11 ] |
|
Ok. Done with simulation. Here're the required steps: mongod --dbpath 1 --logpath 1/mongodb.log --fork --replSet test_mongo --oplogSize 1000 --port 27001 mongo --port 27001 rs.initiate() Then, run this http://pastebin.com/1J78nxNv All the above code does it creates a capped collection and inserts two documents into the capped collection with the same _id, but with differing document sizes. It works in the primary because there is no default _id for capped collections in the primary. On the secondaries it fails because IIRC, the secondaries create an index on _id to aid replication. This _id doesn't allow the document in the replicated capped collection to grow. But the key thing is, this shouldn't stop replication from continuing with other documents. I have a feeling this might not be an easy fix - at least, removing the _id dependency from capped collection replication might be hard. But the second part of the bug - where replication stops happening if the first bug is encountered, might be easy to fix. Just speculating here -T |
| Comment by Kristina Chodorow (Inactive) [ 25/May/11 ] |
|
I think that something that is an insert on the primary may be being turned into an upsert in the oplog (which happens sometimes and is correct, but it looks like there's an edge case that we haven't handled). Are you MapReducing into any capped collections? |
| Comment by Tejaswi Nadahalli [ 25/May/11 ] |
|
I am still working on reproducing it in a non-production setup. Might take a while. As food for thought though, even if there is some code that is causing a capped collection object to increase in size on the primary, that should not stop replication to the secondaries, right? Wouldn't just that behaviour be a good starting point to investigate this? I am just thinking out loud here Will get a reproducable setup though. -T |
| Comment by Tejaswi Nadahalli [ 23/May/11 ] |
|
I have a hunch on how I can locally replicate the setup that reproduces the bug. Will try to do that. -T |
| Comment by Kristina Chodorow (Inactive) [ 23/May/11 ] |
|
A copy of the oplog.rs document that's causing the issue would probably allow me to solve it. When this happens, can you connect to the secondary (that has stopped replicating) and run: > use local ).limit(1).next() Then connect to the primary and find a document greater than the last one on the secondary? I think this should do it: > use local Or if you know the code that is doing this, send exactly what it is sending to the db? |
| Comment by Tejaswi Nadahalli [ 23/May/11 ] |
|
This bug is driving me crazy Anyway, happened again with this logged in the primary: Sun May 22 13:51:13 [conn36600] query admin.$cmd ntoreturn:1 command: { serverStatus: 1 } reslen:1250 126ms The secondary logged this: Sun May 22 02:20:41 [FileAllocator] done allocating datafile /raiddrive/master/stream_db_p.143, size: 2047MB, took 0.023 secs Sun May 22 13:51:25 [replica set sync] replSet syncThread: 10003 failing update: objects in a capped ns cannot grow I am still not on the 1.9 series to get the debug messages that you added. I can do that if you think it'll definitely help. Also, Skot and I did some analysis the other day, and I did notice that there was some application code that was inadvertently increasing the size of an object in a capped collection. This was due to duplication in _id creation. (I don't use _id in my own code, and rely on the default creation to just work). Is it possible that I am being hit by 2 bugs here - one to do with _id creation and how sometimes duplicates get created during inserts to capped collections and two - that when this error happens, slaves stop replication. Any help would be appreciated. -T |
| Comment by Kristina Chodorow (Inactive) [ 09/May/11 ] |
|
That would be great (or if you can reproduce). |
| Comment by Tejaswi Nadahalli [ 09/May/11 ] |
|
Same bug strikes again. Both my stales have gone stale because of the oplog error. My master has only 6 or so hours of oplog and that got overwritten. I will try to set alerts so that if this happens again, I can look at the master oplog immediately. |
| Comment by auto [ 03/May/11 ] |
|
Author: {u'login': u'kchodorow', u'name': u'Kristina', u'email': u'kristina@10gen.com'}Message: more debugging info on sync errors |
| Comment by Kristina Chodorow (Inactive) [ 03/May/11 ] |
|
Hmm, I don't think so. It seems like there was a bad operation in the oplog, but it'll be gone now. I'm going to add some better logging so that this is easier to debug in the future. |
| Comment by Tejaswi Nadahalli [ 03/May/11 ] |
|
No, that would have rolled over db.oplog.rs.find({}, {"ts":1}).sort({$natural:-1}).limit(1) } db.oplog.rs.find({}, {"ts":1}).sort({$natural:1}).limit(1) } I have around 6 hours worth primary's oplog, and as it rolled over, my secondaries went stale, I guess. I will be increasing the oplog size to around 2-3 days in the near future, fwiw Is there anything else I can do? |
| Comment by Kristina Chodorow (Inactive) [ 03/May/11 ] |
|
No, the primary's oplog: local.oplog.rs (if you have a backup or it hasn't rolled over). |
| Comment by Tejaswi Nadahalli [ 03/May/11 ] |
|
The Primary Log at the relevant point is: -------------------------------------------------------------------------------------------------------------- } bytes:4194710 nreturned:10690 4517ms } bytes:4194659 nreturned:8256 3660ms reslen:1237 163ms reslen:1237 231ms reslen:1237 759ms reslen:1237 656ms reslen:1237 103ms } nreturned:101 445ms } nreturned:101 869ms |
| Comment by Kristina Chodorow (Inactive) [ 03/May/11 ] |
|
No thanks, I'm interested in what operation the secondaries got stuck at (which would be in the primary's oplog). If you have a copy of the primary's oplog from when 10003 started appearing, that would be very helpful. |
| Comment by Tejaswi Nadahalli [ 03/May/11 ] |
|
I cannot send that right now, as I have restarted both my stale secondaries and they are back syncing from the primary. But I did check it multiple times back when they had gone stale, and both the secondaries had the rs102 "Too stale to catch up" error. I have the server log and data from both the secondaries though, in a separate backup, in case you want to look at them, or want me to run some queries on them. |
| Comment by Kristina Chodorow (Inactive) [ 02/May/11 ] |
|
Can you sent the output of running rs.status() on the primary? |