SIGSEGV in SHOW ENGINE INNODB STATUS: lock_rec_print() passes NULL from page_find_rec_with_heap_no() to rec_get_offsets() for a waiting record lock (Galera multi-master)

Summary

One node of a 7-node Galera cluster (MariaDB 11.8.2, Galera 26.4.22) crashed with signal 11 while executing SHOW ENGINE INNODB STATUS. The statement came from our monitoring agent (Percona PMM, which runs it every 10 seconds on every node). The node had been up for about 35 days.

The crash happens while InnoDB prints a transaction's waiting record lock (trx->lock.wait_lock). In 11.8.2, lock_rec_print() looks up the record for each set bit with page_find_rec_with_heap_no(), which returns NULL when that heap number is not in the page's record list. The result goes to rec_get_offsets() without a NULL check. The kernel reports a read fault at 0xfffffffffffffffd (NULL - 3), at the instruction in rec_get_offsets_func()+36. That is consistent with reading the status bits at rec - REC_NEW_STATUS on a NULL rec.

So the lock system held a waiting record lock whose bitmap had a bit set for a heap number that was not on the page. This looks like the orphaned wait lock in MDEV-39681 ("delayed BF abort with multi-master load", fixed in 11.8.9). MDEV-39681 reports hangs and an assertion in trx_t::rollback_finish, not this crash, so we cannot tell whether its fix covers this path. lock_rec_print() is unchanged on the current 11.8 branch head (VERSION 11.8.10) and still has no NULL check.

Crash output (error log)

261109 15:07:23 [ERROR] /usr/sbin/mariadbd got signal 11 ;

Sorry, we probably made a mistake, and this is a bug.

Server version: 11.8.2-MariaDB-log source revision: 8d36cafe4fc700e6e577d5a36650c58707e76b92

WSREP: Suppressing further logging

WSREP: Shutting down network communications

Attempting backtrace. Include this in the bug report.

(note: Retrieving this information may fail)

Thread pointer: 0x7eeca0085868

stack_bottom = 0x7f235c327000 thread_stack 0x49000

/usr/sbin/mariadbd(my_print_stacktrace+0x2e)[0x5637f96a54ee]

/usr/sbin/mariadbd(handle_fatal_signal+0x305)[0x5637f9171ad5]

/lib64/libc.so.6(+0x3fc30)[0x7f2367c3fc30]

/usr/sbin/mariadbd(+0xeb13f4)[0x5637f94f93f4]

/usr/sbin/mariadbd(+0xe5ee1e)[0x5637f94a6e1e]

/usr/sbin/mariadbd(+0xe6335d)[0x5637f94ab35d]

/usr/sbin/mariadbd(+0xe63434)[0x5637f94ab434]

/usr/sbin/mariadbd(+0xf06af6)[0x5637f954eaf6]

/usr/sbin/mariadbd(+0xe1b55c)[0x5637f946355c]

/usr/sbin/mariadbd(_Z14ha_show_statusP3THDP10handlerton12ha_stat_type+0x406)[0x5637f9181376]

/usr/sbin/mariadbd(_Z21mysql_execute_commandP3THDb+0x3062)[0x5637f8ee32a2]

/usr/sbin/mariadbd(_Z11mysql_parseP3THDPcjP12Parser_state+0x1e7)[0x5637f8ee5a27]

/usr/sbin/mariadbd(+0x89e261)[0x5637f8ee6261]

/usr/sbin/mariadbd(_Z16dispatch_command19enum_server_commandP3THDPcjb+0x274b)[0x5637f8ee91eb]

/usr/sbin/mariadbd(_Z10do_commandP3THDb+0x13f)[0x5637f8ee9c7f]

/usr/sbin/mariadbd(_Z11tp_callbackP13TP_connection+0x87)[0x5637f90f7fd7]

/usr/sbin/mariadbd(+0xcccc55)[0x5637f9314c55]

/usr/sbin/mariadbd(+0xd71dce)[0x5637f93b9dce]

/lib64/libc.so.6(+0x8b2ea)[0x7f2367c8b2ea]

/lib64/libc.so.6(+0x110500)[0x7f2367d10500]

Connection ID (thread ID): 220443255

Status: NOT_KILLED

Query (0x7eeca0047500): SHOW ENGINE INNODB STATUS

Kernel:

kernel: worker_thread[642085]: segfault at fffffffffffffffd ip 00005637f94f93f4 sp 00007f235c323ba0 error 5 in mariadbd[5637f8d0f000+a75000] likely on CPU 5 (core 5, socket 0)

Unresolved frames, resolved with gdb against the same binary

$ gdb -batch -ex "info symbol 0xeb13f4" ... /usr/sbin/mariadbd

0xeb13f4  rec_get_offsets_func(unsigned char const*, dict_index_t const*, unsigned short*, unsigned long, unsigned long, mem_block_info_t**) + 36

0xe5ee1e  lock_rec_print(_IO_FILE*, ib_lock_t const*, mtr_t&) + 430

0xe6335d  lock_trx_print_wait_and_mvcc_state(_IO_FILE*, trx_t const*, my_hrtime_t) + 365

