[MDEV-33114] mariadb server fails to start due to SEGV Created: 2023-12-23  Updated: 2024-01-03

Status: Open
Project: MariaDB Server
Component/s: Server
Affects Version/s: 10.5.21
Fix Version/s: 10.5

Type: Bug Priority: Major
Reporter: John Tait Assignee: Marko Mäkelä
Resolution: Unresolved Votes: 0
Labels: None
Environment:

MariaDB 10.5.21-MariaDB-0+deb11u1 source revision bed70468ea08c2820647f5e3ac006a9ff88144ac

Kernel version: Linux version 5.10.0-26-amd64 (debian-kernel@lists.debian.org) (gcc-10 (Debian 10.2.1-6) 10.2.1 20210110, GNU ld (GNU Binutils for Debian) 2.35.2) #1 SMP Debian 5.10.197-1 (2023-09-29)


Attachments: File core.gz     Text File mariadbd_full_bt_all_threads.txt    

 Description   

Mariadb server fails to start, possibly during or after transaction recovery. I am not sure what event happened to trigger this problem. Ideally I would like he server to start and perform the recovery but I do have mysqldump file from the prior day. I would need instructions on how to remove the existing database to get the server to start.

This is the full output from syslog, and a zipped core file is attached.

Dec 23 15:20:40 localhost systemd[1]: Starting MariaDB 10.5.21 database server...
Dec 23 15:20:40 localhost mariadbd[142540]: 2023-12-23 15:20:40 0 [Note] Starting MariaDB 10.5.21-MariaDB-0+deb11u1 source revision bed70468ea08c2820647f5e3ac006a9ff88144ac as process 142540
Dec 23 15:20:40 localhost mariadbd[142540]: 2023-12-23 15:20:40 0 [Note] InnoDB: Uses event mutexes
Dec 23 15:20:40 localhost mariadbd[142540]: 2023-12-23 15:20:40 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
Dec 23 15:20:40 localhost mariadbd[142540]: 2023-12-23 15:20:40 0 [Note] InnoDB: Number of pools: 1
Dec 23 15:20:40 localhost mariadbd[142540]: 2023-12-23 15:20:40 0 [Note] InnoDB: Using crc32 + pclmulqdq instructions
Dec 23 15:20:40 localhost mariadbd[142540]: 2023-12-23 15:20:40 0 [Note] InnoDB: Using Linux native AIO
Dec 23 15:20:40 localhost mariadbd[142540]: 2023-12-23 15:20:40 0 [Note] InnoDB: Initializing buffer pool, total size = 134217728, chunk size = 134217728
Dec 23 15:20:40 localhost mariadbd[142540]: 2023-12-23 15:20:40 0 [Note] InnoDB: Completed initialization of buffer pool
Dec 23 15:20:40 localhost mariadbd[142540]: 2023-12-23 15:20:40 0 [Note] InnoDB: Starting crash recovery from checkpoint LSN=4740669058,4740669058
Dec 23 15:20:40 localhost mariadbd[142540]: 2023-12-23 15:20:40 0 [Note] InnoDB: 1 transaction(s) which must be rolled back or cleaned up in total 95 row operations to undo
Dec 23 15:20:40 localhost mariadbd[142540]: 2023-12-23 15:20:40 0 [Note] InnoDB: Trx id counter is 7817665
Dec 23 15:20:40 localhost mariadbd[142540]: 2023-12-23 15:20:40 0 [Note] InnoDB: Starting final batch to recover 3575 pages from redo log.
Dec 23 15:20:40 localhost mariadbd[142540]: 2023-12-23 15:20:40 0 [Note] InnoDB: 128 rollback segments are active.
Dec 23 15:20:40 localhost mariadbd[142540]: 2023-12-23 15:20:40 0 [Note] InnoDB: Starting in background the rollback of recovered transactions
Dec 23 15:20:40 localhost mariadbd[142540]: 2023-12-23 15:20:40 0 [Note] InnoDB: Removed temporary tablespace data file: "ibtmp1"
Dec 23 15:20:40 localhost mariadbd[142540]: 2023-12-23 15:20:40 0 [Note] InnoDB: Creating shared tablespace for temporary tables
Dec 23 15:20:40 localhost mariadbd[142540]: 2023-12-23 15:20:40 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
Dec 23 15:20:40 localhost mariadbd[142540]: 2023-12-23 15:20:40 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
Dec 23 15:20:40 localhost mariadbd[142540]: 231223 15:20:40 [ERROR] mysqld got signal 11 ;
Dec 23 15:20:40 localhost mariadbd[142540]: This could be because you hit a bug. It is also possible that this binary
Dec 23 15:20:40 localhost mariadbd[142540]: or one of the libraries it was linked against is corrupt, improperly built,
Dec 23 15:20:40 localhost mariadbd[142540]: or misconfigured. This error can also be caused by malfunctioning hardware.
Dec 23 15:20:40 localhost mariadbd[142540]: To report this bug, see https://mariadb.com/kb/en/reporting-bugs
Dec 23 15:20:40 localhost mariadbd[142540]: We will try our best to scrape up some info that will hopefully help
Dec 23 15:20:40 localhost mariadbd[142540]: diagnose the problem, but since we have already crashed,
Dec 23 15:20:40 localhost mariadbd[142540]: something is definitely wrong and this may fail.
Dec 23 15:20:40 localhost mariadbd[142540]: Server version: 10.5.21-MariaDB-0+deb11u1 source revision: bed70468ea08c2820647f5e3ac006a9ff88144ac
Dec 23 15:20:40 localhost mariadbd[142540]: key_buffer_size=134217728
Dec 23 15:20:40 localhost mariadbd[142540]: read_buffer_size=131072
Dec 23 15:20:40 localhost mariadbd[142540]: 2023-12-23 15:20:40 0 [Note] InnoDB: 10.5.21 started; log sequence number 4745722408; transaction id 7817666
Dec 23 15:20:40 localhost mariadbd[142540]: 2023-12-23 15:20:40 0 [Note] InnoDB: Loading buffer pool(s) from /var/lib/mysql/ib_buffer_pool
Dec 23 15:20:40 localhost mariadbd[142540]: 2023-12-23 15:20:40 0 [Note] Plugin 'FEEDBACK' is disabled.
Dec 23 15:20:40 localhost mariadbd[142540]: max_used_connections=0
Dec 23 15:20:40 localhost mariadbd[142540]: max_threads=153
Dec 23 15:20:40 localhost mariadbd[142540]: thread_count=0
Dec 23 15:20:40 localhost mariadbd[142540]: It is possible that mysqld could use up to
Dec 23 15:20:40 localhost mariadbd[142540]: key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 467881 K  bytes of memory
Dec 23 15:20:40 localhost mariadbd[142540]: Hope that's ok; if not, decrease some variables in the equation.
Dec 23 15:20:40 localhost mariadbd[142540]: Thread pointer: 0x0
Dec 23 15:20:40 localhost mariadbd[142540]: Attempting backtrace. You can use the following information to find out
Dec 23 15:20:40 localhost mariadbd[142540]: where mysqld died. If you see no messages after this, something went
Dec 23 15:20:40 localhost mariadbd[142540]: terribly wrong...
Dec 23 15:20:40 localhost mariadbd[142540]: 2023-12-23 15:20:40 0 [Note] Server socket created on IP: '0.0.0.0'.
Dec 23 15:20:40 localhost mariadbd[142540]: stack_bottom = 0x0 thread_stack 0x49000
Dec 23 15:20:40 localhost mariadbd[142540]: 2023-12-23 15:20:40 0 [Note] Reading of all Master_info entries succeeded
Dec 23 15:20:40 localhost mariadbd[142540]: 2023-12-23 15:20:40 0 [Note] Added new Master_info '' to hash table
Dec 23 15:20:40 localhost mariadbd[142540]: 2023-12-23 15:20:40 0 [Note] /usr/sbin/mariadbd: ready for connections.
Dec 23 15:20:40 localhost mariadbd[142540]: Version: '10.5.21-MariaDB-0+deb11u1'  socket: '/run/mysqld/mysqld.sock'  port: 3306  Debian 11
Dec 23 15:20:40 localhost mariadbd[142540]: 2023-12-23 15:20:40 0 [Note] InnoDB: Buffer pool(s) load completed at 231223 15:20:40
Dec 23 15:20:40 localhost systemd[1]: Started MariaDB 10.5.21 database server.
Dec 23 15:20:40 localhost /etc/mysql/debian-start[142561]: Upgrading MySQL tables if necessary.
Dec 23 15:20:40 localhost /etc/mysql/debian-start[142564]: Looking for 'mariadb' as: /usr/bin/mariadb
Dec 23 15:20:40 localhost /etc/mysql/debian-start[142564]: Looking for 'mariadb-check' as: /usr/bin/mariadb-check
Dec 23 15:20:40 localhost /etc/mysql/debian-start[142564]: This installation of MariaDB is already upgraded to 10.5.15-MariaDB.
Dec 23 15:20:40 localhost /etc/mysql/debian-start[142564]: There is no need to run mysql_upgrade again for 10.5.21-MariaDB.
Dec 23 15:20:40 localhost /etc/mysql/debian-start[142564]: You can use --force if you still want to run mysql_upgrade
Dec 23 15:20:40 localhost /etc/mysql/debian-start[142572]: Checking for insecure root accounts.
Dec 23 15:20:41 localhost /etc/mysql/debian-start[142576]: Triggering myisam-recover for all MyISAM tables and aria-recover for all Aria tables
Dec 23 15:20:41 localhost mariadbd[142540]: mysys/stacktrace.c:213(my_print_stacktrace)[0x558969295e2e]
Dec 23 15:20:41 localhost mariadbd[142540]: sql/signal_handler.cc:241(handle_fatal_signal)[0x558968d8e0a5]
Dec 23 15:20:41 localhost mariadbd[142540]: sigaction.c:0(__restore_rt)[0x7f357b7f7140]
Dec 23 15:20:42 localhost systemd[1]: Stopping MariaDB 10.5.21 database server...
Dec 23 15:20:42 localhost mariadbd[142540]: 2023-12-23 15:20:42 0 [Note] /usr/sbin/mariadbd (initiated by: unknown): Normal shutdown
Dec 23 15:20:42 localhost mariadbd[142540]: 2023-12-23 15:20:42 0 [Note] Event Scheduler: Purging the queue. 0 events
Dec 23 15:20:42 localhost mariadbd[142540]: 2023-12-23 15:20:42 0 [Note] InnoDB: FTS optimize thread exiting.
Dec 23 15:20:42 localhost mariadbd[142540]: 2023-12-23 15:20:42 0 [Note] InnoDB: Starting shutdown...
Dec 23 15:20:42 localhost mariadbd[142540]: include/page0page.h:646(page_dir_slot_get_rec(unsigned char*))[0x5589690d963e]
Dec 23 15:20:42 localhost mariadbd[142540]: btr/btr0cur.cc:1989(btr_cur_search_to_nth_level(dict_index_t*, unsigned long, dtuple_t const*, page_cur_mode_t, unsigned long, btr_cur_t*, char const*, unsigned int, mtr_t*, unsigned long))[0x55896918c79c]
Dec 23 15:20:42 localhost mariadbd[142540]: include/btr0pcur.inl:445(btr_pcur_open_low(dict_index_t*, unsigned long, dtuple_t const*, page_cur_mode_t, unsigned long, btr_pcur_t*, char const*, unsigned int, unsigned long, mtr_t*) [clone .constprop.0])[0x55896912ea70]
Dec 23 15:20:42 localhost mariadbd[142540]: row/row0row.cc:1306(row_search_index_entry(dict_index_t*, dtuple_t const*, unsigned long, btr_pcur_t*, mtr_t*))[0x55896912eaef]
Dec 23 15:20:42 localhost mariadbd[142540]: row/row0umod.cc:750(row_undo_mod_del_unmark_sec_and_undo_update(unsigned long, que_thr_t*, dict_index_t*, dtuple_t*))[0x55896922e2b0]
Dec 23 15:20:42 localhost mariadbd[142540]: row/row0umod.cc:1026(row_undo_mod(undo_node_t*, que_thr_t*))[0x55896922ef77]
Dec 23 15:20:42 localhost mariadbd[142540]: row/row0undo.cc:424(row_undo_step(que_thr_t*))[0x558969138e59]
Dec 23 15:20:42 localhost mariadbd[142540]: que/que0que.cc:863(que_run_threads(que_thr_t*))[0x5589690f5561]
Dec 23 15:20:42 localhost mariadbd[142540]: trx/trx0roll.cc:631(trx_rollback_active(trx_t*))[0x558969160e00]
Dec 23 15:20:42 localhost mariadbd[142540]: trx/trx0roll.cc:784(trx_rollback_recovered(bool))[0x558969161299]
Dec 23 15:20:42 localhost mariadbd[142540]: trx/trx0roll.cc:838(trx_rollback_all_recovered.cold)[0x558968a65310]
Dec 23 15:20:42 localhost mariadbd[142540]: nptl/pthread_create.c:478(start_thread)[0x7f357b7ebea7]
Dec 23 15:20:42 localhost mariadbd[142540]: x86_64/clone.S:97(__GI___clone)[0x7f357b3f2a2f]
Dec 23 15:20:42 localhost mariadbd[142540]: The manual page at https://mariadb.com/kb/en/how-to-produce-a-full-stack-trace-for-mysqld/ contains
Dec 23 15:20:42 localhost mariadbd[142540]: information that should help you find out what is causing the crash.
Dec 23 15:20:42 localhost mariadbd[142540]: Writing a core file...
Dec 23 15:20:42 localhost mariadbd[142540]: Working directory at /var/lib/mysql
Dec 23 15:20:42 localhost mariadbd[142540]: Resource Limits:
Dec 23 15:20:42 localhost mariadbd[142540]: Limit                     Soft Limit           Hard Limit           Units
Dec 23 15:20:42 localhost mariadbd[142540]: Max cpu time              unlimited            unlimited            seconds
Dec 23 15:20:42 localhost mariadbd[142540]: Max file size             unlimited            unlimited            bytes
Dec 23 15:20:42 localhost mariadbd[142540]: Max data size             unlimited            unlimited            bytes
Dec 23 15:20:42 localhost mariadbd[142540]: Max stack size            8388608              unlimited            bytes
Dec 23 15:20:42 localhost mariadbd[142540]: Max core file size        unlimited            unlimited            bytes
Dec 23 15:20:42 localhost mariadbd[142540]: Max resident set          unlimited            unlimited            bytes
Dec 23 15:20:42 localhost mariadbd[142540]: Max processes             15620                15620                processes
Dec 23 15:20:42 localhost mariadbd[142540]: Max open files            32768                32768                files
Dec 23 15:20:42 localhost mariadbd[142540]: Max locked memory         65536                65536                bytes
Dec 23 15:20:42 localhost mariadbd[142540]: Max address space         unlimited            unlimited            bytes
Dec 23 15:20:42 localhost mariadbd[142540]: Max file locks            unlimited            unlimited            locks
Dec 23 15:20:42 localhost mariadbd[142540]: Max pending signals       15620                15620                signals
Dec 23 15:20:42 localhost mariadbd[142540]: Max msgqueue size         819200               819200               bytes
Dec 23 15:20:42 localhost mariadbd[142540]: Max nice priority         0                    0
Dec 23 15:20:42 localhost mariadbd[142540]: Max realtime priority     0                    0
Dec 23 15:20:42 localhost mariadbd[142540]: Max realtime timeout      unlimited            unlimited            us
Dec 23 15:20:42 localhost mariadbd[142540]: Core pattern: core
Dec 23 15:20:42 localhost mariadbd[142540]: Kernel version: Linux version 5.10.0-26-amd64 (debian-kernel@lists.debian.org) (gcc-10 (Debian 10.2.1-6) 10.2.1 20210110, GNU ld (GNU Binutils for Debian) 2.35.2) #1 SMP Debian 5.10.197-1 (2023-09-29)
Dec 23 15:20:43 localhost systemd[1]: mariadb.service: Main process exited, code=dumped, status=11/SEGV
Dec 23 15:20:43 localhost systemd[1]: mariadb.service: Failed with result 'core-dump'.
Dec 23 15:20:43 localhost systemd[1]: Stopped MariaDB 10.5.21 database server.



 Comments   
Comment by Marko Mäkelä [ 2023-12-23 ]

The hyperlink in the error message also links to How to produce a stack trace from a core file. A core dump by itself can only be interpreted if the executable and the dynamic libraries that produced it are available.

Based on the stack trace output in the log, it looks like something crashed within page_cur_search_with_match() while a recovered transaction was rolled back. You should be able to avoid this crash by setting innodb_force_recovery=3. That should allow a logical dump of the database to be extracted.

It is possible that this crash on corrupted data has been fixed in the MariaDB Server 10.6 release series. For analyzing this crash, it would be helpful to start the server process inside a debugger. In core dumps, the buffer pool is excluded by default (MDEV-10814).

Comment by John Tait [ 2023-12-24 ]

Thank you for your comment Marko. I have now attached the full stack trace. I am happy to start the server under the debugger but will need some guidance / link on how to do so.

Generated at Thu Feb 08 10:36:29 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.