[MDEV-21403] mariabackup: Assertion recv_sys.mlog_checkpoint_lsn <= recv_sys.recovered_lsn failed Created: 2019-12-29  Updated: 2022-11-04

Status: Open
Project: MariaDB Server
Component/s: mariabackup, Storage Engine - InnoDB
Affects Version/s: 10.4, 10.5
Fix Version/s: 10.4

Type: Bug Priority: Major
Reporter: Michael Widenius Assignee: Marko Mäkelä
Resolution: Unresolved Votes: 0
Labels: None

Issue Links:
Relates
relates to MDEV-13830 Assertion failed: recv_sys->mlog_chec... Closed
relates to MDEV-29943 MariaBackup loses a DML operation aft... Open

 Description   

mtr test mariabackup.mdev-14447 fails randomly in 10.5.1 tree with:

CURRENT_TEST: mariabackup.mdev-14447
 
sh: line 1: 21349 Aborted                 (core dumped) /home/my/maria-10.5/extr
 
a/mariabackup/mariabackup --prepare --verbose --apply-log-only --target-dir=/hom
 
e/my/maria-10.5/mysql-test/var/4/tmp/backup --incremental-dir=/home/my/maria-10.
 
5/mysql-test/var/4/tmp/backup_inc1 2>&1
 
mysqltest: At line 35: exec of '/home/my/maria-10.5/extra/mariabackup/mariabacku
 
p --prepare --verbose --apply-log-only --target-dir=/home/my/maria-10.5/mysql-te
 
st/var/4/tmp/backup --incremental-dir=/home/my/maria-10.5/mysql-test/var/4/tmp/b
 
ackup_inc1  2>&1' failed, error: 34304, status: 134, errno: 2
 
 
 
The result from queries just before the failure was:
 
call mtr.add_suppression("InnoDB: New log files created");
 
CREATE TABLE t(a varchar(40) PRIMARY KEY, b varchar(40), c varchar(40), d varchar(40), index(b,c,d)) ENGINE INNODB;
 
# Create full backup , modify table, then create incremental/differential backup
 
BEGIN;
 
INSERT INTO t select uuid(), uuid(), uuid(), uuid() from seq_1_to_100000;
 
COMMIT;
 
SELECT count(*) FROM t;
 
count(*)
 
100000
 
FOUND 1 /Checksum mismatch in datafile/ in backup.log
 
# Prepare full backup, apply incremental one
 
 
 
