Re: Failed to start mysql due to start_lsn and ens_lsn issue

[Jakub Lopuszanski]

Sir, do you recall what were you doing on Aug 3 14:17, which could somehow explain why the files #ib_redo27245 and #ib_redo27249 present this as last modification date (which appears to be fresher than that of other redo log files)? :)

I see that:
#ib_redo27250 has start_lsn 0x67bc77a400
#ib_redo27249 has start_lsn 0x67c284ac00
which indeed looks like ib_redo27250 has too small value.
Also, given that the validation loop at the boot goes through redo log files in the order of their ids, and it didn't complain about ib_redo27245,ib_redo27246,ib_redo27247,ib_redo27248, nor ib_redo27249, this is all quite strange, as it suggests, that somehow these five files are correctly chained together, and it is the #ib_redo27250 which breaks the chain, even though it was modified Aug 2, which is before the #ib_redo27249 touched on Aug 3.
Very puzzling.

Also, assuming that you did no resize operation, each file should have 3276800 bytes and thus span 3276800 - 2048 = 3274752 lsns.
The two numbers 0x67bc77a400 and 0x67c284ac00 seem to belong to the same arithmetic sequence:
(0x67c284ac00 - 0x67bc77a400)/(3276800-2048) == 31
it's just like #ib_redo27250's header is from "31 files before" the #ib_redo27249 - from #ib_redo27218?
This makes "some" sense, because InnoDB reuses old files in circular fashion, and indeed tries to keep ~32 of them, so (-31)-th file would become (+1)-th.
However, when doing so, we first rename it to #ib_redo27218_tmp, overwrite its header to have new start_lsn, and only then rename it back to #ib_redo27250, so it's unclear to me how we could end up with having new file name #ib_redo27250 with the old header...
...unless there's some race condition at I/O layer and metadata gets flushed to stable storage before the actual data.


Thanks for filing the bug - yes please include everything, or at least link back to this thread so there's enough context.

Indeed looking into log_files_create_file()
https://github.com/mysql/mysql-server/blob/mysql-8.0.30/storage/innobase/log/log0files_governor.cc#L1496-L1510
I don't see any explicit fsync operation between (or inside) log_files_prepare_unused_file() which writes the header and log_mark_file_as_in_use() which renames the file.

Also, thanks for running `ls -l` which provided more info than -lh :)