0xe63434  lock_print_info_all_transactions(_IO_FILE*) + 164

0xf06af6  srv_printf_innodb_monitor(_IO_FILE*, unsigned long, unsigned long*, unsigned long*) + 406

0xe1b55c  innobase_show_status(handlerton*, THD*, bool (*)(THD*, char const*, unsigned long, char const*, unsigned long, char const*, unsigned long), ha_stat_type) + 156

Call chain:

ha_show_status -> innobase_show_status -> srv_printf_innodb_monitor -> lock_print_info_all_transactions

  -> lock_trx_print_wait_and_mvcc_state  (prints trx->lock.wait_lock)

  -> lock_rec_print -> rec_get_offsets_func   <-- SIGSEGV, rec == NULL

Code path (mariadb-11.8.2, storage/innobase/lock/lock0lock.cc)

	mtr.start();

	const buf_block_t* block = buf_page_try_get(page_id, &mtr);

	for (ulint i = 0; i < lock_rec_get_n_bits(lock); ++i) {

		if (!lock_rec_get_nth_bit(lock, i)) {

			continue;

		}

		fprintf(file, "Record lock, heap no %lu", (ulong) i);

		if (block) {

			ut_ad(page_is_leaf(block->page.frame));

			const rec_t*	rec;

			rec = page_find_rec_with_heap_no(

				buf_block_get_frame(block), i);

			ut_ad(!page_rec_is_metadata(rec));

			offsets = rec_get_offsets(            // rec may be NULL here

				rec, lock->index, offsets, ...

page_find_rec_with_heap_no() (page0page.cc) is documented as "@return record, NULL if not found". It returns NULL when it reaches the supremum without finding heap_no. This loop is the same on the 11.8 branch head.

What was waiting

• No client connection on this node had a statement in a lock wait at the time of the crash. We checked the general log for statements that started before the crash and had not finished. So the transaction whose wait_lock was printed was most likely a Galera applier thread or a transaction that had just been BF-aborted. Neither appears in the general log.
• The error log shows no WSREP conflict or BF-abort messages before the crash, but conflict logging is off (wsrep_log_conflicts=OFF, cert.log_conflicts=no). That absence is not evidence either way.
• The workload is multi-master: all 7 nodes take writes through a load balancer. The schema has 36 foreign keys with ON DELETE / ON UPDATE CASCADE or SET NULL, including a self-referencing CASCADE key on the main users table. Cascading foreign keys are the setup that reproduces MDEV-39681.
• About 10 hours earlier, an RSU schema change desynced and paused this node and two others for about 50 minutes. The node then returned to SYNCED. Probably unrelated; mentioned for completeness.

Configuration (relevant)

MariaDB-server 11.8.2-1.el9 (MariaDB Foundation RPM), galera-4 26.4.22-1.el9 (Codership RPM), official MariaDB repository

wsrep_slave_threads       = 32

wsrep_sst_method          = rsync

wsrep_log_conflicts       = OFF

wsrep_certify_nonPK       = ON

wsrep_retry_autocommit    = 1

wsrep_provider_options    : cert.log_conflicts=no; cert.optimistic_pa=yes; gcache.size=6G; gcs.fc_limit=16; gcs.fc_factor=1.0

innodb_buffer_pool_size   = 204010946560  (190 GiB)

innodb_lock_wait_timeout  = 50

innodb_deadlock_detect    = ON

innodb_autoinc_lock_mode  = 2

transaction_isolation     = REPEATABLE-READ

binlog_format             = ROW

thread_handling           = pool-of-threads

thread_pool_size          = 32

core_file                 = OFF

What we could not provide

• No usable core dump. core_file=OFF, and systemd-coredump caps cores at 10 GB (ProcessSizeMax=10G), against a 190 GiB buffer pool. The stored core is truncated and has no usable backtrace. We plan to enable core_file with innodb_buffer_pool_in_core_file=OFF, and will attach thread apply all bt full if it happens again.
• No reproduction. It has happened once on this version. The same monitoring statement has run every 10 seconds on all nodes for years on earlier versions.

Questions

1. Does the MDEV-39681 fix (11.8.9) also prevent a trx->lock.wait_lock from keeping heap-number bits for records that are no longer on the page? In other words, does upgrading to 11.8.9 fix this crash?
2. Independently of the root cause, should lock_rec_print() (and the similar callers of page_find_rec_with_heap_no()) handle rec == NULL, for example by printing "record not found on page"? SHOW ENGINE INNODB STATUS is polled continuously by common monitoring tools, so any lock-system inconsistency turns into a crash of a production node.

Related

• MDEV-39681 - delayed BF abort with multi-master load (orphaned lock in the wait queue after a BF abort; fixed in 11.8.9). Probably the same root cause; different symptom.
• MDEV-41183 - 10.11.18 + Galera, repeated signal 11 crashes with SHOW ENGINE INNODB STATUS in the crash log (open). Possibly the same crash.
• MDEV-20675 - an earlier crash in the same printer (lock_trx_print_wait_and_mvcc_state) caused by a missing NULL check, fixed in 10.3.19 / 10.4.9.