[MDEV-27538] MariaDB server startup crash Created: 2022-01-18  Updated: 2023-08-03  Resolved: 2022-02-23

Status: Closed
Project: MariaDB Server
Component/s: Server
Affects Version/s: 10.5.12
Fix Version/s: N/A

Type: Bug Priority: Critical
Reporter: Ladislav Vaiz Assignee: Unassigned
Resolution: Incomplete Votes: 0
Labels: None
Environment:

Debian Linux 11 Bullseye, package from backports 1:10.5.12-0+deb11u1

Issue Links:
Relates
relates to MDEV-13542 Crashing on a corrupted page is unhel... Closed

 Description   

MariaDB server crash on startup. Gdb output:

2022-01-18 16:26:39 0 [Note] InnoDB: Starting in background the rollback of recovered transactions
2022-01-18 16:26:39 0x7fff94ff9700 InnoDB: Assertion failure in file ./storage/innobase/include/fut0lst.h line 127
InnoDB: Failing assertion: addr.page == FIL_NULL || addr.boffset >= FIL_PAGE_DATA
InnoDB: We intentionally generate a memory trap.
InnoDB: Submit a detailed bug report to https://jira.mariadb.org/
InnoDB: If you get repeated assertion failures or crashes, even
InnoDB: immediately after the mysqld startup, there may be
InnoDB: corruption in the InnoDB tablespace. Please refer to
InnoDB: https://mariadb.com/kb/en/library/innodb-recovery-modes/
InnoDB: about forcing recovery.
2022-01-18 16:26:39 0 [Note] InnoDB: Removed temporary tablespace data file: "ibtmp1"
2022-01-18 16:26:39 0 [Note] InnoDB: Creating shared tablespace for temporary tables
2022-01-18 16:26:39 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
2022-01-18 16:26:39 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
2022-01-18 16:26:39 0 [Note] InnoDB: 10.5.12 started; log sequence number 22269595570370; transaction id 796568243
2022-01-18 16:26:39 0 [Note] InnoDB: Loading buffer pool(s) from /var/lib/mysql/ib_buffer_pool
2022-01-18 16:26:39 0 [Note] Plugin 'FEEDBACK' is disabled.

Thread 23 "mysqld" received signal SIGABRT, Aborted.
[Switching to Thread 0x7fff94ff9700 (LWP 918832)]
__GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
50 ../sysdeps/unix/sysv/linux/raise.c: No such file or directory.
(gdb) bt
#0 __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
#1 0x00007ffff7568537 in __GI_abort () at abort.c:79
#2 0x0000555555b8370e in ut_dbg_assertion_failed (expr=expr@entry=0x5555565b3380 "addr.page == FIL_NULL || addr.boffset >= FIL_PAGE_DATA",
file=file@entry=0x5555565b3358 "./storage/innobase/include/fut0lst.h", line=line@entry=127) at ./storage/innobase/ut/ut0dbg.cc:60
#3 0x0000555555b9df1d in flst_read_addr (faddr=<optimized out>) at ./storage/innobase/include/fut0lst.h:127
#4 0x0000555555b9dfb1 in flst_read_addr (faddr=<optimized out>) at ./storage/innobase/include/fut0lst.h:128
#5 flst_get_first (base=<optimized out>) at ./storage/innobase/include/fut0lst.h:135
#6 flst_add_first (base=<optimized out>, boffset=<optimized out>, add=0x7fffd4034d00, aoffset=<optimized out>, mtr=0x7fff94ff8570) at ./storage/innobase/fut/fut0lst.cc:284
#7 0x0000555556252638 in trx_purge_add_undo_to_history (trx=trx@entry=0x7ffff43da0d0, undo=@0x7ffff43db0b0: 0x555557bbaa98, mtr=mtr@entry=0x7fff94ff8570) at ./storage/innobase/trx/trx0purge.cc:298
#8 0x0000555556269016 in trx_write_serialisation_history (trx=0x7ffff43da0d0, mtr=0x7fff94ff8570) at ./storage/innobase/trx/trx0trx.cc:1093
#9 0x00005555562692e2 in trx_t::commit_low (this=0x7ffff43da0d0, mtr=0x7fff94ff8570) at ./storage/innobase/trx/trx0trx.cc:1469
#10 0x000055555626942f in trx_t::commit (this=this@entry=0x7ffff43da0d0) at ./storage/innobase/trx/trx0trx.cc:1507
#11 0x0000555556260a92 in trx_t::rollback_finish (this=0x7ffff43da0d0) at ./storage/innobase/trx/trx0roll.cc:65
#12 trx_rollback_active (trx=0x7ffff43da0d0) at ./storage/innobase/trx/trx0roll.cc:633
#13 0x0000555556260ec9 in trx_rollback_recovered (all=true) at ./storage/innobase/trx/trx0roll.cc:783
#14 0x0000555555b81b88 in trx_rollback_all_recovered () at ./storage/innobase/trx/trx0roll.cc:837
#15 0x00007ffff7a29ea7 in start_thread (arg=<optimized out>) at pthread_create.c:477
#16 0x00007ffff7640def in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
(gdb)

 Comments   
Comment by Marko Mäkelä [ 2022-01-18 ]

Yes, InnoDB is crash-happy when it encounters corrupted data, such as undo log corruption in this case. It should be able to start up with innodb_force_recovery=3 or innodb_force_recovery=5 so that you can rescue your data.

Are there any hints to what caused the corruption? What operations were performed on the data directory earlier? Was a backup restored? Was the ib_logfile0 deleted or the setting innodb_force_recovery=6 used in the past?

Comment by Ladislav Vaiz [ 2022-01-26 ]

I have initialized /var/lib/mysql and recovered databases from backup.
From my point of view this issue can be closed, thanks.

Comment by Elena Stepanova [ 2022-02-23 ]

I guess without any information how the corruption occurred in the first place, there is nothing that can be done about it.

Comment by Marko Mäkelä [ 2023-08-03 ]

MDEV-13542 fixed many cases like this, but not this particular one:

  /* We are in transaction commit; we cannot return an error
 
  when detecting corruption. It is better to crash the server
 
  than to intentionally violate ACID by committing something
 
  that is known to be corrupted. */
 
  ut_a(flst_add_first(rseg_header, TRX_RSEG + TRX_RSEG_HISTORY, undo_page,
 
                      uint16_t(page_offset(undo_header) +
 
                               TRX_UNDO_HISTORY_NODE), mtr) == DB_SUCCESS);

Generated at Thu Feb 08 09:53:40 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.