Error handling was refactored in MDEV-13542 and in a few related tickets. The aim was that data corruption should no longer crash the server but result in errors being reported.
wk_bradp, can you provide a copy of a data directory on which MariaDB Server 10.6.9 fails to start up, and 10.6.8 does start up?
MDEV-29383 is a crash recovery bug that was introduced in MariaDB Server 10.6.9. It could potentially explain this.
Thanks for looking into this, Marko! I don't think I can provide a copy of the data directory for any of these servers because it does contain customer data. I haven't tried to reproduce this issue in a testing environment yet. But I can say that it started with 10.6.9 and hasn't happened again since the rollback to 10.6.8.
I can try to run some tests to try to reproduce the crash if needed but it does sound like that crash recovery bug you mentioned might be related.
Also, just to be clear on the order of things. I didn't downgrade to fix the data corruption, I used innodb_force_recovery=1 to ignore the problem. Only after that did I downgrade to 10.6.8. Meaning, I didn't downgrade to get it to start up, I downgraded to prevent the corruption from happening again. Just wanted to make that clear but let me know if it's not
Also, let me know what you need from me and I'll be happy to provide it. 
wk_bradp, thank you, and sorry for introducing MDEV-29383. I am now convinced that it can have caused your recovery trouble. Specifically, since your corruption looks like something with the undo logs, the culprit could be a change to trx_purge_free_segment().
Ironically, the corruption was caused by MDEV-13542, the very change that aimed to improve our handling of data corruption. Even though the changes were tested very extensively internally, we did not catch the problem until this week, almost 3 months after the change had been implemented.
I think that you’d better stay at 10.6.8 until a 10.6.10 release is available.
Thanks so much for looking into this Marko! I'll leave our systems on 10.6.8 until the next patch is released.
I'll close it as a duplicate then, but please, do comment if the next release won't fix the issue
I am reopening this, because mleich provided an rr replay trace of something that reproduces exactly this message, even when the fix of MDEV-29383 is present.
What I found out so far:
- The problematic page 10:255 is an index page that was freed near LSN 0x40296d.
- The first recovered record for the page at LSN 0x3fee0f fails to apply because the page was read back as all-zero.
- I did not check yet if a FREE_PAGE record for the page had been written or if it was ignored by recovery.
It turns out that we fail to write a FREE_PAGE record (it can only be written by invoking mtr_t::free()) for the following operation:
|
bb-10.6-MDEV-19229 23ab688cec4b3031262bc93921592a04749a4341 |
#2 0x0000564aad8eacef in buf_page_t::set_freed (this=0x7fb1125e7120,
|
prev_state=1610612739, count=0)
|
at /data/Server/bb-10.6-MDEV-19229/storage/innobase/include/buf0buf.h:741
|
#3 0x0000564aadca9fc5 in buf_page_free (space=0x612000041740, page=255,
|
mtr=0x7fb10f496ae0)
|
at /data/Server/bb-10.6-MDEV-19229/storage/innobase/buf/buf0buf.cc:2130
|
#4 0x0000564aadc00c2d in btr_page_free (index=0x6160008ba208,
|
block=0x7fb1125e7120, mtr=0x7fb10f496ae0, blob=false, space_latched=false)
|
at /data/Server/bb-10.6-MDEV-19229/storage/innobase/btr/btr0btr.cc:657
|
#5 0x0000564aadc186da in btr_compress (cursor=0x61a00000a9a8, adjust=false,
|
mtr=0x7fb10f496ae0)
|
at /data/Server/bb-10.6-MDEV-19229/storage/innobase/btr/btr0btr.cc:3964
|
#6 0x0000564aadc68034 in btr_cur_compress_if_useful (cursor=0x61a00000a9a8,
|
adjust=false, mtr=0x7fb10f496ae0)
|
at /data/Server/bb-10.6-MDEV-19229/storage/innobase/btr/btr0cur.cc:5406
|
#7 0x0000564aadc6b3d8 in btr_cur_pessimistic_delete (err=0x7fb10f4967d0,
|
has_reserved_extents=0, cursor=0x61a00000a9a8, flags=0, rollback=false,
|
mtr=0x7fb10f496ae0)
|
at /data/Server/bb-10.6-MDEV-19229/storage/innobase/btr/btr0cur.cc:5863
|
#8 0x0000564aadac19fa in row_purge_remove_clust_if_poss_low (
|
node=0x61a00000a908, mode=522)
|
at /data/Server/bb-10.6-MDEV-19229/storage/innobase/row/row0purge.cc:220
|
Due to the missing record for freeing the page, the recovery will attempt to load the page and fail, as follows.
2022-08-29 9:26:51 0 [Note] InnoDB: Starting final batch to recover 143 pages from redo log.
|
2022-08-29 9:26:53 0 [ERROR] InnoDB: Plugin initialization aborted at srv0start.cc[1555] with error Data structure corruption
|
I must make the failure diagnostics more verbose; it was probably "cleaned up" too much in MDEV-13542.
The root cause of this failure does not look like a recent regression. I think that it will affect 10.5 as well. 10.5 has a compatible log format, and it would crash on this corrupted data directory:
|
10.5 29fa9bcee01cf5457c096bf37bb25c84ddee5a30 |
2022-08-31 11:37:26 0 [Note] InnoDB: Starting final batch to recover 143 pages from redo log.
|
mariadbd: /mariadb/10.5/storage/innobase/log/log0recv.cc:270: log_phys_t::apply_status log_phys_t::apply(const buf_block_t&, uint16_t&) const: Assertion `mach_read_from_4(frame + 4U) == block.page.id().page_no()' failed.
|
The root cause turns out to be that a write of a FREE_PAGE record is being skipped due to an early return here:
#0 fseg_free_page_low (seg_inode=0x7fb112adc0f2 "", iblock=0x7fb1125ebe50,
|
space=0x612000041740, offset=255, mtr=0x7fb10f496ae0, ahi=false)
|
at /data/Server/bb-10.6-MDEV-19229/storage/innobase/fsp/fsp0fsp.cc:2596
|
#1 0x0000564aaddfcef7 in fseg_free_page (seg_header=0x7fb112ae004a "",
|
space=0x612000041740, offset=255, mtr=0x7fb10f496ae0, have_latch=false)
|
at /data/Server/bb-10.6-MDEV-19229/storage/innobase/fsp/fsp0fsp.cc:2629
|
#2 0x0000564aadc00b9e in btr_page_free (index=0x6160008ba208,
|
block=0x7fb1125e7120, mtr=0x7fb10f496ae0, blob=false, space_latched=false)
|
at /data/Server/bb-10.6-MDEV-19229/storage/innobase/btr/btr0btr.cc:650
|
#3 0x0000564aadc186da in btr_compress (cursor=0x61a00000a9a8, adjust=false,
|
mtr=0x7fb10f496ae0)
|
at /data/Server/bb-10.6-MDEV-19229/storage/innobase/btr/btr0btr.cc:3964
|
The culprit is an accidentally added extra return err; statement. (Only in case of an error, we should not write the FREE_PAGE record.)
if (UNIV_UNLIKELY(err != DB_SUCCESS)) { |
return err; |
}
|
return err; |
}
|
|
|
mtr->free(*space, static_cast<uint32_t>(offset)); |
return DB_SUCCESS; |
}
|
As part of fixing this, I am going to add some error messages to identify the corrupted page:
innodb.corrupted_during_recovery 'innodb' w20 [ fail ] Found warnings/errors in server log file!
|
Test ended at 2022-08-31 13:12:59
|
line
|
2022-08-31 13:12:56 0 [ERROR] InnoDB: Unable to apply log to corrupted page [page id: space=5, page number=3]; set innodb_force_recovery to ignore
|
2022-08-31 13:12:58 0 [Warning] InnoDB: Discarding log for corrupted page [page id: space=5, page number=3]
|
Summary: a crash shortly after a page merge (can be triggered by an UPDATE or DELETE or, say, rollback of an INSERT) can cause data corruption.