WriteConcern detected an error E11000 duplicate key error index

[RobIII]

I have a .Net WCF service which acts as an interface between our software and MongoDB using MongoRepository. Since I have updated to the 1.7.0 driver version I get an "WriteConcern detected an error E11000 duplicate key error index..." error when I call the Save method on documents that, indeed, have a unique index.

Let me give you the full story: first, my object (in simplified form, PHP notation):

object(NIDEntry)#40 (12) {

  ["Id"]=>

  string(24) "5069e318ce93af04d8aa582e"

  ["Name"]=>

  string(3) "Foo"

  ["AssociatedNumbers"]=>

  array(1) {

    [0]=>

    object(NIDPhoneNumber)#51 (6) {

      ["CountryCode"]=>

      string(4) "0031"

      ["AreaCode"]=>

      string(4) "0987"

      ["SubscriberNumber"]=>

      string(6) "123456"

      ["PublishType"]=>

      string(1) "p"

      ["NumberType"]=>

      string(1) "p"

      ["NIDStatus"]=>

      NULL

    }

  }

  ["CreateDate"]=>

  string(24) "2012-10-01T18:38:16.171Z"

}

These documents are stored in an NIDEntries collection. This collection has 2 indexes; one for _id (obviously) and one for CountryCode + AreaCode + SubscriberNumber. I have checked, double-checked and triple-checked that this is the only document containing this number (0031 0987 123456). Next, I simply fetch the object using the FindOneByIdAs<NIDEntry>() method. Then I change, for example, only the name ("Foo" => "FooTest") and issue a .Save(). This results in the "WriteConcern detected an error E11000 duplicate key error index NID.NIDEntry.$AssociatedNumbers.SubscriberNumber_1_AssociatedNumbers.AreaCode_1_AssociatedNumbers.CountryCode_1 dup key: { : "123456", : "0987", : "0031" }" exception.

Now here's the thing: 

We have a DTAP environment; all 4 have their own copy of the WCF service. D and T connect to (say) mongo-A (2.2.0) to a database (say) NID_D or NID_T. The A and P servers also run the WCF service; both connecting to mongo-B (2.2.0) to a database (say) NID_A and NID_P. I have illustrated this in the diagram below (fear my paint skills):

Remember that each server/service connects to it's own database (NID_D, NID_T, NID_A, NID_P respectively) which is not in the diagram. I have checked, double checked and triple checked that all servers are running the same WCF service version. Each of them is using the 1.7 version of the mongocsharpdriver. Calling the .Save() method on D, T, and A work fine for updating. Calling the .Save() method on P fails with the exception.

I have ruled out the following:

• It can't be the mongo server; as both A and B are 2.2.0 (on linux) and D, T and A are fine updating existing documents, P is not.
• It can't be the mongocsharp driver, as D, T and A are fine updating existing documents, P is not.
• There's no difference, except for names, IP's and database names, in the connectionstrings for each of the DTAP servers.
• The document is the only document containing the unique (combination of) field(s) value(s). I am doing an "update" using the .Save() method (which is abstracted to .Update() by the MongoRepository).
• The E11000 exception would be explained when doing an insert of a new document; however: there's no insert being done but an update (upsert if you will).

I have rolled back the P server to the previous version which relies on MongoRepository 1.4.0 which relies on the 1.6.1 driver (and safe=true in the connectionstring). The service is then fine with updating the document. When rolling out the new version of the service (which has no functional changes at all except for the dependency on MongoRepository 1.4.1 which, in turn, relies on the 1.7 driver) the P server fails. The changes in 1.4.1 are minimal. What I can't explain is why this works fine on D, T and A but not P. The services are "deployed" using the "XCopy deployment" style; it's just a simple directory containing an .exe, and some DLL's. The WCF services, by the way, are self hosted (not in IIS) and run as Windows service.

In an act of insanity I have run the new version of the WCF service locally on my development machine which I'm sure is running the v1.7 driver and let it connect to "mongo-B" to the NID_P database. Next, I retrieved the document, updated the "name" property and issued the same .Save(). Lo and behold: This works fine!?!? So the problem isn't caused by (say) a "confused mongodb" server or "damaged collection"-file or something. Would this have caused the same exception one of these things might be the case but it turns out it isn't.

There are 2 things I haven't done (yet) to rule stuff out:

1. There's another (XCopy deployed) service running using the 1.6.1 driver on only the P server (not on the other three). However:
• a) this shouldn't interfere (why would windows use the 1.6.1 driver from the other service's directory for example?)
• b) I have stopped this service to rule out that somehow things were getting their wires crossed (this did not help)
• c) why is it that 1.6.1 or 1.7 run fine on D, T and A then?
  
2. Rebooting the server
   

My question is: what could be causing this? What would be a good way to troubleshoot / debug this problem? Any help is appreciated.

[RobIII]

I realize this should've gone to the mongodb-csharp group. My apologies.

[Robert Stam]

It's fine to post this question to mongodb-user. The mongodb-user group is for all drivers. Since you started the discussion on mongodb-user let's continue it here.

Can you provide a stack trace? You mention you are using MongoRepository, but do you know which driver method is ultimately being called? Insert, Save or Update? The stack trace would determine that. It would also be useful to know the values of the parameters passed to the driver's Insert, Save or Update method being called.

You can also turn up the logging level on the server a bit (use mongod -v) and it will log some information about the failed operations.

Are you sure the indexes were created the same way on all mongod servers? In particular, are they all unique indexes? Use getIndexes in the mongo shell to verify.

--
You received this message because you are subscribed to the Google
Groups "mongodb-user" group.
To post to this group, send email to mongod...@googlegroups.com
To unsubscribe from this group, send email to
mongodb-user...@googlegroups.com
See also the IRC channel -- freenode.net#mongodb

