|
I think this is a dup of SERVER-55366 where we incorrectly retry retryable writes without the successful statements.
In this log, we can see that:
// Update _id 0-11 with stmtId 0-11
|
[j1:rs1:n0] | 2021-03-18T20:28:40.479+00:00 D2 TENANT_M 4886009 [TenantMigrationWriter-4] "Applied tenant operation","attr":{"tenant":"tenantMigrationTenantId","migrationUuid":{"uuid":{"$uuid":"14e5e387-10eb-49b2-a428-2b979569fcce"}},"error":{"code":0,"codeName":"OK"},"op":{"oplogEntry":{"lsid":{"id":{"$uuid":"3c69fd32-e9a4-444a-97ac-8d5f76885aea"},"uid":{"$binary":{"base64":"47DEQpj8HBSa+/TImW+5JCeuQeRkm5NMpJWZG3hSuFU=","subType":"0"}}},"txnNumber":5,"op":"u","ns":"tenantMigrationTenantId_background_unique_indexes.test","ui":{"$uuid":"3d1f61d2-c66e-4fb3-9aae-29bea82cd109"},"o":{"_id":4,"x":4,"iter":2},"o2":{"_id":4},"ts":{"$timestamp":{"t":1616099320,"i":5}},"t":2,"wall":{"$date":"2021-03-18T20:28:40.031Z"},"v":2,"stmtId":4,"prevOpTime":{"ts":{"$timestamp":{"t":1616099320,"i":4}},"t":2}}}}
|
[j1:rs1:n0] | 2021-03-18T20:28:40.480+00:00 D2 TENANT_M 4886009 [TenantMigrationWriter-2] "Applied tenant operation","attr":{"tenant":"tenantMigrationTenantId","migrationUuid":{"uuid":{"$uuid":"14e5e387-10eb-49b2-a428-2b979569fcce"}},"error":{"code":0,"codeName":"OK"},"op":{"oplogEntry":{"lsid":{"id":{"$uuid":"3c69fd32-e9a4-444a-97ac-8d5f76885aea"},"uid":{"$binary":{"base64":"47DEQpj8HBSa+/TImW+5JCeuQeRkm5NMpJWZG3hSuFU=","subType":"0"}}},"txnNumber":5,"op":"u","ns":"tenantMigrationTenantId_background_unique_indexes.test","ui":{"$uuid":"3d1f61d2-c66e-4fb3-9aae-29bea82cd109"},"o":{"_id":3,"x":3,"iter":2},"o2":{"_id":3},"ts":{"$timestamp":{"t":1616099320,"i":4}},"t":2,"wall":{"$date":"2021-03-18T20:28:40.030Z"},"v":2,"stmtId":3,"prevOpTime":{"ts":{"$timestamp":{"t":1616099320,"i":3}},"t":2}}}}
|
[j1:rs1:n0] | 2021-03-18T20:28:40.480+00:00 D2 TENANT_M 4886009 [TenantMigrationWriter-0] "Applied tenant operation","attr":{"tenant":"tenantMigrationTenantId","migrationUuid":{"uuid":{"$uuid":"14e5e387-10eb-49b2-a428-2b979569fcce"}},"error":{"code":0,"codeName":"OK"},"op":{"oplogEntry":{"lsid":{"id":{"$uuid":"3c69fd32-e9a4-444a-97ac-8d5f76885aea"},"uid":{"$binary":{"base64":"47DEQpj8HBSa+/TImW+5JCeuQeRkm5NMpJWZG3hSuFU=","subType":"0"}}},"txnNumber":5,"op":"u","ns":"tenantMigrationTenantId_background_unique_indexes.test","ui":{"$uuid":"3d1f61d2-c66e-4fb3-9aae-29bea82cd109"},"o":{"_id":0,"x":0,"iter":2},"o2":{"_id":0},"ts":{"$timestamp":{"t":1616099320,"i":1}},"t":2,"wall":{"$date":"2021-03-18T20:28:40.029Z"},"v":2,"stmtId":0,"prevOpTime":{"ts":{"$timestamp":{"t":0,"i":0}},"t":-1}}}}
|
[j1:rs1:n0] | 2021-03-18T20:28:40.481+00:00 D2 TENANT_M 4886009 [TenantMigrationWriter-2] "Applied tenant operation","attr":{"tenant":"tenantMigrationTenantId","migrationUuid":{"uuid":{"$uuid":"14e5e387-10eb-49b2-a428-2b979569fcce"}},"error":{"code":0,"codeName":"OK"},"op":{"oplogEntry":{"lsid":{"id":{"$uuid":"3c69fd32-e9a4-444a-97ac-8d5f76885aea"},"uid":{"$binary":{"base64":"47DEQpj8HBSa+/TImW+5JCeuQeRkm5NMpJWZG3hSuFU=","subType":"0"}}},"txnNumber":5,"op":"u","ns":"tenantMigrationTenantId_background_unique_indexes.test","ui":{"$uuid":"3d1f61d2-c66e-4fb3-9aae-29bea82cd109"},"o":{"_id":7,"x":7,"iter":2},"o2":{"_id":7},"ts":{"$timestamp":{"t":1616099320,"i":8}},"t":2,"wall":{"$date":"2021-03-18T20:28:40.032Z"},"v":2,"stmtId":7,"prevOpTime":{"ts":{"$timestamp":{"t":1616099320,"i":7}},"t":2}}}}
|
[j1:rs1:n0] | 2021-03-18T20:28:40.481+00:00 D2 TENANT_M 4886009 [TenantMigrationWriter-0] "Applied tenant operation","attr":{"tenant":"tenantMigrationTenantId","migrationUuid":{"uuid":{"$uuid":"14e5e387-10eb-49b2-a428-2b979569fcce"}},"error":{"code":0,"codeName":"OK"},"op":{"oplogEntry":{"lsid":{"id":{"$uuid":"3c69fd32-e9a4-444a-97ac-8d5f76885aea"},"uid":{"$binary":{"base64":"47DEQpj8HBSa+/TImW+5JCeuQeRkm5NMpJWZG3hSuFU=","subType":"0"}}},"txnNumber":5,"op":"u","ns":"tenantMigrationTenantId_background_unique_indexes.test","ui":{"$uuid":"3d1f61d2-c66e-4fb3-9aae-29bea82cd109"},"o":{"_id":8,"x":8,"iter":2},"o2":{"_id":8},"ts":{"$timestamp":{"t":1616099320,"i":9}},"t":2,"wall":{"$date":"2021-03-18T20:28:40.032Z"},"v":2,"stmtId":8,"prevOpTime":{"ts":{"$timestamp":{"t":1616099320,"i":8}},"t":2}}}}
|
[j1:rs1:n0] | 2021-03-18T20:28:40.481+00:00 D2 TENANT_M 4886009 [TenantMigrationWriter-4] "Applied tenant operation","attr":{"tenant":"tenantMigrationTenantId","migrationUuid":{"uuid":{"$uuid":"14e5e387-10eb-49b2-a428-2b979569fcce"}},"error":{"code":0,"codeName":"OK"},"op":{"oplogEntry":{"lsid":{"id":{"$uuid":"3c69fd32-e9a4-444a-97ac-8d5f76885aea"},"uid":{"$binary":{"base64":"47DEQpj8HBSa+/TImW+5JCeuQeRkm5NMpJWZG3hSuFU=","subType":"0"}}},"txnNumber":5,"op":"u","ns":"tenantMigrationTenantId_background_unique_indexes.test","ui":{"$uuid":"3d1f61d2-c66e-4fb3-9aae-29bea82cd109"},"o":{"_id":10,"x":10,"iter":2},"o2":{"_id":10},"ts":{"$timestamp":{"t":1616099320,"i":11}},"t":2,"wall":{"$date":"2021-03-18T20:28:40.032Z"},"v":2,"stmtId":10,"prevOpTime":{"ts":{"$timestamp":{"t":1616099320,"i":10}},"t":2}}}}
|
[j1:rs1:n0] | 2021-03-18T20:28:40.481+00:00 D2 TENANT_M 4886009 [TenantMigrationWriter-3] "Applied tenant operation","attr":{"tenant":"tenantMigrationTenantId","migrationUuid":{"uuid":{"$uuid":"14e5e387-10eb-49b2-a428-2b979569fcce"}},"error":{"code":0,"codeName":"OK"},"op":{"oplogEntry":{"lsid":{"id":{"$uuid":"3c69fd32-e9a4-444a-97ac-8d5f76885aea"},"uid":{"$binary":{"base64":"47DEQpj8HBSa+/TImW+5JCeuQeRkm5NMpJWZG3hSuFU=","subType":"0"}}},"txnNumber":5,"op":"u","ns":"tenantMigrationTenantId_background_unique_indexes.test","ui":{"$uuid":"3d1f61d2-c66e-4fb3-9aae-29bea82cd109"},"o":{"_id":1,"x":1,"iter":2},"o2":{"_id":1},"ts":{"$timestamp":{"t":1616099320,"i":2}},"t":2,"wall":{"$date":"2021-03-18T20:28:40.030Z"},"v":2,"stmtId":1,"prevOpTime":{"ts":{"$timestamp":{"t":1616099320,"i":1}},"t":2}}}}
|
[j1:rs1:n0] | 2021-03-18T20:28:40.481+00:00 D2 TENANT_M 4886009 [TenantMigrationWriter-2] "Applied tenant operation","attr":{"tenant":"tenantMigrationTenantId","migrationUuid":{"uuid":{"$uuid":"14e5e387-10eb-49b2-a428-2b979569fcce"}},"error":{"code":0,"codeName":"OK"},"op":{"oplogEntry":{"lsid":{"id":{"$uuid":"3c69fd32-e9a4-444a-97ac-8d5f76885aea"},"uid":{"$binary":{"base64":"47DEQpj8HBSa+/TImW+5JCeuQeRkm5NMpJWZG3hSuFU=","subType":"0"}}},"txnNumber":5,"op":"u","ns":"tenantMigrationTenantId_background_unique_indexes.test","ui":{"$uuid":"3d1f61d2-c66e-4fb3-9aae-29bea82cd109"},"o":{"_id":11,"x":11,"iter":2},"o2":{"_id":11},"ts":{"$timestamp":{"t":1616099320,"i":12}},"t":2,"wall":{"$date":"2021-03-18T20:28:40.033Z"},"v":2,"stmtId":11,"prevOpTime":{"ts":{"$timestamp":{"t":1616099320,"i":11}},"t":2}}}}
|
[j1:rs1:n0] | 2021-03-18T20:28:40.481+00:00 D2 TENANT_M 4886009 [TenantMigrationWriter-0] "Applied tenant operation","attr":{"tenant":"tenantMigrationTenantId","migrationUuid":{"uuid":{"$uuid":"14e5e387-10eb-49b2-a428-2b979569fcce"}},"error":{"code":0,"codeName":"OK"},"op":{"oplogEntry":{"lsid":{"id":{"$uuid":"3c69fd32-e9a4-444a-97ac-8d5f76885aea"},"uid":{"$binary":{"base64":"47DEQpj8HBSa+/TImW+5JCeuQeRkm5NMpJWZG3hSuFU=","subType":"0"}}},"txnNumber":5,"op":"u","ns":"tenantMigrationTenantId_background_unique_indexes.test","ui":{"$uuid":"3d1f61d2-c66e-4fb3-9aae-29bea82cd109"},"o":{"_id":9,"x":9,"iter":2},"o2":{"_id":9},"ts":{"$timestamp":{"t":1616099320,"i":10}},"t":2,"wall":{"$date":"2021-03-18T20:28:40.032Z"},"v":2,"stmtId":9,"prevOpTime":{"ts":{"$timestamp":{"t":1616099320,"i":9}},"t":2}}}}
|
[j1:rs1:n0] | 2021-03-18T20:28:40.487+00:00 D2 TENANT_M 4886009 [TenantMigrationWriter-3] "Applied tenant operation","attr":{"tenant":"tenantMigrationTenantId","migrationUuid":{"uuid":{"$uuid":"14e5e387-10eb-49b2-a428-2b979569fcce"}},"error":{"code":0,"codeName":"OK"},"op":{"oplogEntry":{"lsid":{"id":{"$uuid":"3c69fd32-e9a4-444a-97ac-8d5f76885aea"},"uid":{"$binary":{"base64":"47DEQpj8HBSa+/TImW+5JCeuQeRkm5NMpJWZG3hSuFU=","subType":"0"}}},"txnNumber":5,"op":"u","ns":"tenantMigrationTenantId_background_unique_indexes.test","ui":{"$uuid":"3d1f61d2-c66e-4fb3-9aae-29bea82cd109"},"o":{"_id":2,"x":2,"iter":2},"o2":{"_id":2},"ts":{"$timestamp":{"t":1616099320,"i":3}},"t":2,"wall":{"$date":"2021-03-18T20:28:40.030Z"},"v":2,"stmtId":2,"prevOpTime":{"ts":{"$timestamp":{"t":1616099320,"i":2}},"t":2}}}}
|
[j1:rs1:n0] | 2021-03-18T20:28:40.487+00:00 D2 TENANT_M 4886009 [TenantMigrationWriter-3] "Applied tenant operation","attr":{"tenant":"tenantMigrationTenantId","migrationUuid":{"uuid":{"$uuid":"14e5e387-10eb-49b2-a428-2b979569fcce"}},"error":{"code":0,"codeName":"OK"},"op":{"oplogEntry":{"lsid":{"id":{"$uuid":"3c69fd32-e9a4-444a-97ac-8d5f76885aea"},"uid":{"$binary":{"base64":"47DEQpj8HBSa+/TImW+5JCeuQeRkm5NMpJWZG3hSuFU=","subType":"0"}}},"txnNumber":5,"op":"u","ns":"tenantMigrationTenantId_background_unique_indexes.test","ui":{"$uuid":"3d1f61d2-c66e-4fb3-9aae-29bea82cd109"},"o":{"_id":5,"x":5,"iter":2},"o2":{"_id":5},"ts":{"$timestamp":{"t":1616099320,"i":6}},"t":2,"wall":{"$date":"2021-03-18T20:28:40.031Z"},"v":2,"stmtId":5,"prevOpTime":{"ts":{"$timestamp":{"t":1616099320,"i":5}},"t":2}}}}
|
[j1:rs1:n0] | 2021-03-18T20:28:40.487+00:00 D2 TENANT_M 4886009 [TenantMigrationWriter-3] "Applied tenant operation","attr":{"tenant":"tenantMigrationTenantId","migrationUuid":{"uuid":{"$uuid":"14e5e387-10eb-49b2-a428-2b979569fcce"}},"error":{"code":0,"codeName":"OK"},"op":{"oplogEntry":{"lsid":{"id":{"$uuid":"3c69fd32-e9a4-444a-97ac-8d5f76885aea"},"uid":{"$binary":{"base64":"47DEQpj8HBSa+/TImW+5JCeuQeRkm5NMpJWZG3hSuFU=","subType":"0"}}},"txnNumber":5,"op":"u","ns":"tenantMigrationTenantId_background_unique_indexes.test","ui":{"$uuid":"3d1f61d2-c66e-4fb3-9aae-29bea82cd109"},"o":{"_id":6,"x":6,"iter":2},"o2":{"_id":6},"ts":{"$timestamp":{"t":1616099320,"i":7}},"t":2,"wall":{"$date":"2021-03-18T20:28:40.031Z"},"v":2,"stmtId":6,"prevOpTime":{"ts":{"$timestamp":{"t":1616099320,"i":6}},"t":2}}}}
|
|
// Got TenantMigrationAborted:
|
[js_test:background_unique_indexes] [jsTest] Got TenantMigrationAborted for command against database "tenantMigrationTenantId_background_unique_indexes" after trying 1 times, retrying the command: {
|
[js_test:background_unique_indexes] [jsTest] "n" : 12,
|
[js_test:background_unique_indexes] [jsTest] "nModified" : 12,
|
[js_test:background_unique_indexes] [jsTest] "ok" : 1,
|
[js_test:background_unique_indexes] [jsTest] "truncatedWriteErrors" : [
|
[js_test:background_unique_indexes] [jsTest] {
|
[js_test:background_unique_indexes] [jsTest] "index" : 12,
|
[js_test:background_unique_indexes] [jsTest] "code" : 325,
|
[js_test:background_unique_indexes] [jsTest] "errmsg" : "Tenant migration aborted"
|
[js_test:background_unique_indexes] [jsTest] }
|
|
// The update of _id: 24 had stmtId 12, which was incorrect!
|
[j1:rs1:n0] | 2021-03-18T20:28:45.515+00:00 D2 TENANT_M 4886009 [TenantMigrationWriter-2] "Applied tenant operation","attr":{"tenant":"tenantMigrationTenantId","migrationUuid":{"uuid":{"$uuid":"14e5e387-10eb-49b2-a428-2b979569fcce"}},"error":{"code":0,"codeName":"OK"},"op":{"oplogEntry":{"lsid":{"id":{"$uuid":"3c69fd32-e9a4-444a-97ac-8d5f76885aea"},"uid":{"$binary":{"base64":"47DEQpj8HBSa+/TImW+5JCeuQeRkm5NMpJWZG3hSuFU=","subType":"0"}}},"txnNumber":5,"op":"u","ns":"tenantMigrationTenantId_background_unique_indexes.test","ui":{"$uuid":"3d1f61d2-c66e-4fb3-9aae-29bea82cd109"},"o":{"_id":24,"x":24,"iter":2},"o2":{"_id":24},"ts":{"$timestamp":{"t":1616099325,"i":2}},"t":2,"wall":{"$date":"2021-03-18T20:28:45.442Z"},"v":2,"stmtId":12,"prevOpTime":{"ts":{"$timestamp":{"t":1616099320,"i":12}},"t":2}}}}
|
Therefore, we were missing some of the updates from the test here. So it makes sense that we got DuplicateKey error when creating an unique index on x here.
[js_test:background_unique_indexes] assert: command failed: {
|
[js_test:background_unique_indexes] "ok" : 0,
|
[js_test:background_unique_indexes] "errmsg" : "Index build failed: 22cb252c-f1a1-41a9-93cb-c40a12775a08: Collection background_unique_indexes.test ( 3d1f61d2-c66e-4fb3-9aae-29bea82cd109 ) :: caused by :: E11000 duplicate key error collection: background_unique_indexes.test index: x_1 dup key: { x: 24.0 }",
|
[js_test:background_unique_indexes] "code" : 11000,
|
[js_test:background_unique_indexes] "codeName" : "DuplicateKey",
|
[js_test:background_unique_indexes] "x" : 24
|
[js_test:background_unique_indexes] _assertCommandWorked@src/mongo/shell/assert.js:719:17
|
[js_test:background_unique_indexes] assert.commandWorked@src/mongo/shell/assert.js:811:16
|
[js_test:background_unique_indexes] @jstests/core/background_unique_indexes.js:53:5
|
[js_test:background_unique_indexes] @jstests/core/background_unique_indexes.js:16:2
|
|