mariabackup: /my/maria-10.5/storage/innobase/log/log0recv.cc:2649: bool recv_parse_log_recs(lsn_t, store_t*, ulint, bool): Assertion `recv_sys.mlog_checkpoint_lsn <= recv_sys.recovered_lsn' failed.


#3  0x00007fc00dae2160 in raise () from /lib64/libc.so.6
 
#4  0x00007fc00dae3741 in abort () from /lib64/libc.so.6
 
#5  0x00007fc00dada75a in __assert_fail_base () from /lib64/libc.so.6
 
#6  0x00007fc00dada7d2 in __assert_fail () from /lib64/libc.so.6
 
#7  0x000000000124cd9e in recv_parse_log_recs (checkpoint_lsn=34221332, store=0x7ffd40828884, available_mem=67371008, apply=true) at /my/maria-10.5/storage/innobase/log/log0recv.cc:2649
 
#8  0x000000000124df2a in recv_scan_log_recs (available_mem=67371008, store_to_hash=0x7ffd40828884, log_block=0x7fc009b21000 "", checkpoint_lsn=34221332, start_lsn=34221056, end_lsn=34286592, contiguous_lsn=0x7ffd40828a98, group_scanned_lsn=0x2628c98 <log_sys+664>) at /my/maria-10.5/storage/innobase/log/log0recv.cc:3110
 
#9  0x000000000124e4a5 in recv_group_scan_log_recs (checkpoint_lsn=34221332, contiguous_lsn=0x7ffd40828a98, last_phase=false) at /my/maria-10.5/storage/innobase/log/log0recv.cc:3198
 
#10 0x000000000124fb89 in recv_recovery_from_checkpoint_start (flush_lsn=64240) at /my/maria-10.5/storage/innobase/log/log0recv.cc:3507
 
#11 0x0000000001395450 in srv_start (create_new_db=false) at /my/maria-10.5/storage/innobase/srv/srv0start.cc:1743
 
#12 0x00000000007842a2 in innodb_init () at /my/maria-10.5/extra/mariabackup/xtrabackup.cc:1975
 
#13 0x000000000078e232 in xtrabackup_prepare_func (argv=0x3817150) at /my/maria-10.5/extra/mariabackup/xtrabackup.cc:5529
 
#14 0x0000000000790251 in main_low (argv=0x3817150) at /my/maria-10.5/extra/mariabackup/xtrabackup.cc:6318
 
#15 0x000000000078fa8e in main (argc=6, argv=0x7ffd40830208) at /my/maria-10.5/extra/mariabackup/xtrabackup.cc:6108

When trying to repeat, I also found this issue during shutdown

sql/signal_handler.cc:209(handle_fatal_signal)[0xbee896]
 
/lib64/libpthread.so.0(+0x12360)[0x7f2f68a3e360]
 
/lib64/libpthread.so.0(pthread_cond_wait+0x1fd)[0x7f2f68a3990d]
 
/usr/lib64/libstdc++.so.6(_ZNSt18condition_variable4waitERSt11unique_lockISt5mutexE+0xc)[0x7f2f672bfb4c]
 
tpool/task.cc:63(tpool::waitable_task::wait())[0x1478852]
 
srv/srv0srv.cc:2233(srv_shutdown_purge_tasks())[0x123710d]
 
srv/srv0srv.cc:2304(srv_purge_shutdown())[0x123758e]
 
srv/srv0start.cc:2296(innodb_preshutdown())[0x1240491]
 
sql/handler.cc:886(plugin_pre_shutdown(THD*, st_plugin_int**, void*))[0xbf3000]
 
sql/sql_plugin.cc:2452(plugin_foreach_with_mask(THD*, char (*)(THD*, st_plugin_int**, void*), int, unsigned int, void*))[0x8ce920]
 
sql/handler.cc:895(ha_pre_shutdown())[0xbf302c]
 
sql/mysqld.cc:5731(mysqld_main(int, char**))[0x774752]



 Comments   
Comment by Elena Stepanova [ 2020-01-31 ]

Also observed on 10.4:

10.4 a10a94b2

 
mariabackup.mdev-14447                   w3 [ fail ]
 
        Test ended at 2020-01-31 07:44:04
 
 
 
CURRENT_TEST: mariabackup.mdev-14447
 
sh: line 1: 262394 Aborted                 /home/elenst/builds/10.4-a10a94b2-deb/bin/mariabackup --prepare --verbose --apply-log-only --target-dir=/home/elenst/mtr_logs/var_10.4_a10a94b2_big/3/tmp/backup --incremental-dir=/home/elenst/mtr_logs/var_10.4_a10a94b2_big/3/tmp/backup_inc1 2>&1
 
mysqltest: At line 35: exec of '/home/elenst/builds/10.4-a10a94b2-deb/bin/mariabackup --prepare --verbose --apply-log-only --target-dir=/home/elenst/mtr_logs/var_10.4_a10a94b2_big/3/tmp/backup --incremental-dir=/home/elenst/mtr_logs/var_10.4_a10a94b2_big/3/tmp/backup_inc1  2>&1' failed, error: 34304, status: 134, errno: 2
 
Output from before failure:
 
/home/elenst/builds/10.4-a10a94b2-deb/bin/mariabackup based on MariaDB server 10.4.13-MariaDB Linux (x86_64)
 
[00] 2020-01-31 07:44:01 incremental backup from 71201 is enabled.
 
[00] 2020-01-31 07:44:01 cd to /home/elenst/mtr_logs/var_10.4_a10a94b2_big/3/tmp/backup/
 
[00] 2020-01-31 07:44:01 This target seems to be already prepared.
 
[00] 2020-01-31 07:44:01 mariabackup: using the following InnoDB configuration for recovery:
 
[00] 2020-01-31 07:44:01 innodb_data_home_dir = .
 
[00] 2020-01-31 07:44:01 innodb_data_file_path = ibdata_first:3M;ibdata_second:1M:autoextend
 
[00] 2020-01-31 07:44:01 innodb_log_group_home_dir = /home/elenst/mtr_logs/var_10.4_a10a94b2_big/3/tmp/backup_inc1/
 
[00] 2020-01-31 07:44:01 InnoDB: Using Linux native AIO
 
[00] 2020-01-31 07:44:01 mariabackup: Generating a list of tablespaces
 
[00] 2020-01-31 07:44:01 page size for /home/elenst/mtr_logs/var_10.4_a10a94b2_big/3/tmp/backup_inc1//ibdata_second.delta is 16384 bytes
 
[00] 2020-01-31 07:44:01 Applying /home/elenst/mtr_logs/var_10.4_a10a94b2_big/3/tmp/backup_inc1//ibdata_second.delta to ./ibdata_second...
 
[00] 2020-01-31 07:44:01 page size for /home/elenst/mtr_logs/var_10.4_a10a94b2_big/3/tmp/backup_inc1//ibdata_first.delta is 16384 bytes
 
[00] 2020-01-31 07:44:01 Applying /home/elenst/mtr_logs/var_10.4_a10a94b2_big/3/tmp/backup_inc1//ibdata_first.delta to ./ibdata_first...
 
[00] 2020-01-31 07:44:01 page size for /home/elenst/mtr_logs/var_10.4_a10a94b2_big/3/tmp/backup_inc1//test/t.ibd.delta is 16384 bytes
 
[00] 2020-01-31 07:44:01 Applying /home/elenst/mtr_logs/var_10.4_a10a94b2_big/3/tmp/backup_inc1//test/t.ibd.delta to ./test/t.ibd...
 
[00] 2020-01-31 07:44:01 page size for /home/elenst/mtr_logs/var_10.4_a10a94b2_big/3/tmp/backup_inc1//mysql/transaction_registry.ibd.delta is 16384 bytes
 
[00] 2020-01-31 07:44:01 Applying /home/elenst/mtr_logs/var_10.4_a10a94b2_big/3/tmp/backup_inc1//mysql/transaction_registry.ibd.delta to ./mysql/transaction_registry.ibd...
 
[00] 2020-01-31 07:44:01 page size for /home/elenst/mtr_logs/var_10.4_a10a94b2_big/3/tmp/backup_inc1//mysql/innodb_table_stats.ibd.delta is 16384 bytes
 
[00] 2020-01-31 07:44:01 Applying /home/elenst/mtr_logs/var_10.4_a10a94b2_big/3/tmp/backup_inc1//mysql/innodb_table_stats.ibd.delta to ./mysql/innodb_table_stats.ibd...
 
[00] 2020-01-31 07:44:01 page size for /home/elenst/mtr_logs/var_10.4_a10a94b2_big/3/tmp/backup_inc1//mysql/innodb_index_stats.ibd.delta is 16384 bytes
 
[00] 2020-01-31 07:44:01 Applying /home/elenst/mtr_logs/var_10.4_a10a94b2_big/3/tmp/backup_inc1//mysql/innodb_index_stats.ibd.delta to ./mysql/innodb_index_stats.ibd...
 
[00] 2020-01-31 07:44:01 mariabackup: using the following InnoDB configuration for recovery:
 
[00] 2020-01-31 07:44:01 innodb_data_home_dir = .
 
[00] 2020-01-31 07:44:01 innodb_data_file_path = ibdata_first:3M;ibdata_second:1M:autoextend
 
[00] 2020-01-31 07:44:01 innodb_log_group_home_dir = /home/elenst/mtr_logs/var_10.4_a10a94b2_big/3/tmp/backup_inc1/
 
[00] 2020-01-31 07:44:01 InnoDB: Using Linux native AIO
 
[00] 2020-01-31 07:44:01 Starting InnoDB instance for recovery.
 
[00] 2020-01-31 07:44:01 mariabackup: Using 104857600 bytes for buffer pool (set by --use-memory parameter)
 
2020-01-31  7:44:02 0 [Note] InnoDB: !!!!!!!! UNIV_DEBUG switched on !!!!!!!!!
 
2020-01-31  7:44:02 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
 
2020-01-31  7:44:02 0 [Note] InnoDB: Uses event mutexes
 
2020-01-31  7:44:02 0 [Note] InnoDB: Compressed tables use zlib 1.2.7
 
2020-01-31  7:44:02 0 [Note] InnoDB: Number of pools: 1
 
2020-01-31  7:44:02 0 [Note] InnoDB: Using SSE2 crc32 instructions
 
/home/elenst/builds/10.4-a10a94b2-deb/bin/mariabackup: O_TMPFILE is not supported on /tmp (disabling future attempts)
 
2020-01-31  7:44:02 0 [Note] InnoDB: Initializing buffer pool, total size = 100M, instances = 1, chunk size = 100M
 
2020-01-31  7:44:02 0 [Note] InnoDB: Completed initialization of buffer pool
 
2020-01-31  7:44:02 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
 
2020-01-31  7:44:02 0 [Note] InnoDB: Starting crash recovery from checkpoint LSN=38532815
 
 
 
MLOG_CHECKPOINT(37068128) read at 38532842
 
MLOG_CHECKPOINT(37068128) reread at 38532815
 
mariabackup: /home/elenst/src/10.4/storage/innobase/log/log0recv.cc:2788: bool recv_parse_log_recs(lsn_t, store_t*, ulint, bool): Assertion `recv_sys.mlog_checkpoint_lsn <= recv_sys.recovered_lsn' failed.
 
200131  7:44:02 [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.4.13-MariaDB-debug
 
key_buffer_size=0
 
read_buffer_size=131072
 
max_used_connections=0
 
max_threads=1
 
thread_count=0
 
It is possible that mysqld could use up to 
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 6033 K  bytes of memory
 
Hope that's ok; if not, decrease some variables in the equation.
 
 
 
Thread pointer: 0x0
 
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 = 0x0 thread_stack 0x49000
 
/home/elenst/builds/10.4-a10a94b2-deb/bin/mariabackup(my_print_stacktrace+0x40)[0x555c6aafd0c3]
 
/home/elenst/builds/10.4-a10a94b2-deb/bin/mariabackup(handle_fatal_signal+0x3a9)[0x555c6a26ee4f]
 
sigaction.c:0(__restore_rt)[0x7fc483f6f5d0]
 
:0(__GI_raise)[0x7fc482931207]
 
:0(__GI_abort)[0x7fc4829328f8]
 
:0(__assert_fail_base)[0x7fc48292a026]
 
:0(__GI___assert_fail)[0x7fc48292a0d2]
 
/home/elenst/builds/10.4-a10a94b2-deb/bin/mariabackup(+0x11b1278)[0x555c6a796278]
 
/home/elenst/builds/10.4-a10a94b2-deb/bin/mariabackup(+0x11b239c)[0x555c6a79739c]
 
log/log0recv.cc:2789(recv_parse_log_recs(unsigned long, store_t*, unsigned long, bool))[0x555c6a797932]
 
log/log0recv.cc:3263(recv_scan_log_recs(unsigned long, store_t*, unsigned char const*, unsigned long, unsigned long, unsigned long, unsigned long*, unsigned long*))[0x555c6a798e94]
 
log/log0recv.cc:3360(recv_group_scan_log_recs(unsigned long, unsigned long*, bool))[0x555c6a8de1a0]
 
log/log0recv.cc:3660(recv_recovery_from_checkpoint_start(unsigned long))[0x555c69ce691f]
 
srv/srv0start.cc:1871(srv_start(bool))[0x555c69cf0f9worker[3] > Restart  - not started
 
 
 
mariabackup/xtrabackup.cc:1989(innodb_init())[0x555c69cf3166]
 
mariabackup/xtrabackup.cc:5552(xtrabackup_prepare_func(char**))[0x555c69cf2973]
 
/lib64/libc.so.6(__libc_start_main+0xf5)[0x7fc48291d3d5]
 
/home/elenst/builds/10.4-a10a94b2-deb/bin/mariabackup(+0x6fcc89)[0x555c69ce1c89]
 
The manual page at http://dev.mysql.com/doc/mysql/en/crashing.html contains
 
information that should help you find out what is causing the crash.
 
Writing a core file...
 
Working directory at /home/elenst/mtr_logs/var_10.4_a10a94b2_big/3/tmp/backup
 
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             4096                 2315692              processes 
Max open files            1024                 1024                 files     
Max locked memory         1073741824           1073741824           bytes     
Max address space         unlimited            unlimited            bytes     
Max file locks            unlimited            unlimited            locks     
Max pending signals       2315692              2315692              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: core

Comment by Marko Mäkelä [ 2022-11-04 ]

This may be duplicated by MDEV-29943. MariaDB Server 10.5.2 and later may be unaffected by this, because that was the first version to include the redo log rewrite MDEV-12353.

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