[RobIII]

MongoRepository calls the .Save() method (as linked in my original post in the 4th bullet point).

The indexes were created the same on all servers (the WCF project creates these at startup using EnsureIndex(<something>), I have dropped these on several servers (including P) several times hoping it would be something like that but no luck. I'll try the shell to find out if something went awry there maybe.

For the rest I'll get back to you tomorrow when I'm at work and I'll post stacktraces/logs. Thanks for the swift reply so far!

[RobIII]

The indexes are identical:

NID_A:

> db.NIDEntry.getIndexes();

[

        {

                "v" : 1,

                "key" : {

                        "_id" : 1

                },

                "ns" : "NID_A.NIDEntry",

                "name" : "_id_"

        },

        {

                "v" : 1,

                "key" : {

                        "AssociatedNumbers.SubscriberNumber" : 1,

                        "AssociatedNumbers.AreaCode" : 1,

                        "AssociatedNumbers.CountryCode" : 1

                },

                "unique" : true,

                "ns" : "NID_A.NIDEntry",

                "name" : "AssociatedNumbers.SubscriberNumber_1_AssociatedNumbers.AreaCode_1_AssociatedNumbers.CountryCode_1",

                "sparse" : true

        }

]

NID_P:

> db.NIDEntry.getIndexes();

[

        {

                "v" : 1,

                "key" : {

                        "_id" : 1

                },

                "ns" : "NID_P.NIDEntry",

                "name" : "_id_"

        },

        {

                "v" : 1,

                "key" : {

                        "AssociatedNumbers.SubscriberNumber" : 1,

                        "AssociatedNumbers.AreaCode" : 1,

                        "AssociatedNumbers.CountryCode" : 1

                },

                "unique" : true,

                "ns" : "NID_P.NIDEntry",

                "name" : "AssociatedNumbers.SubscriberNumber_1_AssociatedNumbers.AreaCode_1_AssociatedNumbers.CountryCode_1",

                "sparse" : true

        }

]

This is the stacktrace:

WriteConcern detected an error 'E11000 duplicate key error index: NID_P.NIDEntry.$AssociatedNumbers.SubscriberNumber_1_AssociatedNumbers.AreaCode_1_AssociatedNumbers.CountryCode_1  dup key: { : "123456", : "0987", : "0031" }'. (Response was { "err" : "E11000 duplicate key error index: NID_P.NIDEntry.$AssociatedNumbers.SubscriberNumber_1_AssociatedNumbers.AreaCode_1_AssociatedNumbers.CountryCode_1  dup key: { : \"123456\", : \"0987\", : \"0031\" }", "code" : 11000, "n" : 0, "connectionId" : 604922, "ok" : 1.0 }).

   at MongoDB.Driver.Internal.MongoConnection.SendMessage(MongoRequestMessage message, WriteConcern writeConcern, String databaseName)

   at MongoDB.Driver.MongoCollection.InsertBatch(Type nominalType, IEnumerable documents, MongoInsertOptions options)

   at MongoDB.Driver.MongoCollection.Insert(Type nominalType, Object document, MongoInsertOptions options)

   at MongoDB.Driver.MongoCollection.Save(Type nominalType, Object document, MongoInsertOptions options)

   at CompanyName.NIDRepository.NIDEntryRepository.Update(NIDEntry entry)

   at NIDWCF.NIDWCFService.Update(NIDEntry nidentry) in d:\<fakepath>\NIDWCF\NIDWCFService.cs:line 37

Which is funny, because now I notice .Save() calling .Insert() which, I guess, should have been an .Update() call?. Now, to figure out why it is determined by .Save() to call .Insert() instead of .Update(). Maybe idProvider.GetDocumentId() somehow fails to retrieve the document-Id? Would you happen to know of any changes in 1.6.1 to 1.7 that would've impacted this?

I would like to do a little more debugging but because this problem only exists in the production server and this server is, d'uh, in production that kinda limits my options. I will, later today, start mongo with the -v argument to see if I can find out more but I'm more and more convinced the problem lies in either the driver or the WCF service and/or MongoRepository; if the mongo-server were the problem the problem would (probably) also exist using the 1.6.1 driver. Then, leaving the WCF service, MongoRepository and the driver; which one is it? The WCF service hasn't changed other than referencing the new MongoRepository; MongoRepository hasn't changed much either (updated to v1.7 driver and using MongoClient instead of MongoServer, see relevant diff). But, since this bug doesn't exist in D, T and A I don't know why it would fail in P. And finally: I am quite sure the driver isn't the problem either (since I highly regard R. Stam :-) ). So I'll have to do some more digging. Results will be posted as soon as I have them.

Again, thanks for thinking along with me.

Rob

[RobIII]

OMG. O-effin'-EM-GEE...

Turns out: a while ago we dropped the Dreamsongs part of the Dreamsongs.MongoRepository namespace. Long story short: it turns out that D, T and A all had stale WSDL caches so when the new version was rolled out the WCF service/MongoRepository could determine the object's ID without a problem. The P environment, being in use all the time, had a recent WSDL cache which, referred to DreamSongs.MonoRepository in some places. This cause the ID not being received correctly by the WCF service, which caused the MongoRepository/MongoDb C-Sharp Driver to execute an insert instead of an update (which explains the E11000 duplicate key).

So; lesson learned: a changed namespace can cause duplicate keys :P (Next time I'll be sure to clear WSDl caches....).

Solved; PEBKAC. My bad and sorry for the inconveinience.

Rob

[Robert Stam]

Glad to hear you figured it out. Thanks for letting us know.