Major - P3 mongodb single_batch.js test very rarely fails collection validation.
[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 }
In the failure, the data are missing from the collection but present on the indexes thus manifesting as an extra index validation failure.
[1600742308:370729][34908:0x7f944bb89740], wt, txn-recover: [WT_VERB_RECOVERY] Recovery checkpoint_timestamp 5f4eec420000000d [1600742308:370741][34908:0x7f944bb89740], wt, txn-recover: [WT_VERB_RECOVERY | WT_VERB_RECOVERY_PROGRESS] Set global recovery timestamp: (1599007810, 13) [1600742308:370748][34908:0x7f944bb89740], wt, txn-recover: [WT_VERB_RECOVERY] Recovery oldest_timestamp 5f4eec3d0000000d [1600742308:370753][34908:0x7f944bb89740], wt, txn-recover: [WT_VERB_RECOVERY | WT_VERB_RECOVERY_PROGRESS] Set global oldest timestamp: (1599007805, 13) [1600742308:370763][34908:0x7f944bb89740], wt, txn-recover: [WT_VERB_TIMESTAMP] Timestamp (1599007805, 13): Updated pinned timestamp [1600742308:371145][34908:0x7f944bb89740], wt, txn-recover: [WT_VERB_RTS] Performing recovery rollback_to_stable with stable timestamp: (1599007810, 13) and oldest timestamp: (1599007805, 13)
The missing data are before the durable timestamp of the checkpoint presented in the data files, thus it should be included in the checkpoint but they are missing.
Looking at the wiredtiger log, we confirmed that the missing data have been applied to the log with each insertion to the collection table accompanied by two additional insertions to the two indexes table.
{ "lsn" : [7,1129600],
"hdr_flags" : "compressed",
"rec_len" : 394240,
"mem_len" : 8389333,
"type" : "commit",
"txnid" : 1083,
"ops": [
{ "optype": "txn_timestamp",
"time_sec": 1599007809,
"time_nsec": 471658300,
"commit_ts": 0,
"durable_ts": 0,
"first_commit_ts": 0,
"prepare_ts": 0,
"read_ts": 6867686245703614473
},
{ "optype": "row_put",
"fileid": 2147483788 0x8000008c,
"key": "\u0088",
"key-hex": "88",
"value-bson":
{u'_id': 10.0,
},
{ "optype": "row_put",
"fileid": 2147483789 0x8000008d,
"key": "+\u0014\u0004",
"key-hex": "2b1404",
"value": "\u0000@\u0001",
"value-hex": "004001"
},
{ "optype": "row_put",
"fileid": 2147483790 0x8000008e,
"key": "2\u00d7\u008d|\u0000#l\u00f5Z\u0004\u0000@",
"key-hex": "32d78d7c00236cf55a040040",
"value": "\u0002",
"value-hex": "02"
},
{ "optype": "row_put",
"fileid": 2147483788 0x8000008c,
"key": "\u0089",
"key-hex": "89",
"value-bson":
{u'_id': 13.0,
},
{ "optype": "row_put",
"fileid": 2147483789 0x8000008d,
"key": "+\u001a\u0004",
"key-hex": "2b1a04",
"value": "\u0000H\u0001",
"value-hex": "004801"
},
{ "optype": "row_put",
"fileid": 2147483790 0x8000008e,
"key": "2\u00ba;Me\u001c\u00bd\u0015r\u0004\u0000H",
"key-hex": "32ba3b4d651cbd1572040048",
"value": "\u0002",
"value-hex": "02"
},
{ "optype": "row_put",
"fileid": 2147483788 0x8000008c,
"key": "\u008a",
"key-hex": "8a",
"value-bson":
{u'_id': 14.0,
},
{ "optype": "row_put",
"fileid": 2147483789 0x8000008d,
"key": "+\u001c\u0004",
"key-hex": "2b1c04",
"value": "\u0000P\u0001",
"value-hex": "005001"
},
{ "optype": "row_put",
"fileid": 2147483790 0x8000008e,
"key": "2\u00fd\u009at/\u00dc\u00d1~\u0002\u0004\u0000P",
"key-hex": "32fd9a742fdcd17e02040050",
"value": "\u0002",
"value-hex": "02"
},
{ "optype": "row_put",
"fileid": 2147483788 0x8000008c,
"key": "\u008b",
"key-hex": "8b",
"value-bson":
{u'_id': 15.0,
},
{ "optype": "row_put",
"fileid": 2147483789 0x8000008d,
"key": "+\u001e\u0004",
"key-hex": "2b1e04",
"value": "\u0000X\u0001",
"value-hex": "005801"
},
{ "optype": "row_put",
"fileid": 2147483790 0x8000008e,
"key": "2\u00ba\u0013#\u0017\u00a03u\u00b8\u0004\u0000X",
"key-hex": "32ba132317a03375b8040058",
"value": "\u0002",
"value-hex": "02"
},
{ "optype": "row_put",
"fileid": 2147483788 0x8000008c,
"key": "\u008c",
"key-hex": "8c",
"value-bson":
{u'_id': 16.0,
},
{ "optype": "row_put",
"fileid": 2147483789 0x8000008d,
"key": "+ \u0004",
"key-hex": "2b2004",
"value": "\u0000`\u0001",
"value-hex": "006001"
},
{ "optype": "row_put",
"fileid": 2147483790 0x8000008e,
"key": "2H\u001c!\u00e3\u008c\f\u00b8h\u0004\u0000`",
"key-hex": "32481c21e38c0cb868040060",
"value": "\u0002",
"value-hex": "02"
},
{ "optype": "row_put",
"fileid": 2147483788 0x8000008c,
"key": "\u008d",
"key-hex": "8d",
"value-bson":
{u'_id': 17.0,
},
{ "optype": "row_put",
"fileid": 2147483789 0x8000008d,
"key": "+\"\u0004",
"key-hex": "2b2204",
"value": "\u0000h\u0001",
"value-hex": "006801"
},
{ "optype": "row_put",
"fileid": 2147483790 0x8000008e,
"key": "2oXR\u00eb\u00c7\u00b0\u00e2\u00da\u0004\u0000h",
"key-hex": "326f5852ebc7b0e2da040068",
"value": "\u0002",
"value-hex": "02"
},
{ "optype": "row_put",
"fileid": 2147483788 0x8000008c,
"key": "\u008e",
"key-hex": "8e",
"value-bson":
{u'_id': 18.0,
},
{ "optype": "row_put",
"fileid": 2147483789 0x8000008d,
"key": "+$\u0004",
"key-hex": "2b2404",
"value": "\u0000p\u0001",
"value-hex": "007001"
},
{ "optype": "row_put",
"fileid": 2147483790 0x8000008e,
"key": "2\u00df\u00fe\u00f3\u00f0\u008a\u0001\u00ac\u00fa\u0004\u0000p",
"key-hex": "32dffef3f08a01acfa040070",
"value": "\u0002",
"value-hex": "02"
},
{ "optype": "row_put",
"fileid": 2147483788 0x8000008c,
"key": "\u008f",
"key-hex": "8f",
"value-bson":
{u'_id': 19.0,
},
{ "optype": "row_put",
"fileid": 2147483789 0x8000008d,
"key": "+&\u0004",
"key-hex": "2b2604",
"value": "\u0000x\u0001",
"value-hex": "007801"
},
{ "optype": "row_put",
"fileid": 2147483790 0x8000008e,
"key": "2\u00ae\u00bc\u009ak8\u00d5s\u00e8\u0004\u0000x",
"key-hex": "32aebc9a6b38d573e8040078",
"value": "\u0002",
"value-hex": "02"
},
{ "optype": "txn_timestamp",
"time_sec": 1599007810,
"time_nsec": 173659400,
"commit_ts": 6867686249998581769,
"durable_ts": 6867686249998581771,
"first_commit_ts": 6867686249998581769,
"prepare_ts": 6867686249998581769,
"read_ts": 0
}
]
},
This issue rarely reproduce. Only two occurrences in 8 months.