Do you use Galera snapshot transfer with the default wsrep_sst_method=rsync?
That could corrupt files until proper locking was implemented in MDEV-25975. See also MDEV-27437.
We are using mariabackup SST method. However I think this is a secondary discussion IMO and we should focus on
[FATAL] InnoDB: Page old data size
|
thing.
It is well known (MDEV-13542) that InnoDB is eager to crash on a corrupted page. We should find out why the page was corrupted in the first place. Was wsrep_sst_method=rsync ever used in the past? What is the oldest server version with which the files had ever been written?
The stack trace in the description does not show the correct InnoDB function names. A stack trace from GDB would be more useful. If the stack trace includes a change buffer merge, then it is a known problem but something that we cannot reproduce and thus not fix; see MDEV-27734 and the open tickets linked from it.
How was the "re-sync from scratch of two cluster nodes" executed? Were the crash recovery error messages issued for the same page or same tablespace as the fatal error? The inconsistency noticed during redo log based recovery should be unrelated to any bug in the change buffer.
No, mariabackup SST was set during the initial cluster setup and we've been using only this one.
The files has been moved from older setup with MariaDB 10.1 using mariabackup as well. Then it was working fine for few months.
As I said, the issue started to occur after we created an additional index on the log table. Because we don't know the root cause, we deleted that additional index so it's possible, that this issue won't occur anymore to reproduce 
The re-sync was done using just full state transfer, via native Galera mechanism.
Hello again,
we've faced another issue that crashed MariaDB and I'm wondering if this can be caused by some data loss or corruption in InnoDB?
2022-04-24 4:10:12 2 [ERROR] InnoDB: Record in index `id_token` of table `ankietka_www`.`log` was not found on update: TUPLE (info_bits=0, 2 fields): {[4] (0x80000000),[4] (0x8F07D5AA)} at: COMPACT RECORD(info_bits=0, 2 fields): {[4] (0x80000000),[4] (0x8F07D3FC)}
|
2022-04-24 04:10:12 0x7f9b94590700 InnoDB: Assertion failure in file /home/buildbot/buildbot/build/mariadb-10.6.4/storage/innobase/rem/rem0rec.cc line 877
|
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 mariadbd 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.
|
220424 4:10:12 [ERROR] mysqld got signal 6 ;
|
This could be because you hit a bug. It is also possible that this binary
|
or one of the libraries it was linked against is corrupt, improperly built,
|
or misconfigured. This error can also be caused by malfunctioning hardware.
|
|
|
To report this bug, see https://mariadb.com/kb/en/reporting-bugs
|
|
|
We will try our best to scrape up some info that will hopefully help
|
diagnose the problem, but since we have already crashed,
|
something is definitely wrong and this may fail.
|
|
|
Server version: 10.6.4-MariaDB-1:10.6.4+maria~focal-log
|
key_buffer_size=134217728
|
read_buffer_size=131072
|
max_used_connections=7
|
max_threads=2002
|
thread_count=9
|
It is possible that mysqld could use up to
|
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 4539512 K bytes of memory
|
Hope that's ok; if not, decrease some variables in the equation.
|
|
|
Thread pointer: 0x7f9b74000c58
|
Attempting backtrace. You can use the following information to find out
|
where mysqld died. If you see no messages after this, something went
|
terribly wrong...
|
stack_bottom = 0x7f9b9458fdc8 thread_stack 0x49000
|
/usr/sbin/mariadbd(my_print_stacktrace+0x32)[0x55ccf1e4df12]
|
??:0(my_print_stacktrace)[0x55ccf19082b5]
|
/lib/x86_64-linux-gnu/libpthread.so.0(+0x153c0)[0x7f9b9eacc3c0]
|
/lib/x86_64-linux-gnu/libc.so.6(gsignal+0xcb)[0x7f9b9e5d218b]
|
??:0(gsignal)[0x7f9b9e5b1859]
|
/usr/sbin/mariadbd(+0x654434)[0x55ccf15a8434]
|
??:0(Wsrep_server_service::log_dummy_write_set(wsrep::client_state&, wsrep::ws_meta const&))[0x55ccf1594ce4]
|
??:0(Wsrep_server_service::log_dummy_write_set(wsrep::client_state&, wsrep::ws_meta const&))[0x55ccf1c5b9ca]
|
??:0(void std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >::_M_construct<char*>(char*, char*, std::forward_iterator_tag))[0x55ccf1d2a394]
|
??:0(std::pair<std::_Rb_tree_iterator<std::pair<unsigned long const, bool> >, bool> std::_Rb_tree<unsigned long, std::pair<unsigned long const, bool>, std::_Select1st<std::pair<unsigned long const, bool> >, std::less<unsigned long>, std::allocator<std::pair<unsigned long const, bool> > >::_M_emplace_unique<unsigned long&, bool>(unsigned long&, bool&&))[0x55ccf1cb9363]
|
??:0(void std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >::_M_construct<char*>(char*, char*, std::forward_iterator_tag))[0x55ccf1cb93cc]
|
??:0(void std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >::_M_construct<char*>(char*, char*, std::forward_iterator_tag))[0x55ccf1cca69c]
|
??:0(void std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >::_M_construct<char*>(char*, char*, std::forward_iterator_tag))[0x55ccf1ccb2c7]
|
??:0(void std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >::_M_construct<char*>(char*, char*, std::forward_iterator_tag))[0x55ccf1ca7e52]
|
??:0(void std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >::_M_construct<char*>(char*, char*, std::forward_iterator_tag))[0x55ccf1bfbd67]
|
??:0(wsrep_notify_status(wsrep::server_state::state, wsrep::view const*))[0x55ccf1917cee]
|
??:0(handler::ha_delete_row(unsigned char const*))[0x55ccf1a321b9]
|
??:0(Delete_rows_log_event::do_exec_row(rpl_group_info*))[0x55ccf1a2536f]
|
??:0(Rows_log_event::do_apply_event(rpl_group_info*))[0x55ccf1bc6d79]
|
??:0(wsrep_apply_events(THD*, Relay_log_info*, void const*, unsigned long))[0x55ccf1bae9fb]
|
??:0(Wsrep_applier_service::apply_write_set(wsrep::ws_meta const&, wsrep::const_buffer const&, wsrep::mutable_buffer&))[0x55ccf1ed0100]
|
??:0(wsrep::server_state::start_streaming_applier(wsrep::id const&, wsrep::transaction_id const&, wsrep::high_priority_service*))[0x55ccf1ed0fc1]
|
??:0(wsrep::server_state::on_apply(wsrep::high_priority_service&, wsrep::ws_handle const&, wsrep::ws_meta const&, wsrep::const_buffer const&))[0x55ccf1ee236c]
|
/usr/lib/libgalera_smm.so(+0x639eb)[0x7f9b95fa59eb]
|
src/trx_handle.cpp:391(galera::TrxHandleSlave::apply(void*, wsrep_cb_status (*)(void*, wsrep_ws_handle const*, unsigned int, wsrep_buf const*, wsrep_trx_meta const*, bool*), wsrep_trx_meta const&, bool&))[0x7f9b95fb782e]
|
src/replicator_smm.cpp:504(galera::ReplicatorSMM::apply_trx(void*, galera::TrxHandleSlave&))[0x7f9b95fba408]
|
src/replicator_smm.cpp:2141(galera::ReplicatorSMM::process_trx(void*, boost::shared_ptr<galera::TrxHandleSlave> const&))[0x7f9b95fedd92]
|
src/gcs_action_source.cpp:63(galera::GcsActionSource::process_writeset(void*, gcs_action const&, bool&))[0x7f9b95fedf1b]
|
src/gcs_action_source.cpp:110(galera::GcsActionSource::dispatch(void*, gcs_action const&, bool&))[0x7f9b95fee112]
|
src/gcs_action_source.cpp:29(Release::~Release())[0x7f9b95fbae00]
|
src/replicator_smm.cpp:390(galera::ReplicatorSMM::async_recv(void*))[0x7f9b95f90fe1]
|
/usr/sbin/mariadbd(_ZN5wsrep18wsrep_provider_v2611run_applierEPNS_21high_priority_serviceE+0x12)[0x55ccf1ee2982]
|
??:0(wsrep::wsrep_provider_v26::run_applier(wsrep::high_priority_service*))[0x55ccf1bc8c47]
|
??:0(wsrep_fire_rollbacker)[0x55ccf1bb93c3]
|
??:0(start_wsrep_THD(void*))[0x55ccf1b4917d]
|
/lib/x86_64-linux-gnu/libpthread.so.0(+0x9609)[0x7f9b9eac0609]
|
/lib/x86_64-linux-gnu/libc.so.6(clone+0x43)[0x7f9b9e6ae293]
|
|
|
Trying to get some variables.
|
Some pointers may be invalid and cause the dump to abort.
|
Query (0x7f9b8d4ab33b): DELETE FROM `log` WHERE `id` IN ("252173220")
|
|
|
Connection ID (thread ID): 2
|
Status: NOT_KILLED
|
|
|
Optimizer switch: index_merge=on,index_merge_union=on,index_merge_sort_union=on,index_merge_intersection=on,index_merge_sort_intersection=off,engine_condition_pushdown=off,index_condition_pushdown=on,derived_merge=on,derived_with_keys=on,firstmatch=on,loosescan=on,materialization=on,in_to_exists=on,semijoin=on,partial_match_rowid_merge=on,partial_match_table_scan=on,subquery_cache=on,mrr=off,mrr_cost_based=off,mrr_sort_keys=off,outer_join_with_cache=on,semijoin_with_cache=on,join_cache_incremental=on,join_cache_hashed=on,join_cache_bka=on,optimize_join_buffer_size=on,table_elimination=on,extended_keys=on,exists_to_in=on,orderby_uses_equalities=on,condition_pushdown_for_derived=on,split_materialized=on,condition_pushdown_for_subquery=on,rowid_filter=on,condition_pushdown_from_having=on,not_null_range_scan=off
|
|
|
The manual page at https://mariadb.com/kb/en/how-to-produce-a-full-stack-trace-for-mysqld/ contains
|
information that should help you find out what is causing the crash.
|
Writing a core file...
|
Working directory at /var/lib/mysql
|
Resource Limits:
|
Limit Soft Limit Hard Limit Units
|
Max cpu time unlimited unlimited seconds
|
Max file size unlimited unlimited bytes
|
Max data size unlimited unlimited bytes
|
Max stack size 8388608 unlimited bytes
|
Max core file size 0 unlimited bytes
|
Max resident set unlimited unlimited bytes
|
Max processes 144426 144426 processes
|
Max open files 32768 32768 files
|
Max locked memory 65536 65536 bytes
|
Max address space unlimited unlimited bytes
|
Max file locks unlimited unlimited locks
|
Max pending signals 144426 144426 signals
|
Max msgqueue size 819200 819200 bytes
|
Max nice priority 0 0
|
Max realtime priority 0 0
|
Max realtime timeout unlimited unlimited us
|
Core pattern: |/usr/share/apport/apport %p %s %c %d %P %E
|
r.kubik, the latest output that you provided shows corruption at two levels: an error message indicating that the indexes of a table are not consistent with each other, and an assertion failure because of an invalid record header bits (a corrupted index page).
This could be due to a bug in the Galera snapshot transfer scripts, for example if a failure to apply the copied log (mariadb-backup --prepare) was ignored by the scripts. I’m reassigning this to our Galera maintainer.
r.kubik How did you migrate from 10.1 to 10.6? Can we have full error log and your configuration of the nodes.
Migration has been done using mariabackup from 10.1 to 10.6, using just binary files from /var/lib/mysql. Then mysql_upgrade done on target 10.6 nodes.
Configuration:
# this is read by the standalone daemon and embedded servers
|
[server]
|
|
|
# this is only for the mysqld standalone daemon
|
[mysqld]
|
|
|
#
|
# * Basic Settings
|
#
|
|
|
user = mysql
|
pid-file = /run/mysqld/mysqld.pid
|
basedir = /usr
|
datadir = /var/lib/mysql
|
tmpdir = /tmp
|
lc-messages-dir = /usr/share/mysql
|
lc-messages = en_US
|
skip-external-locking
|
|
|
# Broken reverse DNS slows down connections considerably and name resolve is
|
# safe to skip if there are no "host by domain name" access grants
|
skip-name-resolve
|
|
|
# Instead of skip-networking the default is now to listen only on
|
# localhost which is more compatible and is not less secure.
|
bind-address = 0.0.0.0
|
|
|
#
|
# * Fine Tuning
|
#
|
|
|
#key_buffer_size = 128M
|
max_allowed_packet = 32M
|
#thread_stack = 192K
|
#thread_cache_size = 8
|
# This replaces the startup script and checks MyISAM tables if needed
|
# the first time they are touched
|
#myisam_recover_options = BACKUP
|
max_connections = 2000
|
#table_cache = 64
|
|
|
performance_schema = ON
|
sql_mode = 'NO_AUTO_CREATE_USER,NO_ENGINE_SUBSTITUTION'
|
|
|
#
|
# * Logging and Replication
|
#
|
|
|
# Both location gets rotated by the cronjob.
|
# Be aware that this log type is a performance killer.
|
# Recommend only changing this at runtime for short testing periods if needed!
|
#general_log_file = /var/log/mysql/mysql.log
|
#general_log = 1
|
|
|
# When running under systemd, error logging goes via stdout/stderr to journald
|
# and when running legacy init error logging goes to syslog due to
|
# /etc/mysql/conf.d/mariadb.conf.d/50-mysqld_safe.cnf
|
# Enable this if you want to have error logging into a separate file
|
log_error = /var/log/mysql/error.log
|
# Enable the slow query log to see queries with especially long duration
|
#slow_query_log_file = /var/log/mysql/mariadb-slow.log
|
log_output=FILE
|
slow_query_log
|
slow_query_log_file = /var/log/mysql/mariadb-slow.log
|
#long_query_time = 10
|
#log_slow_verbosity = query_plan,explain
|
#log-queries-not-using-indexes
|
#min_examined_row_limit = 1000
|
|
|
# The following can be used as easy to replay backup logs or for replication.
|
# note: if you are setting up a replication slave, see README.Debian about
|
# other settings you may need to change.
|
server_id = 10
|
#log_bin = /var/log/mysql/mysql-bin.log
|
#expire_logs_days = 2
|
#max_binlog_size = 100M
|
#log_slave_updates = ON
|
|
|
#
|
# * SSL/TLS
|
#
|
|
|
# For documentation, please read
|
# https://mariadb.com/kb/en/securing-connections-for-client-and-server/
|
#ssl-ca = /etc/mysql/cacert.pem
|
#ssl-cert = /etc/mysql/server-cert.pem
|
#ssl-key = /etc/mysql/server-key.pem
|
#require-secure-transport = on
|
|
|
#
|
# * Character sets
|
#
|
|
|
# MySQL/MariaDB default is Latin1, but in Debian we rather default to the full
|
# utf8 4-byte character set. See also client.cnf
|
collation-server=utf8_general_ci
|
init-connect='SET NAMES utf8'
|
character-set-server=utf8
|
|
|
#
|
# * InnoDB
|
#
|
|
|
# InnoDB is enabled by default with a 10MB datafile in /var/lib/mysql/.
|
# Read the manual for more InnoDB related options. There are many!
|
# Most important is to give InnoDB 80 % of the system RAM for buffer use:
|
# https://mariadb.com/kb/en/innodb-system-variables/#innodb_buffer_pool_size
|
innodb_buffer_pool_size = 26G
|
innodb_log_file_size = 768M
|
|
|
# this is only for embedded server
|
[embedded]
|
|
|
# This group is only read by MariaDB servers, not by MySQL.
|
# If you use the same .cnf file for MySQL and MariaDB,
|
# you can put MariaDB-only options here
|
[mariadb]
|
# SST
|
wsrep_sst_method = mariabackup
|
wsrep_sst_auth = mariabackup:PASSWORD
|
|
|
# This group is only read by MariaDB-10.6 servers.
|
# If you use the same .cnf file for MariaDB of different versions,
|
# use this group for options that older servers don't understand
|
[mariadb-10.6]
|
#
|
# * Galera-related settings
|
#
|
# See the examples of server wsrep.cnf files in /usr/share/mysql
|
# and read more at https://mariadb.com/kb/en/galera-cluster/
|
|
|
[galera]
|
# Mandatory settings
|
|
|
wsrep_provider = /usr/lib/libgalera_smm.so
|
wsrep_on = ON
|
wsrep_cluster_name = "customer-prod-db-cluster"
|
wsrep_cluster_address = gcomm://xxx.xx.29.103,xxx.xx.29.104,xxx.xx.29.105
|
binlog_format = row
|
default_storage_engine = InnoDB
|
innodb_autoinc_lock_mode = 2
|
|
|
# Allow server to accept connections on all interfaces.
|
bind-address = 0.0.0.0
|
|
|
# Optional settings
|
wsrep_slave_threads = 1
|
innodb_flush_log_at_trx_commit = 0
|
|
Configuration is the same on all the nodes, Galera docs readed carefully.
Any updates on this?
r.kubik, was a mariabackup --prepare or innobackupex --apply-log step run on the 10.1 files as part of the upgrade? Do you have the output from that step available? I am aware that before MDEV-12353 introduced a new redo log record format, recovery or backup could sometimes fail.
I think that in some past versions, the Galera snapshot transfer scripts omitted or discarded log files. That is a sure recipe for disaster, and it would disable an important safety mechanism against corruption. I became aware of that while implementing MDEV-27199.
I only know InnoDB and some of the interface between it and Galera. I would say that an upgrade with wsrep_sst_method=rsync and innodb_use_native_aio=0 on the 10.1 donor should be safe. I would not trust anything else. After upgrading to a donor that contains the fix of MDEV-25975, the default setting innodb_use_native_aio=1 should be safe with wsrep_sst_method=rsync.
When it comes to the crash, I think that it should be prevented by the changes that I implemented for MDEV-13542 today. This ticket is about corruption due to Galera upgrade, not about the crash.
The upgrade was done on a "normal" MariaDB instance. Galera was introduced/configured afterwards, on 10.6, after the mysql_upgrade etc.
mariabackup --prepare has been executed using Mariabackup 10.1
r.kubik, did you witness any corruption before enabling Galera? If you happen to have an old backup, I would suggest to invoke CHECK TABLE on every table.
In MDEV-21724 the recovery of some index page operations was rewritten, and consistency checks were added. A consistency check did fail according to the Description:
|
mariadb-10.6.4 |
2022-04-13 6:42:20 0 [ERROR] InnoDB: Not applying INSERT_HEAP_DYNAMIC due to corruption on [page id: space=3076, page number=2608001]
|
I do not think we see such errors in the internal InnoDB stress testing when the server is being killed under load, or mariadb-backup is being used. My best guess is that such errors occur when a section of the log was lost, or the ib_logfile0 was deleted in the past, to ‘fix’ crash recovery trouble. Could that have been the case here?
A debug option could be implemented in MDEV-18976 to better catch this type of inconsistency.
No, there was no corruptions before galera, but galera has been introduced at the same time when migration/upgrade 10.1>10.6 occured. We are now unsure if this is galera thing, or migration issue. Have you encounteder similar issues with 10.1 > 10.6 upgrade in the past? Is it possible?
Are our Galera setting safe? Is there anything we can improve to make the cluster and data safe?
We are now considering a scenario of stopping the production, making logical backup (mysqldump), purging the whole cluster and restoring from .sql backup to get rid of all data corruption. WDYT?
I'm pretty sure that noone touched ib_logfile0 in the past.
I am not a support engineer, and this is not a support portal but a bug reporting system. That being said, logical backup and restore does sounds reasonable to me. If the InnoDB log got out of sync with the InnoDB data files, all sorts of bad things could happen.
It may be impossible to determine what caused this corruption, and I can imagine that your priority is to fix the corruption, not to track down the root cause. Bugs in the Galera SST and IST are my best guesses. Some fixes to that were included in the recent 10.6.8 release.
MDEV-24449 is an example of an improbable bug that could cause corruption from the very first InnoDB release until it was fixed. Theoretically it is possible that the data files were corrupted already in 10.1, and an inconsistency of the index page was only noticed when the log was applied. The recovery code in MDEV-21724 is separate from the code that would insert records during normal database operation.
It is actually possible that there is a recovery bug in 10.5 and 10.6, caused by MDEV-21724. I am currently looking at https://rr-project.org traces of a failure where the child page number in a record was written as 0x203 and updated to 0x204, but recovered as 0x103 and 0x104. This would also affect backup, and obviously, wsrep_sst_method=mariabackup. I would recommend upgrading to 10.6.8 and using wsrep_sst_method=rsync to avoid hitting this bug.
Apparently, our internal stress testing of recovery and backup is using too small tables and too frequent DDL, which would lead to rather short lifetime of InnoDB data files. For the failure that I am currently debugging, the non-default setting innodb_file_per_table=0 was used, that is, all persistent InnoDB data was being written to the system tablespace. To catch this type of errors more easily, MDEV-18976 has to be implemented.
Hi,
in our case, using rsync as SST method is not preferred. The dataset is ~350GB and we don't want to "freeze" the cluster during SST.
Is it really so recommended from your side?
For now we are going to do a logical backup&restore as well as upgrade to latest 10.6 version. Is this bug still relevant? According to MDEV-21724 it's fixed.
I filed MDEV-28668 for the recovery bug. I think that it could cause this kind of corruption, but I cannot say if it is the actual cause of the reported problem.
There is another recovery bug MDEV-28731 that could cause this.
In fact, the crash on exactly this type of corruption will be removed in MDEV-18519.
The issue does not appear anymore after we dumped the data via mysqldump and restored it.
Issue based on comments has been resolved and identified bugs are fixed. If issue again reproduces please open a new MDEV.