[MDEV-24012] Assertion `cursor->is_system() || srv_operation == SRV_OPERATION_RESTORE_DELTA || xb_close_files' failed. Created: 2020-10-22  Updated: 2020-11-02  Resolved: 2020-10-27

Status: Closed
Project: MariaDB Server
Component/s: mariabackup, Storage Engine - InnoDB
Affects Version/s: N/A
Fix Version/s: N/A

Type: Bug Priority: Major
Reporter: Matthias Leich Assignee: Marko Mäkelä
Resolution: Not a Bug Votes: 0
Labels: rr-profile

Issue Links:
Blocks
blocks MDEV-23855 InnoDB log checkpointing causes regre... Closed

 Description   

Assert hit during RQG testing
Workflow:
1. Start the DB server
2. two sessions run a DDL/DML mix
3. During 2. is ongoing
     Make a backup of the data
 
... mariabackup --backup ...
[rr 3898431 2490]/home/mleich/Server_bin/bb-10.5-MDEV-23855C_asan_Og/bin/mariabackup based on MariaDB server 10.5.7-MariaDB Linux (x86_64)
[rr 3898431 2494][00] 2020-10-21 16:42:30 uses posix_fadvise().
[rr 3898431 2501][00] 2020-10-21 16:42:30 cd to /dev/shm/vardir/1603297041/49/1/data/
...
[rr 3898431 2788][00] 2020-10-21 16:42:30 mariabackup: Generating a list of tablespaces
[rr 3898431 2954]2020-10-21 16:42:30 0 [ERROR] InnoDB: Operating system error number 2 in a file operation
...
[rr 3898431 2966]2020-10-21 16:42:30 0 [ERROR] InnoDB: File ./test/t1.ibd: 'open' returned OS error 71.
...
[rr 3898431 4039][01] 2020-10-21 16:42:31 Copying ./test/t3.ibd to /dev/shm/vardir/1603297041/49/1_clone/data/test/t3.ibd
[rr 3898431 4049][01] 2020-10-21 16:42:31         ...done
[rr 3898431 4053]mariabackup: /home/mleich/Server/bb-10.5-MDEV-23855C/extra/mariabackup/fil_cur.cc:155: xb_fil_cur_result_t xb_fil_cur_open(xb_fil_cur_t*, xb_read_filt_t*, fil_node_t*, uint, ulonglong): Assertion `cursor->is_system() || srv_operation == SRV_OPERATION_RESTORE_DELTA || xb_close_files' failed.
 
(rr) bt
#0  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
#1  0x0000149362e36859 in __GI_abort () at abort.c:79
#2  0x0000149362e36729 in __assert_fail_base (fmt=0x149362fcc588 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x5582f8e3e6a0 "cursor->is_system() || srv_operation == SRV_OPERATION_RESTORE_DELTA || xb_close_files", 
    file=0x5582f8e3d350 "/home/mleich/Server/bb-10.5-MDEV-23855C/extra/mariabackup/fil_cur.cc", line=155, function=<optimized out>) at assert.c:92
#3  0x0000149362e47f36 in __GI___assert_fail (assertion=assertion@entry=0x5582f8e3e6a0 "cursor->is_system() || srv_operation == SRV_OPERATION_RESTORE_DELTA || xb_close_files", 
    file=file@entry=0x5582f8e3d350 "/home/mleich/Server/bb-10.5-MDEV-23855C/extra/mariabackup/fil_cur.cc", line=line@entry=155, 
    function=function@entry=0x5582f8e3e720 "xb_fil_cur_result_t xb_fil_cur_open(xb_fil_cur_t*, xb_read_filt_t*, fil_node_t*, uint, ulonglong)") at assert.c:101
#4  0x00005582f65ebf72 in xb_fil_cur_open (cursor=0x5ec93533b540, read_filter=<optimized out>, node=0x60c000001618, thread_n=<optimized out>, max_file_size=<optimized out>) at /home/mleich/Server/bb-10.5-MDEV-23855C/storage/innobase/include/fil0fil.h:91
#5  0x00005582f65c1f7c in xtrabackup_copy_datafile (node=0x60c000001618, thread_n=<optimized out>, dest_name=<optimized out>, max_size=<optimized out>) at /home/mleich/Server/bb-10.5-MDEV-23855C/extra/mariabackup/xtrabackup.cc:2518
#6  0x00005582f65c27ea in data_copy_thread_func (arg=0x60400000a510) at /home/mleich/Server/bb-10.5-MDEV-23855C/extra/mariabackup/xtrabackup.cc:2897
#7  0x00007c1f2f077609 in start_thread (arg=<optimized out>) at pthread_create.c:477
#8  0x0000149362f33103 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
(rr)
 
bb-10.5-MDEV-23855 HEAD 709eb74793cfdd2ee5e48855f5d09bb39fe882dc 2020-10-21T19:01:33+03:00 compiled with debug+ASAN+Og
 
