[SERVER-13861] Mongo crashes on duplicates when there are no any Created: 07/May/14  Updated: 10/Dec/14  Resolved: 20/May/14

Status: Closed
Project: Core Server
Component/s: Replication
Affects Version/s: 2.6.0
Fix Version/s: None

Type: Bug Priority: Critical - P2
Reporter: Moshe Shperling Assignee: Thomas Rueckstiess
Resolution: Cannot Reproduce Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Operating System: ALL
Participants:

 Description   

Hi
we have replica set consisting of only mongo server 2.6 (we have upgraded a week ago) . we are running on windows server 2008 on virtual machine.

Recently we have noticed rather annoying issue: we have a collection called items_full which has a unique index on field sku. when we run following update query:
db.items_full.update({},{$set:{'ProductInfo.ProductCA.isUpdated':false}},

{multi:true}

)

it crashes with error:
E11000 duplicate key error index: inventory.items_full.$sku_1 dup key: { : "DSSWI#Luc_W_Lp-12550-Gy-014-Gy" }

when i look for the above sku i get only 1 result.

Any ideas?



 Comments   
Comment by Moshe Shperling [ 21/May/14 ]

hi

indeed we cannot reproduce this issue with indexes, but we found another issue now that has to do with 2.6 version. where should i report it? here? or open another ticket?

thanks

Comment by Thomas Rueckstiess [ 20/May/14 ]

Hi Moshe,

Thanks for letting us know. I'll resolve the ticket now as "Cannot Reproduce", but if it happens again, feel free to re-open the ticket and provide additional information on the incident.

Regards,
Thomas

Comment by Moshe Shperling [ 12/May/14 ]

hello. here is an update on this. while we copied the collection (items_full to items_full copy) the indexes were not duplicated. therefore even though that the duplicates are there - we cannot reproduce the issue.
we have upgraded back to 2.6 and planning to upgrade to 2.6.1.

we run db.upgradeCheck() command and here is the result:
Everything in 'inventory' is ready for the upgrade!
true

we also schedulled indexes recreation in order to catch the duplicates when they appear. if/when we encounter this issue again we will update this ticket.

Comment by Thomas Rueckstiess [ 08/May/14 ]

Hi Moshe,

1. We'd like to find out if the problem is in the data or the indexes. As an experiment, can you do the following steps:

  • upgrade back to 2.6.0
  • with a 2.6.0 mongo shell, can you run the upgrade check utility and paste its output below:

    use inventory
    db.upgradeCheck()

  • then repeat the bulk update. if it fails again on a duplicate key violation, run on the mongo shell

    use inventory
    db.items_full.find({sku_upper: "<duplicate key>"}).hint({$natural: 1})

    where <duplicate key> needs to be the duplicate key value for that document that was returned in the error message. Does this return multiple documents? Can you paste the output of this find below? By scanning the collection without an index, this will determine if the documents are in fact duplicate, or if the index is reporting the same document multiple times.

2. We can see in the log file you pasted that there are "getlasterror" commands. These are deprecated with the new write commands in MongoDB 2.6 and the C# driver 1.9. Did you run the bulk update still with C# driver 1.8 (or an older php driver, as you mentioned?) Can you repeat it with the 1.9 driver?

3. To narrow it further down, can you tell us the exact operations you use to insert/upsert/update the documents? I can see the bulk update call, but are there other operations that insert or modify the data? How did the duplicate skus get generated in the first place?

4. Finally, as we are still unsuccessful in reproducing the problem so far, would you be willing to share the data of this collection with us (securely) for internal reproduction of the issue?

Regards,
Thomas

Comment by Moshe Shperling [ 08/May/14 ]

one more thing: we use php driver as well to update this collection

Comment by Moshe Shperling [ 08/May/14 ]

hi Thomas

we did some research on this and have some more information, but first here is an information you have asked:

1. here is the log:

