non-latest WAL log corruption after EBS snapshot restore in AWS

[tonyxuqqi]

Version: RocksDB 6.29

Expected behavior

Using kPointInTimeRecovery, after EBS restore, the non-latest WAL log file should not be corrupted.

Actual behavior

The non-latest WAL file is corrupted after EBS restore.
And we also noticed that after enable track_and_verify_wals_in_manifest, some WAL files' size in manifest does not match the actual one---the actual size is bigger than the one in manifest.

"[2024/03/08 14:14:16.534 +00:00][4][WARN] [db/db_impl/db_impl_open.cc:818] /var/lib/wal/rocksdb/15557239.log: dropping 32768 bytes; Corruption: checksum mismatch
[2024/03/08 14:14:16.534 +00:00][4][WARN] [db/db_impl/db_impl_open.cc:818] /var/lib/wal/rocksdb/15557239.log: dropping 64430 bytes; Corruption: error in middle of record
[2024/03/08 14:14:16.534 +00:00][4][INFO] [db/db_impl/db_impl_open.cc:1140] Point in time recovered to log #15557239 seq #296119395244
[2024/03/08 14:14:16.534 +00:00][4][INFO] [db/db_impl/db_impl_open.cc:890] Recovering log #15557242 mode 2
[2024/03/08 14:14:16.535 +00:00][4][WARN] [db/db_impl/db_impl_open.cc:896] /var/lib/wal/rocksdb/15557242.log: dropping 36031876 bytes
[2024/03/08 14:14:16.535 +00:00][4][INFO] [db/db_impl/db_impl_open.cc:890] Recovering log #15557245 mode 2
[2024/03/08 14:14:16.536 +00:00][4][WARN] [db/db_impl/db_impl_open.cc:896] /var/lib/wal/rocksdb/15557245.log: dropping 35957673 bytes
"

Steps to reproduce the behavior

Running some heavy write workload, take the EBS snapshot and then restore it in another machine. Open the rocksdb.

[ajkr]

Could you please provide the setting you have for recycle_log_file_num? Additionally, if you have the full contents of the OPTIONS file used to write the DB, that could potentially give even more clues.

[nkg-]

TiKV uses kPointInTimeRecovery and kAbsoluteConsistency, so it has WAL recycle disabled. ie recycle_log_file_num=0.

As for WriteOptions, I only see 3 options ever being set.

• sync: Across writes, set to true (set when internal storage topology like sharding changes) and false (normal application writes)
• no_slowdown: false (default. Set sometimes. Not sure if set during this repro)
• disable_wal: false

[ajkr]

Thanks for the info.

Does TiKV also use an external syncer thread, that is, setting manual_wal_flush==true + a loop of FlushWAL(true /* sync */)?

Did your LOG file contain any occurrences of "WAL Sync error"?

Do you still have 15557239.log? I can't tell from the error message, but it would be interesting to know if this error is around the end of the log file.

[nkg-]

Does TiKV also use an external syncer thread, that is, setting manual_wal_flush==true + a loop of FlushWAL(true /* sync */)?

Great question. I think @tonyxuqqi mentioned tikv does trigger flushWAL manually, except I can't find a code reference. So @tonyxuqqi , if you can confirm.

Did your LOG file contain any occurrences of "WAL Sync error"?

Yeah. We had checked earlier. Unfortunately no "sync error". THat would have a perfect smoking gun.

Do you still have 15557239.log? I can't tell from the error message, but it would be interesting to know if this error is around the end of the log file.

We don't have the log file. Right now. But we 10s of repro per week. How can you tell if corruption is in middle or end. FWIW, what I saw was there were

• 359 records missing (compared to last readable seqnum in the corrupt wal, and first seqnum in next wal).
• Corrupt wal had 76k bytes extra. When compared to the size in the manifest. We have track wal in manifest enabled. https://github.com/facebook/rocksdb/wiki/Track-WAL-in-MANIFEST. Is it possible MANIFEST doesn't get updated, with every corresponding call to fsync WAL.

[ajkr]

This is good info. I think 359 missing records should mean the corruption was near the tail. It might be the number of records between the last FlushWAL(true /* sync */) finished and the WAL ended.

There is one bug fix I see that could be relevant: #10560

I think you said you hit this problem even before turning on WAL tracking? WAL tracking is a good feature, but important bug fixes are needed that probably are not present in version 6.29. #10185 sounds like a possible fix for the symptom you described.

[nkg-]

I think you said you hit this problem even before turning on WAL tracking?

Yes. We enabled to debug the corruption. So corruption was there before.

Both fixes seem very relevant. #10560 particularly seems to match @tonyxuqqi hypothesis we were discussing earlier this week. I can try patching this one, to fix the corruption.

And #10185 to fix the manifest tracking. We indeed see 100s/hour of size mismatches, which don't point to a corrupt WALs.

[mittalrishabh]

@ajkr can rocksdb start writing to a new WAL before previous WALs are fsynced.

[ajkr]

Hi, yes, it can. When next WAL sync is requested, though, we fsync in order from oldest unsynced WAL up to the active WAL

[mittalrishabh]

I think It doesn't mean that latest WAL file is written only after old WAL files. Filesystem can flush the blocks independently. Since the file system's flushing behavior may not guarantee the sequential writing of WAL files, is it safe to assume that the tail of the non latest WAL file is always completely written in case of unclean shutdown ?

[ajkr]

Yes you are right. As you described it, there is a valid scenario where point-in-time recovery encounters "Corruption: checksum mismatch" and does not proceed to recover the most recent log.

However, this scenario should not be enough to trigger "Corruption: SST file is ahead of WALs in CF lock". There is another fsync procedure to prevent that, which is we fsync the WALs whose data was flushed before recording the SST file to the MANIFEST.

[mittalrishabh]

Thanks, It makes sense.

[mittalrishabh]

Hi Andrew, I have put some comments on the PR #10560.

[ajkr]

Replied there - feel free to follow up there if I missed something

[mittalrishabh]

@ajkr We already have this #10185 in our TiKV branch. It appears that PingCAP cherry-picked a few changes after forking from the 6.29 release. I have attached a screenshot of the cherry-picked changes for your reference.
Based on the current code, it seems that there might be a bug in tracking wal size in manifest, or there could be missing fsync calls.
I am cherrypicking the other change #10560 to see if it resolves the issue.

[nkg-]

+1 to @mittalrishabh said. We are cherrypicking the fsync fix #10560. We will update here, if it fixes the WAL corruption.

For WAL size mismatch with manifest, as @mittalrishabh said, its already included, and we still see LOTs (every rocksdb instance shows 1 mismatch per hour) of mismatches. So wondering if its possible there is another bug in WAL size tracking. @ajkr : Is there anything we can provide to help you debug that.