[SERVER-55364] Investigate DuplicateKey error for createIndex command in background_unique_indexes.js in tenant migration stepdown/kill/terminate suites Created: 19/Mar/21  Updated: 27/Oct/23  Resolved: 06/Apr/21

Status: Closed
Project: Core Server
Component/s: Replication
Affects Version/s: None
Fix Version/s: None

Type: Bug Priority: Major - P3
Reporter: Cheahuychou Mao Assignee: Lingzhi Deng
Resolution: Gone away Votes: 0
Labels: pm-1791_non-cloud-blocking
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Issue Links:
Depends
is depended on by SERVER-52713 [testing] Add stepdown/kill/terminate... Closed
Problem/Incident
is caused by SERVER-55366 inject_tenant_prefix.js should not mo... Closed
Related
related to SERVER-55810 Complete TODO listed in SERVER-55364 Closed
Operating System: ALL
Sprint: Repl 2021-04-19
Participants:

 Description   

The command to create unique index in the test consistently fails the stepdown/kill/terminate suites.

[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] 	"keyPattern" : {
[js_test:background_unique_indexes] 		"x" : 1
[js_test:background_unique_indexes] 	},
[js_test:background_unique_indexes] 	"keyValue" : {
[js_test:background_unique_indexes] 		"x" : 24
[js_test:background_unique_indexes] 	},
[js_test:background_unique_indexes] 	"$clusterTime" : {
[js_test:background_unique_indexes] 		"clusterTime" : Timestamp(1616099326, 143),
[js_test:background_unique_indexes] 		"signature" : {
[js_test:background_unique_indexes] 			"hash" : BinData(0,"AAAAAAAAAAAAAAAAAAAAAAAAAAA="),
[js_test:background_unique_indexes] 			"keyId" : NumberLong(0)
[js_test:background_unique_indexes] 		}
[js_test:background_unique_indexes] 	},
[js_test:background_unique_indexes] 	"operationTime" : Timestamp(1616099326, 143)
[js_test:background_unique_indexes] } with original command request: {
[js_test:background_unique_indexes] 	"createIndexes" : "test",
[js_test:background_unique_indexes] 	"indexes" : [
[js_test:background_unique_indexes] 		{
[js_test:background_unique_indexes] 			"key" : {
[js_test:background_unique_indexes] 				"x" : 1
[js_test:background_unique_indexes] 			},
[js_test:background_unique_indexes] 			"name" : "x_1",
[js_test:background_unique_indexes] 			"background" : true,
[js_test:background_unique_indexes] 			"unique" : true
[js_test:background_unique_indexes] 		}
[js_test:background_unique_indexes] 	],
[js_test:background_unique_indexes] 	"lsid" : {
[js_test:background_unique_indexes] 		"id" : UUID("3c69fd32-e9a4-444a-97ac-8d5f76885aea")
[js_test:background_unique_indexes] 	},
[js_test:background_unique_indexes] 	"$clusterTime" : {
[js_test:background_unique_indexes] 		"clusterTime" : Timestamp(1616099326, 136),
[js_test:background_unique_indexes] 		"signature" : {
[js_test:background_unique_indexes] 			"hash" : BinData(0,"AAAAAAAAAAAAAAAAAAAAAAAAAAA="),
[js_test:background_unique_indexes] 			"keyId" : NumberLong(0)
[js_test:background_unique_indexes] 		}
[js_test:background_unique_indexes] 	},
[js_test:background_unique_indexes] 	"writeConcern" : {
[js_test:background_unique_indexes] 		"w" : "majority",
[js_test:background_unique_indexes] 		"wtimeout" : 300321
[js_test:background_unique_indexes] 	},
[js_test:background_unique_indexes] 	"comment" : {
[js_test:background_unique_indexes] 		"isCmdObjWithTenantId" : true
[js_test:background_unique_indexes] 	}
[js_test:background_unique_indexes] } on connection: connection to localhost:20252
[js_test:background_unique_indexes] _getErrorWithCode@src/mongo/shell/utils.js:25:13
[js_test:background_unique_indexes] doassert@src/mongo/shell/assert.js:18:14
[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



 Comments   
Comment by Lingzhi Deng [ 06/Apr/21 ]

Fixed by SERVER-55366

Comment by Lingzhi Deng [ 06/Apr/21 ]

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

Generated at Thu Feb 08 05:36:15 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.