2014-05-08T11:21:47.386+0300 [conn36516] run command inventory.$cmd { getlasterror: 1 }
2014-05-08T11:21:47.387+0300 [conn36516] command inventory.$cmd command: getLastError { getlasterror: 1 } ntoreturn:1 keyUpdates:0 numYields:0  reslen:128 0ms
2014-05-08T11:21:47.431+0300 [conn4501] User Assertion: 11000:E11000 duplicate key error index: inventory.items_full.$sku_upper  dup key: { : "DSSWI#LUC_W_LP-12550-GY-014-GY" }
2014-05-08T11:21:47.431+0300 [conn4501] User Assertion: 11000:E11000 duplicate key error index: inventory.items_full.$sku_upper  dup key: { : "DSSWI#LUC_W_LP-12550-GY-014-GY" }
2014-05-08T11:21:47.431+0300 [conn4501] IndexCatalog::indexRecord failed: 11000 E11000 duplicate key error index: inventory.items_full.$sku_upper  dup key: { : "DSSWI#LUC_W_LP-12550-GY-014-GY" }
2014-05-08T11:21:47.431+0300 [conn4501] User Assertion: 11000:E11000 duplicate key error index: inventory.items_full.$sku_upper  dup key: { : "DSSWI#LUC_W_LP-12550-GY-014-GY" }
2014-05-08T11:21:47.432+0300 [conn4501] User Assertion: 11000:E11000 duplicate key error index: inventory.items_full.$sku_upper  dup key: { : "DSSWI#LUC_W_LP-12550-GY-014-GY" }
2014-05-08T11:21:47.432+0300 [conn4501] IndexCatalog::indexRecord failed: 11000 E11000 duplicate key error index: inventory.items_full.$sku_upper  dup key: { : "DSSWI#LUC_W_LP-12550-GY-014-GY" }
2014-05-08T11:21:47.432+0300 [conn4501] update inventory.items_full query: { $or: [ { ProductInfo.ProductCA.isautopriced: "TRUE", ProductInfo.ProductCA.classification: { $in: [ "Watch Straps", "Watches" ] }, ProductInfo.ProductCA.totalpooled: { $gt: "0" } }, { ProductInfo.ProductCA.force_reprice: "TRUE" } ] } update: { $set: { ProductInfo.ProductCA.isUpdated: true } } nscanned:3599 nscannedObjects:3599 nmoved:1 nModified:1 keyUpdates:1 exception: E11000 duplicate key error index: inventory.items_full.$sku_
2014-05-08T11:21:47.432+0300 [conn4501] run command inventory.$cmd { getlasterror: 1.0, w: 1.0 }
2014-05-08T11:21:47.432+0300 [conn4501] command inventory.$cmd command: getLastError { getlasterror: 1.0, w: 1.0 } keyUpdates:0 numYields:0  reslen:212 0ms
2014-05-08T11:21:47.435+0300 [journal] journal WRITETODATAFILES 0.248ms
2014-05-08T11:21:47.747+0300 [journal] journal REMAPPRIVATEVIEW done startedAt: 56 n:36 5ms
2014-05-08T11:21:48.001+0300 [conn35457] run command admin.$cmd { ping: 1 }
2014-05-08T11:21:48.001+0300 [conn35457] command admin.$cmd command: ping { ping: 1 } ntoreturn:1 keyUpdates:0 numYields:0  reslen:37 0ms
2014-05-08T11:21:48.029+0300 [conn716] run command admin.$cmd { ping: 1.0 }
2014-05-08T11:21:48.029+0300 [conn716] command admin.$cmd command: ping { ping: 1.0 } keyUpdates:0 numYields:0  reslen:37 0ms
2014-05-08T11:21:48.095+0300 [conn36522] PageFaultException thrown
2014-05-08T11:21:48.097+0300 [conn36522] PageFaultException thrown
2014-05-08T11:21:48.097+0300 [conn36522] PageFaultException thrown

2. we have upgraded from 2.4.9.
3 there were duplicates and we created index with dropDups:true.
4 until yesterday we used 1.8 now we use 1.9.

now some more information we have found.
in 2.6 mongo version:

  • we can not make a general update to all items because of duplicates error.
  • when we look for duplicated sku it gives only 1 result

we downgraded today back to 2.4.9 and there:

  • we can run update even though there are duplicated skus
  • we can see duplicated skus

the question now is How these duplicated skus (around 20) got through unique index?
according to our check it seems like they all we created after the upgrade to 2.6.

thanks for your help. hope you come up with some idea regarding duplicates creation.

Comment by Thomas Rueckstiess [ 07/May/14 ]

Hi Moshe,

I have tried to reproduce this issue but haven't been able to so far.