RQG
===
git clone https://github.com/mleich1/rqg --branch experimental RQG
 
perl rqg.pl \
--grammar=conf/mariadb/table_stress_innodb_nocopy1.yy \
--gendata=conf/mariadb/table_stress.zz \
--gendata_sql=conf/mariadb/table_stress.sql \
--reporters=Mariabackup_linux \
--mysqld=--innodb_use_native_aio=1 \
--mysqld=--innodb_lock_schedule_algorithm=fcfs \
--mysqld=--loose-idle_write_transaction_timeout=0 \
--mysqld=--loose-idle_transaction_timeout=0 \
--mysqld=--loose-idle_readonly_transaction_timeout=0 \
--mysqld=--connect_timeout=60 \
--mysqld=--interactive_timeout=28800 \
--mysqld=--slave_net_timeout=60 \
--mysqld=--net_read_timeout=30 \
--mysqld=--net_write_timeout=60 \
--mysqld=--loose-table_lock_wait_timeout=50 \
--mysqld=--wait_timeout=28800 \
--mysqld=--lock-wait-timeout=86400 \
--mysqld=--innodb-lock-wait-timeout=50 \
--no-mask \
--queries=10000000 \
--seed=random \
--reporters=Backtrace \
--reporters=ErrorLog \
--reporters=Deadlock1 \
--validators=None \
--mysqld=--log_output=none \
--mysqld=--log-bin \
--mysqld=--log_bin_trust_function_creators=1 \
--mysqld=--loose-debug_assert_on_not_freed_memory=0 \
--engine=InnoDB \
--restart_timeout=120 \
--duration=400 \
--mysqld=--loose-innodb_fatal_semaphore_wait_threshold=400 \
--mysqld=--loose-innodb-sync-debug \
--mysqld=--innodb_stats_persistent=off \
--mysqld=--loose-max-statement-time=30 \
--threads=2 \
--mysqld=--innodb_page_size=64K \
--mysqld=--innodb-buffer-pool-size=256M \
--duration=400 \
--no_mask \
--workdir=/data/mleich/RQG_mleich/storage/1603297041/49 \
--vardir=/dev/shm/vardir/1603297041/49 \
--mtr-build-thread=778 \
--basedir1=/home/mleich/Server_bin/bb-10.5-MDEV-23855C_asan_Og \
--script_debug=_nix_ \
--rr=Extended \
--rr_options=--chaos



 Comments   
Comment by Matthias Leich [ 2020-10-22 ]

rr:/home/mleich/RQG/storage/1603297041/
 
cd /home/mleich/RQG/storage/1603297041/TBR-715/dev/shm/vardir/1603297041/49/1/rr
_RR_TRACE_DIR="." rr replay --mark-stdio mariabackup-15
 
The archive is /home/mleich/RQG/storage/1603297041/000275.tgz
 
RQG error pattern
[ 'TBR-715' , 'Executing backup: .{1,5000}mariabackup based on MariaDB server.{1,5000}\[ERROR\] InnoDB: Operating system error number 2 in a file operation.{1,30000}Copying ibdata1 to .{1,3000}mariabackup: .{1,300}fil_cur.cc:.{1,30}xb_fil_cur_result_t xb_fil_cur_open.{1,300}Assertion .cursor->is_system\(\) \|\| srv_operation == SRV_OPERATION_RESTORE_DELTA \|\| xb_close_files. failed.' ],

Comment by Marko Mäkelä [ 2020-10-22 ]

This failure occurred in the MDEV-23855 development branch right before the MDEV-24000 change. Is this failure repeatable with a newer version of the branch?

Comment by Matthias Leich [ 2020-10-26 ]

rr:/data/mleich/RQG_mleich/storage/1603717346/MDEV-24012-TBR-715/dev/shm/vardir/1603717346/87/1/rr
_RR_TRACE_DIR="." rr replay --mark-stdio mariabackup-15
 
origin/bb-10.5-MDEV-23855 cdd97d8c2eaa892fdc4d26ea6652878aeceeb8d5 2020-10-26T10:00:39+02:00

Comment by Marko Mäkelä [ 2020-10-26 ]

This failure was repeatable in the latest pushed MDEV-23855 branch. In the final rebase to 10.5, I tried to address this by introducing Datafile::detach() and making Mariabackup pass an already opened file to fil_space_t::add().

mleich, is this bug repeatable in the latest 10.5?

Comment by Matthias Leich [ 2020-10-27 ]

No replay on latest 10.5 (before MDEV-23855 was pushed).
~2200 RQG tests

Comment by Marko Mäkelä [ 2020-10-27 ]

This bug was not present in a main branch, only in a MDEV-23855 development branch.

Comment by Matthias Leich [ 2020-10-29 ]

No replay on latest 10.5 (after MDEV-23855 was pushed).
~2200 RQG tests

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