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

Capped collections can exceed limits after rollback

    • Type: Icon: Bug Bug
    • Resolution: Fixed
    • Priority: Icon: Major - P3 Major - P3
    • 5.0.0-rc2, 5.1.0-rc0
    • Affects Version/s: 5.0.0-rc0
    • Component/s: None
    • None
    • Fully Compatible
    • ALL
    • v5.0
    • Execution Team 2021-06-28
    • 39

      The create_capped_collection_maxdocs.js test creates a capped collection with the maximum number of documents set to be 3. There's an assertion that the number of documents in the capped collection never exceeds 3. However, there was a build failure that showed 4 documents present in the capped collection at some point.

      Since SERVER-16049, capped deletes are replicated. This means that capped deletes can be rolled back without rolling back the insert that caused the capped collection to trigger the delete. This makes it possible for the capped collection to exceed its limits temporarily until the next insert is performed.

       

      This is a known and understood limit of capped collections. Tagging this test with does_not_support_stepdowns would this fix.

       

      From the build failure:

      The last capped insert and (triggered) delete on this capped collection was performed successfully, and the capped collection has 3 documents present upon committing:

      [j0:s1:n1] {"t":{"$date":"2021-05-27T16:26:01.940+00:00"},"s":"I",  "c":"STORAGE",  "id":0,       "ctx":"conn65","msg":"XXX Enter","attr":{"ns":"test0_fsmdb0.create_capped_collection_maxdocs2_0","cappedFirstRecord":"1040","cappedLock":true,"sideTxn":false,"numRecords":4,"docsOverCap":1,"dataSize":4092,"sizeOverCap":0}}
      [j0:s1:n1] {"t":{"$date":"2021-05-27T16:26:01.940+00:00"},"s":"I",  "c":"STORAGE",  "id":0,       "ctx":"conn65","msg":"XXX begin seekNear()","attr":{"ns":"test0_fsmdb0.create_capped_collection_maxdocs2_0"}}
      [j0:s1:n1] {"t":{"$date":"2021-05-27T16:26:01.940+00:00"},"s":"I",  "c":"STORAGE",  "id":0,       "ctx":"conn65","msg":"XXX found record to delete","attr":{"ns":"test0_fsmdb0.create_capped_collection_maxdocs2_0","record":"1040"}}
      [j0:s1:n1] {"t":{"$date":"2021-05-27T16:26:01.940+00:00"},"s":"I",  "c":"STORAGE",  "id":0,       "ctx":"conn65","msg":"XXX deleting","attr":{"ns":"test0_fsmdb0.create_capped_collection_maxdocs2_0","record":"1040","docsRemoved":1}}
      [j0:s1:n1] {"t":{"$date":"2021-05-27T16:26:01.942+00:00"},"s":"I",  "c":"STORAGE",  "id":0,       "ctx":"conn65","msg":"XXX Exit","attr":{"ns":"test0_fsmdb0.create_capped_collection_maxdocs2_0","cappedFirstRecord":"1040","cappedLock":true,"sideTxn":false,"numRecords":3,"docsOverCap":1,"docsRemoved":1,"dataSize":3069,"sizeOverCap":0}}
      [j0:s1:n1] {"t":{"$date":"2021-05-27T16:26:01.942+00:00"},"s":"I",  "c":"STORAGE",  "id":0,       "ctx":"conn65","msg":"XXX onCommit","attr":{"ns":"test0_fsmdb0.create_capped_collection_maxdocs2_0","oldCappedFirstRecord":"1040","newCappedFirstRecord":"1041"}}
      

      Right after this, the primary stepped down:

      [j0:s1:n1] | 2021-05-27T16:26:01.949+00:00 I  REPL     21402   [conn117] "Stepping down from primary, because a new term has begun","attr":{"term":19}
      [j0:s1:n1] | 2021-05-27T16:26:01.955+00:00 I  REPL     21358   [ReplCoord-4] "Replica set state transition","attr":{"newState":"SECONDARY","oldState":"PRIMARY"}
      

      Triggering a rollback:

      [j0:s1:n1] | 2021-05-27T16:26:03.022+00:00 I  REPL     21098   [BackgroundSync] "Starting rollback due to fetcher error","attr":{"error":"OplogStartMissing: the sync source's oplog and our oplog have diverged, going into rollback. our last optime fetched: { ts: Timestamp(1622132761, 60), t: 18 }. source's GTE: { ts: Timestamp(1622132762, 1), t: 19 }","lastCommittedOpTime":{"ts":{"$timestamp":{"t":1622132761,"i":54}},"t":18}}
      [j0:s1:n1] | 2021-05-27T16:26:03.023+00:00 I  REPL     21102   [BackgroundSync] "Rollback using 'recoverToStableTimestamp' method"
      [j0:s1:n1] | 2021-05-27T16:26:03.023+00:00 I  ROLLBACK 21593   [BackgroundSync] "Transition to ROLLBACK"
      

      which removed the last capped delete (but not insert)

      [j0:s1:n1] | 2021-05-27T16:26:03.419+00:00 D2 ROLLBACK 21656   [BackgroundSync] "Local oplog entry to roll back","attr":{"oplogEntry":{"op":"d","ns":"test0_fsmdb0.create_capped_collection_maxdocs2_0","ui":{"$uuid":"3ed3170e-87d4-4ead-a92d-dcf3aa04820b"},"o":{"_id":{"$oid":"60afc819e7821bc338a7d711"}},"ts":{"$timestamp":{"t":1622132761,"i":59}},"t":18,"v":2,"wall":{"$date":"2021-05-27T16:26:01.940Z"}}}
      [j0:s1:n1] | 2021-05-27T16:26:03.426+00:00 D2 ROLLBACK 21605   [BackgroundSync] "Setting record count for namespace after rollback","attr":{"namespace":"test0_fsmdb0.create_capped_collection_maxdocs2_0","uuid":"3ed3170e-87d4-4ead-a92d-dcf3aa04820b","oldCount":3,"newCount":4,"countDiff":1}
      

            Assignee:
            gregory.wlodarek@mongodb.com Gregory Wlodarek
            Reporter:
            gregory.wlodarek@mongodb.com Gregory Wlodarek
            Votes:
            0 Vote for this issue
            Watchers:
            4 Start watching this issue

              Created:
              Updated:
              Resolved: