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

    XMLWordPrintableJSON

Details

    • Icon: Bug Bug
    • Resolution: Fixed
    • Icon: Major - P3 Major - P3
    • 7.1.0-rc0, 6.0.7, 5.0.19, 7.0.0-rc3
    • 5.0.15, 6.0.4
    • 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

    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?

      Attachments

        1. image-2023-05-31-15-48-18-602.png
          image-2023-05-31-15-48-18-602.png
          17 kB

        Activity

          People

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

            Dates

              Created:
              Updated:
              Resolved: