[SERVER-28153] Duplicate data is sometimes inserted with unique index Created: 01/Mar/17 Updated: 18/Apr/17 Resolved: 29/Mar/17 |
|
| Status: | Closed |
| Project: | Core Server |
| Component/s: | Index Maintenance |
| Affects Version/s: | 3.2.7, 3.2.12 |
| Fix Version/s: | None |
| Type: | Bug | Priority: | Blocker - P1 |
| Reporter: | Phillip Wirth | Assignee: | Eric Milkie |
| Resolution: | Duplicate | Votes: | 1 |
| Labels: | uic | ||
| Remaining Estimate: | Not Specified | ||
| Time Spent: | Not Specified | ||
| Original Estimate: | Not Specified | ||
| Issue Links: |
|
||||||||
| Operating System: | ALL | ||||||||
| Participants: | |||||||||
| Description |
|
I do have an unique index with a partialFilterExpression on a collection but duplicate data is sometimes inserted. Index creation
The index from the getIndicies command
The duplicated Documents
MongoDb version: 3.2.7, seems also to happen with 3.2.12 - at least A Sidenote: When dumping the collection and restoring it, a duplicate key error is thrown Why is it sometimes possible to insert duplicate data and how to avoid that? |
| Comments |
| Comment by Eric Milkie [ 29/Mar/17 ] | |||||||||||||||||||||
|
I discovered a problem with partial index filters on unique indexes with WiredTiger that I believe is what you were experiencing here. Please follow the linked ticket for further updates. | |||||||||||||||||||||
| Comment by Eric Milkie [ 27/Mar/17 ] | |||||||||||||||||||||
|
Hi pwirth | |||||||||||||||||||||
| Comment by Phillip Wirth [ 22/Mar/17 ] | |||||||||||||||||||||
|
Hi this issue is not present anymore since we do use unique indexes with a partialExpressionFilter anymore. | |||||||||||||||||||||
| Comment by Ramon Fernandez Marina [ 21/Mar/17 ] | |||||||||||||||||||||
|
pwirth, if this is still an issue for you, can you please provide the information that Thomas requested in the previous comment? Thanks, | |||||||||||||||||||||
| Comment by Kelsey Schubert [ 13/Mar/17 ] | |||||||||||||||||||||
|
Hi pwirth, Would you please provide the complete output of the following commands against the affected collections?
Thank you, | |||||||||||||||||||||
| Comment by Phillip Wirth [ 13/Mar/17 ] | |||||||||||||||||||||
|
The problem still exists now with a different Index... From 38 Documents only 28 were in the Index. Calling reIndex on the collection resolved the issue, however I guess that in further duplicate documents will be present. I Just found out that there isn't any _id index which is very weird! | |||||||||||||||||||||
| Comment by Phillip Wirth [ 13/Mar/17 ] | |||||||||||||||||||||
|
Hi Eric, unfortunately this isn't possible anymore since we changed some fields and dropped the index since this all was happening live. And I can't provide you any server logs since we do not have any permission to read that file ...... | |||||||||||||||||||||
| Comment by Eric Milkie [ 10/Mar/17 ] | |||||||||||||||||||||
|
Since this index is clearly not working, would you like to try dropping and recreating it with the same spec? It would be interesting to see if the index rebuild would discover the unique key violations, or not. This would help narrow down where the issue lies. | |||||||||||||||||||||
| Comment by Eric Milkie [ 10/Mar/17 ] | |||||||||||||||||||||
|
Thanks for that info. I have been using upserts with string _id fields in my repro attempts, so it's still not clear if that particular code path is involved in this issue. | |||||||||||||||||||||
| Comment by Phillip Wirth [ 10/Mar/17 ] | |||||||||||||||||||||
|
Hey Eric, I just found out that our code does not perform a simple insert.
The documentation on save
Since we generate a string _id field an upsert will be performed. | |||||||||||||||||||||
| Comment by Phillip Wirth [ 08/Mar/17 ] | |||||||||||||||||||||
https://jira.mongodb.org/browse/SERVER-28153?focusedCommentId=1518375&page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel#comment-1518375 I noted it here after I looked closely in the documents which are not in the index (anymore) and found around 80 documents that match this pattern
sounds great!
well we can't even get the mongod logs from this server ... we will see after Friday - I have to leave for today - good night to where ever you are | |||||||||||||||||||||
| Comment by Eric Milkie [ 08/Mar/17 ] | |||||||||||||||||||||
Have you seen evidence of this? (I didn't see anything in the discussion so far in this ticket that showed that.) This fact would narrow down the areas of the code to look at. Another option to explore: To determine if WiredTiger is the culprit here, we would require you to send us your journal files immediately after an inserted or updated record did not get indexed; in addition, a special WiredTiger option to not discard journal files after a checkpoint, in case a checkpoint happens to run. If you are willing to explore this option, I can send more details. | |||||||||||||||||||||
| Comment by Phillip Wirth [ 08/Mar/17 ] | |||||||||||||||||||||
It will get dropped however a new index with slightly different behavior replaces this one. So we can't reproduce this issue anymore on next Friday.
It is too late for such a check now, but I do not think that such a thing would be helpful since there are documents updated and then disappeared, sometimes after days, from the index somehow. Which implies that they were in the index once they got inserted.
I suggested already updating at least to 3.2.12 to my colleagues ... we will see what Friday brings at first for our next release. Thanks also for the help so far | |||||||||||||||||||||
| Comment by Eric Milkie [ 08/Mar/17 ] | |||||||||||||||||||||
|
I've discussed this situation further with my colleagues. I'd like you to try dropping the index and recreating it the same way, to see if it still has the same issue. You will need to manually clear out the documents with conflicting "userId" fields first. " that it exists in the uidx-something-user index? As we take steps to narrow down the problem, I'd like to have immediate signal on whether a given step has caused a change in behavior, and confirming that inserts are working properly or not is the best way to achieve that. | |||||||||||||||||||||
| Comment by Phillip Wirth [ 08/Mar/17 ] | |||||||||||||||||||||
|
On another collection with 3 indices with partialFilterExpression where the filter consists of 2 exits operations combined everything works fine. So everything points to a faulty check with new BasicDBObject(Properties.someting, new BasicDBObject("$eq", true)) what do you think Eric? | |||||||||||||||||||||
| Comment by Phillip Wirth [ 07/Mar/17 ] | |||||||||||||||||||||
Usually, items and recipient, Also some fields will can get added to the root document, but there is no pattern visible...
That is not possible by applications logic
There are no other indices. I can now confirm, there are documents which got updated but are not in the index... | |||||||||||||||||||||
| Comment by Eric Milkie [ 07/Mar/17 ] | |||||||||||||||||||||
|
Interesting. When documents get updated, which fields typically change? Would such updates move a document into or out of one of the partial indexes on the collection? | |||||||||||||||||||||
| Comment by Phillip Wirth [ 07/Mar/17 ] | |||||||||||||||||||||
|
1.
Such a document does not exist. 2.
371 of 786 unique userIds were not found in the index. It gets more weird now 3.
No. , the insert is always the same, in case of something:false there are some more fields populated irrelevant to the uidx-something-user index. but relevant for idx-another-index since one these additional field builds the unique key.
| |||||||||||||||||||||
| Comment by Eric Milkie [ 07/Mar/17 ] | |||||||||||||||||||||
|
Also, is your application code path different when it inserts a document with {something:true} versus a document with {something:false}? Would such writes possibly have different parameters to the update command, via the Java driver? | |||||||||||||||||||||
| Comment by Eric Milkie [ 07/Mar/17 ] | |||||||||||||||||||||
|
It would be an interesting data point if you found documents with the same userId and more than 0 of them were in the uidx-something-user index. That might imply that the documents now missing from the index were at one point present in the index, and sometime later those records were either explicitly removed via a bug in the insert logic, or lost by the storage engine. | |||||||||||||||||||||
| Comment by Phillip Wirth [ 07/Mar/17 ] | |||||||||||||||||||||
|
I do now have a test collection with all the documents matching "something:false"
and a collection with all the documents matching "something:false" from the index.
The first thing I did was to find out if this only affecty some specific userId s ... but no.
There is one user having 6 Documents, some having 5 or 4 but the most having 3 or 2 documents. I looked a bit further...
Returns 6 documents. When looking in the collection derived from the index:
Nothing has been found. This pattern is true for most of the documents ... I just found a few exceptions yet but even they don't tend to be something special. The time window is now from mid of january (or before - I do not have all logs ... ) till now. | |||||||||||||||||||||
| Comment by Eric Milkie [ 07/Mar/17 ] | |||||||||||||||||||||
|
Sorry, I forgot you are using a user-defined _id field. Can you check that the _id index has all the records (~4333 or whatever the current record count is now)? | |||||||||||||||||||||
| Comment by Phillip Wirth [ 07/Mar/17 ] | |||||||||||||||||||||
- Correct. There is a difference between those 2 indicies, idx-another-index covers also more fields which should, based on the business logic be unique. Just to let you see the other index, sorry for this obfuscation...
Since the collection is not that big I will try my best.
in my researches I found out that there were days between the creation date of these 2 documents Unfortunately there is no ObjectId, just a self written _id field which is a random UUID so no chance to get any timestamp from and also no other field to determine when the document was inserted. I can just grep through the logs, which are incomplete ... | |||||||||||||||||||||
| Comment by Eric Milkie [ 07/Mar/17 ] | |||||||||||||||||||||
|
Those counts are very strange. 3/4 of the records that should be in the uidx-something-user index are erroneously not indexed. , and then query all the records in the uidx-something-user index via a hint, and then compare the two query responses. Perhaps all the incorrectly indexed records shared the same insert time window, or have the same configuration of fields? | |||||||||||||||||||||
| Comment by Phillip Wirth [ 07/Mar/17 ] | |||||||||||||||||||||
|
Seems legit. Current count: 4333
| |||||||||||||||||||||
| Comment by Eric Milkie [ 07/Mar/17 ] | |||||||||||||||||||||
|
Can you also count the number of documents with {something:true}? We can compare that number with 485 to learn how many records are not in the index but should be.
| |||||||||||||||||||||
| Comment by Phillip Wirth [ 07/Mar/17 ] | |||||||||||||||||||||
|
Hi Erik, the collection is very small, just 4331 entries currently.
Interresting fact: The both indicies together should cover all documents but there is a huge gap. 4331 - 3112 != 485 The other index is a partial index too but those problems only occur with the one previously mentioned, uidx-something-user And could you please focus on version 3.2.7, I am pretty sure this bug exists in 3.2.12 too but I can't verify that :/ | |||||||||||||||||||||
| Comment by Eric Milkie [ 07/Mar/17 ] | |||||||||||||||||||||
|
Hi Phillip,
| |||||||||||||||||||||
| Comment by Eric Milkie [ 07/Mar/17 ] | |||||||||||||||||||||
|
I took the information you provided and have been attempting to write reproduction scripts to try to suss this out. In the past few days I have examined the code in-depth but haven't found any smoking guns yet. | |||||||||||||||||||||
| Comment by Phillip Wirth [ 03/Mar/17 ] | |||||||||||||||||||||
|
1.
With "the specific fields" I mean userId and something 3.
Will find the documents.
Will find the documents.
Will not find the documents
Will not find the documents Side note: in my researches I found out that there were days between the creation date of these 2 documents, ( 3 or up to a week not sure anymore) - but the index was created way before. Since this is live data there will be an update next Friday which will delete the index and create another one with different options. Maybe this will fix the problem (But I bet not since it is also a uniquie - partialExpression filter index. Well in other words: the windows to research this bug is closing. The only thing that I will have afterwards is a dump with a broken index. (Which I can't restore with indicies as previously mentioned) | |||||||||||||||||||||
| Comment by Eric Milkie [ 03/Mar/17 ] | |||||||||||||||||||||
|
Thank you for your answers so far! I need some clarification. 1. What you mean by "specific fields" – which exact ones? If possible, can you supply the exact invocation for writes that resulted in the conflicting documents? 3. Are you certain none of the documents are in the index? This fact is surprising to me. I would expect either one or both of a conflicting pair of documents to be in the index. Can you show the exact queries and output that show this? | |||||||||||||||||||||
| Comment by Phillip Wirth [ 03/Mar/17 ] | |||||||||||||||||||||
|
Hi @milkie 1. Just normal inserts cause the problem, the specific fields are never updated again, but other parts of the document with simple updates 2. It is a standalone node. 3. The documents in question are not in the index. 4. No document validation is used, db.getCollectionInfos() prints only collection names with empty options on every collection.
6. Maybe once a week, not quite sure since the error causes subsequenz errors when the data gets reimported on another server | |||||||||||||||||||||
| Comment by Eric Milkie [ 02/Mar/17 ] | |||||||||||||||||||||
|
Hi pwirth | |||||||||||||||||||||
| Comment by Phillip Wirth [ 02/Mar/17 ] | |||||||||||||||||||||
|
Could be a duplicate of |