To diagnose this further, we would need the log file covering the entire update process. Can you share that with us? If it contains sensitive information I can provide a way to share it securely. If this happens repeatedly (and reproducibly), could you increase the log level to 2 before the next bulk update and provide the log file afterwards?

Also some additional questions:

  1. What version did you upgrade from?
  2. When you created the index, were there duplicates that you needed to drop (hence the "dropDups" option enabled)?
  3. What version of the C# driver are you using?

Thanks,
Thomas

Comment by Moshe Shperling [ 07/May/14 ]

hi i deleted sku_1, but the same thing happens with sku_upper_1. here is an Exception print i get from c# driver writeconcern object

WriteConcern detected an error 'E11000 duplicate key error index:

inventory.items_full.$sku_upper  dup key: { : "DSSWI#LUC_W_LP-12550-GY-014-GY" }'. (Response was { "lastOp" : { "$timestamp" : NumberLong("6010707345208771083") }, "connectionId" : 6082, "err" : "E11000 duplicate key error index: inventory.items_full.$sku_upper  dup key: { : \"DSSWI#LUC_W_LP-12550-GY-014-GY\" }", "code" : 11000, "n" : 0, "ok" : 1.0 }).

when i look in the collection for this (DSSWI#LUC_W_LP-12550-GY-014-GY) item i get only 1 result

the db in general runs as usual - only updates to this collection do not work to all the items (only to 35% - then it crashes).

Comment by Michael Grundy [ 07/May/14 ]

I don't see the "sku_1" index that the insert error references. Could you post the output of db.system.indexes.find(

{name:"sku_1"}

) ?

Also, when you say crashes, is mongod also terminating with an exception, or is it just the update failing with the duplicate index error?

Thanks!

Comment by Moshe Shperling [ 07/May/14 ]

here you go

{
    "0" : {
        "v" : 1,
        "key" : {
            "_id" : 1
        },
        "ns" : "inventory.items_full",
        "name" : "_id_"
    },
    "1" : {
        "v" : 1,
        "key" : {
            "sku" : 1,
            "ProductInfo.BuyBoxInfo.asin" : 1
        },
        "ns" : "inventory.items_full",
        "name" : "sku_ProductInfo.BuyBoxInfo.asin"
    },
    "2" : {
        "v" : 1,
        "key" : {
            "sku" : 1,
            "ProductInfo_couk.BuyBoxInfo.asin" : 1
        },
        "ns" : "inventory.items_full",
        "name" : "sku_ProductInfo_couk.BuyBoxInfo.asin"
    },
    "3" : {
        "v" : 1,
        "key" : {
            "sku" : 1,
            "ProductInfo_ca.BuyBoxInfo.asin" : 1
        },
        "ns" : "inventory.items_full",
        "name" : "sku_ProductInfo_ca.BuyBoxInfo.asin"
    },
    "4" : {
        "v" : 1,
        "key" : {
            "sku" : 1,
            "ProductInfo_de.BuyBoxInfo.asin" : 1
        },
        "ns" : "inventory.items_full",
        "name" : "sku_ProductInfo_de.BuyBoxInfo.asin"
    },
    "5" : {
        "v" : 1,
        "key" : {
            "sku_upper" : 1
        },
        "unique" : true,
        "ns" : "inventory.items_full",
        "name" : "sku_upper",
        "dropDups" : true
    },
    "6" : {
        "v" : 1,
        "key" : {
            "ProductInfo.ProductCA.isautopriced" : 1,
            "ProductInfo.ProductCA.totalpooled" : 1,
            "ProductInfo.ProductCA.classification" : 1,
            "ProductInfo.ProductCA.force_reprice" : 1
        },
        "ns" : "inventory.items_full",
        "name" : "force_classification"
    },
    "7" : {
        "v" : 1,
        "key" : {
            "ProductInfo.ProductCA.isUpdated" : 1
        },
        "name" : "ProductInfo.ProductCA.isUpdated_1",
        "ns" : "inventory.items_full"
    }
}

thanks

Comment by Michael Grundy [ 07/May/14 ]

Yes, just the indexes from items_full should be fine

Comment by Moshe Shperling [ 07/May/14 ]

there are 191 indexes. it is quite large to print. maybe you need just indexes referring to the items_full collection?

Comment by Michael Grundy [ 07/May/14 ]

Hi Moshe -

Could you post the output from db.system.indexes.find() please?

Thanks!
Mike

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