Uploaded image for project: 'WiredTiger'
  1. WiredTiger
  2. WT-6733

Investigate partial prepared transaction in a checkpoint

    • Type: Icon: Task Task
    • Resolution: Cannot Reproduce
    • Priority: Icon: Major - P3 Major - P3
    • None
    • Affects Version/s: None
    • Component/s: None
    • None
    • Storage - Ra 2020-10-05, Storage - Ra 2020-11-30

      We hit a background validation error in mongodb, which detects there are 14 extra indexes. Later, we find some of the corresponding collection records that belong to the same prepared transaction are missing from the checkpoint. Note that the prepared transaction is stable so rollback to stable should not be involved.

      Investigate the root cause of this issue.

      [ShardedClusterFixture:job1:shard1:primary] 2020-09-02T01:50:13.047+0100 | 2020-09-02T01:50:13.047+01:00 I  INDEX    20305   [conn241] "Index inconsistencies were detected. Starting the second phase of index validation to gather concise errors","attr":{"namespace":"test.jstests_single_batch"}
      [ShardedClusterFixture:job1:shard1:primary] 2020-09-02T01:50:13.047+0100 | 2020-09-02T01:50:13.047+01:00 I  INDEX    20297   [conn241] "Starting to traverse through all the document key sets"
      [ShardedClusterFixture:job1:shard1:primary] 2020-09-02T01:50:13.047+0100 | 2020-09-02T01:50:13.047+01:00 I  INDEX    20298   [conn241] "Finished traversing through all the document key sets"
      [ShardedClusterFixture:job1:shard1:primary] 2020-09-02T01:50:13.047+0100 | 2020-09-02T01:50:13.047+01:00 I  INDEX    20299   [conn241] "Starting to traverse through all the indexes"
      [ShardedClusterFixture:job1:shard1:primary] 2020-09-02T01:50:13.047+0100 | 2020-09-02T01:50:13.047+01:00 I  INDEX    20300   [conn241] "Traversing through the index entries","attr":{"index":"_id_"}
      [ShardedClusterFixture:job1:shard1:primary] 2020-09-02T01:50:13.047+0100 | 2020-09-02T01:50:13.047+01:00 I  INDEX    20300   [conn241] "Traversing through the index entries","attr":{"index":"_id_hashed"}
      [ShardedClusterFixture:job1:shard1:primary] 2020-09-02T01:50:13.047+0100 | 2020-09-02T01:50:13.047+01:00 I  INDEX    20301   [conn241] "Finished traversing through all the indexes"
      [ShardedClusterFixture:job1:shard1:primary] 2020-09-02T01:50:13.047+0100 | 2020-09-02T01:50:13.047+01:00 I  INDEX    20302   [conn241] "Validation complete -- Corruption found","attr":{"namespace":"test.jstests_single_batch","uuid":" (UUID: c28d1ae3-f309-4148-8606-5bfced80ab33)"}
      [ShardedClusterFixture:job1:shard1:primary] 2020-09-02T01:50:13.047+0100 | 2020-09-02T01:50:13.048+01:00 I  COMMAND  51803   [conn241] "Slow query","attr":{"type":"command","ns":"test.$cmd","appName":"MongoDB Shell","command":{"validate":"jstests_single_batch","full":true,"lsid":{"id":{"$uuid":"4c590050-f98a-4aa4-8891-93d5b234f2ce"}},"$clusterTime":{"clusterTime":{"$timestamp":{"t":1599007810,"i":13}},"signature":{"hash":{"$binary":{"base64":"AAAAAAAAAAAAAAAAAAAAAAAAAAA=","subType":"0"}},"keyId":0}},"$readPreference":{"mode":"secondaryPreferred"},"$db":"test"},"numYields":0,"reslen":1974,"locks":{"ParallelBatchWriterMode":{"acquireCount":{"r":1}},"ReplicationStateTransition":{"acquireCount":{"w":1}},"Global":{"acquireCount":{"w":1}},"Database":{"acquireCount":{"w":1}},"Collection":{"acquireCount":{"W":1}},"Mutex":{"acquireCount":{"r":1}}},"flowControl":{"acquireCount":1},"storage":{"data":{"bytesRead":15731337,"timeReadingMicros":7996}},"protocol":"op_msg","durationMillis":47}
      [ValidateCollections:job1:single_batch:ValidateCollections] 2020-09-02T01:50:13.049+0100 Collection validation failed on host localhost:20253 with response: {
      [ValidateCollections:job1:single_batch:ValidateCollections] 2020-09-02T01:50:13.049+0100 	"ns" : "test.jstests_single_batch",
      [ValidateCollections:job1:single_batch:ValidateCollections] 2020-09-02T01:50:13.049+0100 	"nInvalidDocuments" : 0,
      [ValidateCollections:job1:single_batch:ValidateCollections] 2020-09-02T01:50:13.049+0100 	"nrecords" : 8,
      [ValidateCollections:job1:single_batch:ValidateCollections] 2020-09-02T01:50:13.049+0100 Collection validation failed on host localhost:20253 with response: {
      [ValidateCollections:job1:single_batch:ValidateCollections] 2020-09-02T01:50:13.049+0100 	"ns" : "test.jstests_single_batch",
      [ValidateCollections:job1:single_batch:ValidateCollections] 2020-09-02T01:50:13.049+0100 	"nInvalidDocuments" : 0,
      [ValidateCollections:job1:single_batch:ValidateCollections] 2020-09-02T01:50:13.049+0100 	"nrecords" : 8,
      [ValidateCollections:job1:single_batch:ValidateCollections] 2020-09-02T01:50:13.050+0100 	"nIndexes" : 2,
      [ValidateCollections:job1:single_batch:ValidateCollections] 2020-09-02T01:50:13.050+0100 	"keysPerIndex" : {
      [ValidateCollections:job1:single_batch:ValidateCollections] 2020-09-02T01:50:13.050+0100 		"_id_" : 15,
      [ValidateCollections:job1:single_batch:ValidateCollections] 2020-09-02T01:50:13.050+0100 		"_id_hashed" : 15
      [ValidateCollections:job1:single_batch:ValidateCollections] 2020-09-02T01:50:13.050+0100 	},
      [ValidateCollections:job1:single_batch:ValidateCollections] 2020-09-02T01:50:13.050+0100 	"indexDetails" : {
      [ValidateCollections:job1:single_batch:ValidateCollections] 2020-09-02T01:50:13.050+0100 		"_id_" : {
      [ValidateCollections:job1:single_batch:ValidateCollections] 2020-09-02T01:50:13.050+0100 			"valid" : false
      [ValidateCollections:job1:single_batch:ValidateCollections] 2020-09-02T01:50:13.050+0100 		},
      [ValidateCollections:job1:single_batch:ValidateCollections] 2020-09-02T01:50:13.050+0100 		"_id_hashed" : {
      [ValidateCollections:job1:single_batch:ValidateCollections] 2020-09-02T01:50:13.050+0100 			"valid" : false
      [ValidateCollections:job1:single_batch:ValidateCollections] 2020-09-02T01:50:13.050+0100 		}
      [ValidateCollections:job1:single_batch:ValidateCollections] 2020-09-02T01:50:13.050+0100 	},
      [ValidateCollections:job1:single_batch:ValidateCollections] 2020-09-02T01:50:13.050+0100 	"valid" : false,
      [ValidateCollections:job1:single_batch:ValidateCollections] 2020-09-02T01:50:13.050+0100 	"repaired" : false,
      [ValidateCollections:job1:single_batch:ValidateCollections] 2020-09-02T01:50:13.050+0100 	"warnings" : [
      [ValidateCollections:job1:single_batch:ValidateCollections] 2020-09-02T01:50:13.050+0100 		"Detected 14 extra index entries."
      [ValidateCollections:job1:single_batch:ValidateCollections] 2020-09-02T01:50:13.050+0100 	],
      [ValidateCollections:job1:single_batch:ValidateCollections] 2020-09-02T01:50:13.050+0100 	"errors" : [
      [ValidateCollections:job1:single_batch:ValidateCollections] 2020-09-02T01:50:13.050+0100 		"Index with name '_id_' has inconsistencies.",
      [ValidateCollections:job1:single_batch:ValidateCollections] 2020-09-02T01:50:13.050+0100 		"Index with name '_id_hashed' has inconsistencies."
      [ValidateCollections:job1:single_batch:ValidateCollections] 2020-09-02T01:50:13.050+0100 	"nIndexes" : 2,
      [ValidateCollections:job1:single_batch:ValidateCollections] 2020-09-02T01:50:13.050+0100 	"keysPerIndex" : {
      [ValidateCollections:job1:single_batch:ValidateCollections] 2020-09-02T01:50:13.050+0100 		"_id_" : 15,
      [ValidateCollections:job1:single_batch:ValidateCollections] 2020-09-02T01:50:13.050+0100 		"_id_hashed" : 15
      [ValidateCollections:job1:single_batch:ValidateCollections] 2020-09-02T01:50:13.050+0100 	}
      

            Assignee:
            chenhao.qu@mongodb.com Chenhao Qu
            Reporter:
            chenhao.qu@mongodb.com Chenhao Qu
            Votes:
            0 Vote for this issue
            Watchers:
            8 Start watching this issue

              Created:
              Updated:
              Resolved: