[SERVER-74551] WriteConflictException unnecessarily logged as warning during findAndModify after upgrade to mongo 5.0 Created: 02/Mar/23  Updated: 29/Oct/23  Resolved: 06/Jun/23

Status: Closed
Project: Core Server
Component/s: None
Affects Version/s: 5.0.15, 6.0.4
Fix Version/s: 7.1.0-rc0, 6.0.7, 5.0.19, 7.0.0-rc3

Type: Bug Priority: Major - P3
Reporter: Łukasz Gębicki Assignee: David Storch
Resolution: Fixed Votes: 2
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Attachments: PNG File image-2023-05-31-15-48-18-602.png    
Issue Links:
Backports
Problem/Incident
is caused by SERVER-43821 Fail in query execution by throwing r... Closed
Related
is related to SERVER-80317 DuplicateKey error message is logged ... Open
Assigned Teams:
Query Execution
Backwards Compatibility: Fully Compatible
Operating System: ALL
Backport Requested:
v7.0, v6.3, v6.0, v5.0
Steps To Reproduce:

Bug can be reproduced using prepared java project: https://github.com/gebus93/mongo-find-and-modify-issue 

Alternative manual steps:
1. Prepare data set with attributes "id", "creationTime", "status"
2. Prepare command findAndModify or findOneAndUpdate which takes first document from result with status "NEW", sorted by creationTime, and changes status to "PROCESSING".
3. Run this command asynchronously in 25 threads at the same time.

Sprint: QE 2023-06-12
Participants:
Case:

 Description   

After upgrading mongodb from version 4.4.x to 5.0.14 in a company I'm working for, we have found thousands of errors in our logs. All of them refers to the same issue "Plan executor error during findAndModify".

In our case, we use findAndModify in a spring-boot application to take first pending job from a queue. This operation is executed concurrently on many app instances (5-10 threads each).

Here you can find sample project simulating our use case: https://github.com/gebus93/mongo-find-and-modify-issue

In this project I created 3 tests to compare the behaviour of mongo 4, 5 and 6. Each test runs a specific mongodb in a docker container and executes the same test case.

Mongodb 4.4.19 doesn't log any write conflict during the test, but starting from mongo 5.0.x error logs are produced on every test run.

 

{"t":{"$date":"2023-03-02T11:47:14.567+00:00"},"s":"W",  "c":"COMMAND",  "id":23802,   "ctx":"conn13","msg":"Plan executor error during findAndModify","attr":{"error":{"code":112,"codeName":"WriteConflict","errmsg":"WriteConflict error: this operation conflicted with another operation. Please retry your operation or multi-document transaction."},"stats":{"stage":"UPDATE","nReturned":0,"executionTimeMillisEstimate":0,"works":104,"advanced":0,"needTime":102,"needYield":1,"saveState":1,"restoreState":1,"failed":true,"isEOF":0,"nMatched":0,"nWouldModify":0,"nWouldUpsert":0,"inputStage":{"stage":"SORT","nReturned":1,"executionTimeMillisEstimate":0,"works":103,"advanced":1,"needTime":102,"needYield":0,"saveState":2,"restoreState":1,"isEOF":0,"sortPattern":{"creationTime":1},"memLimit":104857600,"limitAmount":1,"type":"default","totalDataSizeSorted":0,"usedDisk":false,"inputStage":{"stage":"COLLSCAN","filter":{"status":{"$eq":"NEW"}},"nReturned":53,"executionTimeMillisEstimate":0,"works":102,"advanced":53,"needTime":48,"needYield":0,"saveState":2,"restoreState":1,"isEOF":1,"direction":"forward","docsExamined":100}}},"cmd":{"findAndModify":"jobs","query":{"status":"NEW"},"sort":{"creationTime":1},"update":{"$set":{"status":"PROCESSING"}},"new":false}}} 

Is this behaviour expected?
Why is there a difference between mongodb 4 and the others?



 Comments   
Comment by David Storch [ 13/Jun/23 ]

Hi sushant3524@gmail.com! The fix has already been applied to the v6.0 release branch and will be included in the forthcoming 6.0.7 patch release.

Comment by Sushant Ashutosh [ 13/Jun/23 ]

hii david.storch@mongodb.com We are facing same issue after recently upgrading to 6.0.6.
Any timeline that you can share for this fix for mongo version 6?

Comment by Łukasz Gębicki [ 09/Jun/23 ]

david.storch@mongodb.com, Thank you for the information!

Comment by David Storch [ 07/Jun/23 ]

Hi lukasz.gebicki@autenti.com legatti@gmail.com, I've completed all of the backports. The fix is now present in the 5.0 branch and will be available as part of upcoming release version 5.0.19. We are currently planning for 5.0.19 general availability sometime in early-to-mid July. Thanks for bringing the issue to our attention!

Comment by Githook User [ 07/Jun/23 ]

Author:

{'name': 'David Storch', 'email': 'david.storch@mongodb.com', 'username': 'dstorch'}

Message: SERVER-74551 fix spammy WCE logging in findAndModify code

(cherry picked from commit 5ff8a1da2b1aa08a36fae3ec1747728fecaf70c6)
Branch: v5.0
https://github.com/mongodb/mongo/commit/abac1c20035195e59fda2b072514a12d5bc054a9

Comment by Githook User [ 07/Jun/23 ]

Author:

{'name': 'David Storch', 'email': 'david.storch@mongodb.com', 'username': 'dstorch'}

Message: SERVER-74551 fix spammy WCE logging in findAndModify code

(cherry picked from commit ab75b27df99ad549b141ef27fcddf5eb04b58b74)
Branch: v6.0
https://github.com/mongodb/mongo/commit/5ff8a1da2b1aa08a36fae3ec1747728fecaf70c6

Comment by David Storch [ 07/Jun/23 ]

Hi lukasz.gebicki@autenti.com, I'm working on the backports now and will provide another update regarding timeline when this lands in 5.0. I completed the backport to the 7.0 branch yesterday, and I expect the backports to 6.0 and 5.0 to be pretty straightforward as well.

Comment by Łukasz Gębicki [ 07/Jun/23 ]

Hi david.storch@mongodb.com! Yes, I was asking specifically about version 5.0.x. If it's not a problem for you, It would be nice to be informed about the release timeline, specifically in which patch version and when we can expect this fix to be released.

Comment by Githook User [ 06/Jun/23 ]

Author:

{'name': 'David Storch', 'email': 'david.storch@mongodb.com', 'username': 'dstorch'}

Message: SERVER-74551 fix spammy WCE logging in findAndModify code

(cherry picked from commit ab75b27df99ad549b141ef27fcddf5eb04b58b74)
Branch: v7.0
https://github.com/mongodb/mongo/commit/d920c730e9143c7f14dda9248734944f40f74e98

Comment by David Storch [ 06/Jun/23 ]

Hi lukasz.gebicki@autenti.com! I've just merged the fix for this issue into the master branch, which will evolve into the 7.1 rapid release branch. However, we also intend to backport the fix to the 7.0, 6.0, and 5.0 branches. Once those backports are complete, the fix will be included in the next patch release on each branch. Are you interested specifically in the release timeline for the 5.0.x patch release containing this fix? If so, I can update you regarding timeline once the backport to the 5.0 branch is complete.

Comment by Githook User [ 06/Jun/23 ]

Author:

{'name': 'David Storch', 'email': 'david.storch@mongodb.com', 'username': 'dstorch'}

Message: SERVER-74551 fix spammy WCE logging in findAndModify code
Branch: master
https://github.com/mongodb/mongo/commit/ab75b27df99ad549b141ef27fcddf5eb04b58b74

Comment by Łukasz Gębicki [ 02/Jun/23 ]

Thanks david.storch@mongodb.com !

Could you tell us when we can expect this fix? It would be great to get our mongo instances updated and finally get rid of those warnings.

Comment by Eduardo Legatti [ 01/Jun/23 ]

Thanks david.storch@mongodb.com 

Comment by Felix Gertz [ 01/Jun/23 ]

Fantastic david.storch@mongodb.com ! Thanx for fixing this.

Comment by David Storch [ 31/May/23 ]

Hi lukasz.gebicki@autenti.com legatti@gmail.com mongo@felixgertz.de, I'm looking into this now. Given that WriteConflictException being thrown and retried internally is a perfectly normal behavior, I would say that the eager logging of these exceptions as log warnings is a bug. We will look into providing a fix soon in the affected release branches which prevents these unnecessary warnings from spamming the logs.

Comment by Eduardo Legatti [ 31/May/23 ]

All you need to vote for this issue

Comment by Eduardo Legatti [ 31/May/23 ]

Hi,

I am planning to upgrade our MongoDB servers from version 4.2 to 6.0. It's going to be impractical to have these errors in the logs for dozens of databases. If there is no solution I will not be able to do this upgrade. The question now is: Is this a bug or a normal behavior.  We need a workaround to stop generating these messages.

Comment by Felix Gertz [ 31/May/23 ]

Hi,

we having the same since we updated to version 5. We also running concurrent updates with findOneAndUpdate for queue processing, successfully since years.
This now generates 7GB of logs with "Plan executeor error..." each day, which lead us to create a regular manual cleanup job, done by one of our trainee.

Would be great if he could go back to making coffee for us.

Comment by Eduardo Legatti [ 26/May/23 ]

Hi,

Any news about this issue? I also having many messages in the log. I'm using 6.0.4 Community. Is there a workaround to stop generating these messages?

{{}}

{"t":{"$date":"2023-03-02T11:47:14.567+00:00"},"s":"W", "c":"COMMAND", "id":23802, "ctx":"conn13","msg":"Plan executor error during findAndModify","attr":{"error":{"code":112,"codeName":"WriteConflict","errmsg":"WriteConflict error: this operation conflicted with another operation. Please retry your operation or multi-document transaction."}

{{}}

Comment by Max Hirschhorn [ 20/Apr/23 ]

Hi lukasz.gebicki@autenti.com!

Thanks for your report. Just an update - we are still looking into this.

I believe the excessive logging about WriteConflictExceptions during the execution of a findAndModify command was introduced by the changes from d295b66 as part of SERVER-43821. The UpdateStage throws a WriteConflictException—which is a subclass of DBException—when a findAndModify + sort initially matches a document yet finds the document no longer matches the filter when it goes to update the document. (The DeleteStage has identical behavior as well.) Previously the WriteConflictException wouldn't trigger the LOGV2_WARNING(23802, "Plan executor error during findAndModify") yet now it does.

CC david.storch@mongodb.com, kyle.suarez@mongodb.com

Generated at Thu Feb 08 06:27:46 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.