Loading...

Type: Task
Resolution: Cannot Reproduce
Priority: Major - P3
Fix Version/s: None
Affects Version/s: None
Component/s: None
Labels:
None

Sprint:
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 	}

depends on

SERVER-51387 Assert that the stable timestamp is never set higher than the WT all_durable timestamp

Closed

is related to

WT-6747 Add prepare support in checkpoint test

Closed

WT-6748 Set different timestamps for prepared updates in timestamp abort

Closed

WT-6749 Write a python test for update restore of prepared updates

Closed

Details

Description

Attachments

Issue Links

Activity

People

Dates