Uploaded image for project: 'Core Server'
  1. Core Server
  2. SERVER-74551

WriteConflictException unnecessarily logged as warning during findAndModify after upgrade to mongo 5.0

    • Type: Icon: Bug Bug
    • Resolution: Fixed
    • Priority: Icon: Major - P3 Major - P3
    • 7.1.0-rc0, 6.0.7, 5.0.19, 7.0.0-rc3
    • Affects Version/s: 5.0.15, 6.0.4
    • Component/s: None
    • None
    • Query Execution
    • Fully Compatible
    • ALL
    • v7.0, v6.3, v6.0, v5.0
    • Hide

      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.

      Show
      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.
    • QE 2023-06-12

      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?

            Assignee:
            david.storch@mongodb.com David Storch
            Reporter:
            lukasz.gebicki@autenti.com Łukasz Gębicki
            Votes:
            2 Vote for this issue
            Watchers:
            20 Start watching this issue

              Created:
              Updated:
              Resolved: