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

Investigate effectiveness of test jstests/replsets/rollback_waits_for_bgindex_completion.js

    • Type: Icon: Bug Bug
    • Resolution: Duplicate
    • Priority: Icon: Major - P3 Major - P3
    • None
    • Affects Version/s: None
    • Component/s: None
    • None
    • ALL
    • Repl 2021-10-18, Repl 2021-11-01, Replication 2021-11-15

      Test jstests/replsets/rollback_waits_for_bgindex_completion.js runs an index build in the background while a transaction is waiting to be committed, leader steps down, and rollsback the txn. Test verifies that rollback should wait for the index build to be aborted but it seems from the logs that there is no wait happening--rollback proceeds immediately because abort of index build has occurred earlier. We should investigate if the current behavior makes for a correct test, and possibly introduce a delay in aborting the index build so rollback effectively waits for it.

      Please refer to ticket https://jira.mongodb.org/browse/SERVER-59687 for more information.

      Relevant log portion:

      [js_test:rollback_waits_for_bgindex_completion] d20030| {"t":{"$date":"2021-09-22T23:06:42.609+00:00"},"s":"I",  "c":"STORAGE",  "id":20655,   "ctx":"BackgroundSync","msg":"Index build: joined after abort","attr":{"buildUUID":{"uuid":{"$uuid":"39d281db-25d4-46c3-9f3b-20133f58bff4"}},"waitResult":{"code":0,"codeName":"OK"},"status":{"code":276,"codeName":"IndexBuildAborted","errmsg":"collection scan stopped. totalRecords: 1; durationMillis: 0ms; phase: collection scan; collectionScanPosition: RecordId(1); readSource: kMajorityCommitted :: caused by :: operation was interrupted"}}}
      [js_test:rollback_waits_for_bgindex_completion] d20030| {"t":{"$date":"2021-09-22T23:06:42.609+00:00"},"s":"I",  "c":"STORAGE",  "id":20347,   "ctx":"BackgroundSync","msg":"Index build: aborted without cleanup","attr":{"buildUUID":{"uuid":{"$uuid":"39d281db-25d4-46c3-9f3b-20133f58bff4"}},"collectionUUID":{"uuid":{"$uuid":"8cec4cde-51df-432e-8bd2-2a2f8a54593d"}},"namespace":"dbWithBgIndex.coll"}}
      [js_test:rollback_waits_for_bgindex_completion] d20030| {"t":{"$date":"2021-09-22T23:06:42.609+00:00"},"s":"I",  "c":"STORAGE",  "id":4656002, "ctx":"IndexBuildsCoordinatorMongod-0","msg":"unable to log operation","attr":{"error":{"code":276,"codeName":"IndexBuildAborted","errmsg":"operation was interrupted"}}}
      [js_test:rollback_waits_for_bgindex_completion] d20032| {"t":{"$date":"2021-09-22T23:06:42.613+00:00"},"s":"I",  "c":"REPL",     "id":21079,   "ctx":"BackgroundSync","msg":"bgsync - stopReplProducer fail point enabled. Blocking until fail point is disabled."}
      [js_test:rollback_waits_for_bgindex_completion] d20030| {"t":{"$date":"2021-09-22T23:06:42.617+00:00"},"s":"I",  "c":"INDEX",    "id":4841502, "ctx":"BackgroundSync","msg":"Index build: wrote resumable state to disk","attr":{"buildUUID":{"uuid":{"$uuid":"39d281db-25d4-46c3-9f3b-20133f58bff4"}},"collectionUUID":{"uuid":{"$uuid":"8cec4cde-51df-432e-8bd2-2a2f8a54593d"}},"namespace":"dbWithBgIndex.coll","details":{"_id":{"$uuid":"39d281db-25d4-46c3-9f3b-20133f58bff4"},"phase":"collection scan","collectionUUID":{"$uuid":"8cec4cde-51df-432e-8bd2-2a2f8a54593d"},"collectionScanPosition":1,"indexes":[{"fileName":"extsort-index.0-1004796179216808253","numKeys":1,"ranges":[{"startOffset":0,"endOffset":13,"checksum":4272028543}],"sideWritesTable":"internal-43--4107655658741736919","spec":{"v":2,"key":{"x":1},"name":"x_1"},"isMultikey":false,"multikeyPaths":[{"multikeyComponents":[]}]}]}}}
      [js_test:rollback_waits_for_bgindex_completion] d20030| {"t":{"$date":"2021-09-22T23:06:42.617+00:00"},"s":"I",  "c":"ROLLBACK", "id":21595,   "ctx":"BackgroundSync","msg":"Waiting for all background operations to complete before starting rollback"}
      [js_test:rollback_waits_for_bgindex_completion] d20030| {"t":{"$date":"2021-09-22T23:06:42.617+00:00"},"s":"I",  "c":"ROLLBACK", "id":21597,   "ctx":"BackgroundSync","msg":"Finished waiting for background operations to complete before rollback"}
      

      Notice the last two lines, rollback intends to wait for indexbuild to be completed (aborted?), but the abort has already occurred, so there is nothing to wait for.

            Assignee:
            adi.zaimi@mongodb.com Adi Zaimi
            Reporter:
            adi.zaimi@mongodb.com Adi Zaimi
            Votes:
            0 Vote for this issue
            Watchers:
            2 Start watching this issue

              Created:
              Updated:
              Resolved: