[MDEV-18200] MariaBackup full backup failed with InnoDB: Failing assertion: success in storage/innobase/fil/fil0fil.cc line 657 Created: 2019-01-10  Updated: 2023-10-12  Resolved: 2023-10-12

Status: Closed
Project: MariaDB Server
Component/s: mariabackup, Storage Engine - InnoDB
Affects Version/s: 10.2, 10.3, 10.4
Fix Version/s: 10.4.32, 10.5.23, 10.6.16, 10.10.7, 10.11.6, 11.0.4, 11.1.3

Type: Bug Priority: Blocker
Reporter: Elena Stepanova Assignee: Daniel Black
Resolution: Fixed Votes: 1
Labels: affects-tests, rr-profile

Attachments: File MDEV-18200.test     File mbackup_backup_0.log     File mysql.err     File mysql.log     File simp_MDEV-18200.yy     File trial.log    
Issue Links:
Blocks
is blocked by MDEV-24044 mariabackup --backup: [ERROR] InnoDB:... Closed
Duplicate
is duplicated by MDEV-18550 InnoDB: Failing assertion: success du... Open
is duplicated by MDEV-24687 Mariabackup: Assertion `cursor->is_sy... Open
Relates
relates to MDEV-24626 Remove synchronous write of page0 and... Closed
relates to MDEV-26398 mariabackup failed on Windows 10 Needs Feedback

 Description   

10.4 301bd62b253

mariabackup: Generating a list of tablespaces
2019-01-10  3:51:49 0 [Warning] InnoDB: Allocated tablespace ID 3 for mysql/transaction_registry, old maximum was 0
2019-01-10  3:51:49 0 [ERROR] InnoDB: Operating system error number 2 in a file operation.
2019-01-10  3:51:49 0 [ERROR] InnoDB: The error means the system cannot find the path specified.
2019-01-10  3:51:49 0 [ERROR] InnoDB: If you are installing InnoDB, remember that you must create directories yourself, InnoDB does not create them.
2019-01-10  3:51:49 0 [ERROR] InnoDB: File ./test/#sql-6041_11.ibd: 'open' returned OS error 71.
2019-01-10 03:51:49 0x7fa4fbbdb740  InnoDB: Assertion failure in file /home/travis/src/storage/innobase/fil/fil0fil.cc line 657
InnoDB: Failing assertion: success
InnoDB: We intentionally generate a memory trap.
 
/home/travis/server/bin/mariabackup(+0xfc703a)[0x55e5bbb9003a]
/home/travis/server/bin/mariabackup(+0xd38cdf)[0x55e5bb901cdf]
ut/ut0mem.cc:42(ut_strlcpy(char*, char const*, unsigned long))[0x55e5bb905105]
fil/fil0fil.cc:658(fil_node_open_file(fil_node_t*))[0x55e5bb1e3d2e]
fil/fil0fil.cc:1647(fil_space_t::open())[0x55e5bb1e4126]
mariabackup/xtrabackup.cc:3136(xb_load_single_table_tablespace(char const*, char const*, bool))[0x55e5bb1e46c1]
mariabackup/xtrabackup.cc:3251(enumerate_ibd_files(void (*)(char const*, char const*, bool)))[0x55e5bb1e6509]
mariabackup/xtrabackup.cc:3421(xb_load_tablespaces())[0x55e5bb1eda33]
mariabackup/xtrabackup.cc:4250(xtrabackup_backup_func())[0x55e5bb1ed283]
/lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0xf0)[0x7fa4f9830830]
/home/travis/server/bin/mariabackup(_start+0x29)[0x55e5bb1dcef9]

Logs are attached.
Not reproducible right away.



 Comments   
Comment by Matthias Leich [ 2019-04-16 ]

I am working on some replay testcase.

Comment by Matthias Leich [ 2019-04-16 ]

Simplified RQG grammar (simp_MDEV-18200.yy)

query:
    # The following
    # ALTER TABLE t1 MODIFY COLUMN col2 INT NOT NULL |
    # ALTER TABLE t1 MODIFY COLUMN col2 INT          ;
    # or just Marko's proposal
        ALTER TABLE t1 FORCE ;
 
query_init:
    # same assert
    # CREATE TABLE t1 ( col2 INT ) ENGINE = InnoDB ROW_FORMAT = Dynamic ;
    # CREATE TABLE t1 ( col2 INT ) ENGINE = InnoDB ROW_FORMAT = Redundant ;
    # CREATE TABLE t1 ( col2 INT ) ENGINE = InnoDB ROW_FORMAT = Compressed ;
      CREATE TABLE t1 ( col2 INT ) ENGINE = InnoDB ROW_FORMAT = Compact ;
 
Replay on
- 10.2.24 commit bc8d173b9f9a629d6301f5e8eb011155b041de4a 2019-04-15
- 10.3.15 commit a2335b791aa06fbf4b784486ed9d34ba75af9d51   2019-04-14
- 10.4.5    commit eb056f8726131b652f22b33b23c0682741ea5475 2019-04-16
 
Please use the uploaded MTR based test MDEV-18200.test.

Comment by Marko Mäkelä [ 2019-04-16 ]

With MDEV-18200.test I can reproduce the problem:

10.2 bc8d173b9f9a629d6301f5e8eb011155b041de4a

2019-04-16 17:51:12 140650916363264 [ERROR] InnoDB: Cannot open datafile for read-only: './test/#sql-ib1974.ibd' OS error: 71
[00] FATAL ERROR: 2019-04-16 17:51:12 Can't open datafile test/#sql-ib1974
mysqltest: At line 27: exec of '/dev/shm/10.2/extra/mariabackup/mariabackup --defaults-file=/dev/shm/10.2/mysql-test/var/my.cnf  --backup --target-dir=/dev/shm/10.2/mysql-test/var/tmp/backup' failed, error: 256, status: 1, errno: 11

This is slightly different from the original description, because the name prefix #sql-ib is generated by InnoDB for table-rebuilding ALGORITHM=INPLACE. The originally reported prefix #sql- followed by hexadecimal digits would be for ALGORITHM=COPY.

I believe that this bug is outside InnoDB core, in Mariabackup. I would guess that normal file operations would be protected by locks, but the #sql names for intermediate copies of tables are not protected by any locks.

Comment by Matthias Leich [ 2019-06-12 ]

The problem affects also builds without debug.
MariaDB Enterprise 10.2.25 commit fd21ff94a2136f4c1ebb896987b7607b1d161cad 2019-06-11

Comment by Matthias Leich [ 2019-06-18 ]

I have set the label "affects-tests" because a quite high fraction of my RQG based tests for Mariabackup abort with this failure.
The unfortunate consequence is:
Other maybe existing and unknown bugs have a significant lower chance to show up.

Comment by Elena Stepanova [ 2019-07-05 ]

Probably a variation of the same problem, here the errors happen on the server side after restoring a backup. No assertion failure, just errors:

2019-07-05 21:45:04 140439568443200 [Note] InnoDB: New log files created, LSN=33849437
2019-07-05 21:45:04 140439568443200 [Note] InnoDB: Highest supported file format is Barracuda.
2019-07-05 21:45:04 140439568443200 [ERROR] InnoDB: Operating system error number 2 in a file operation.
2019-07-05 21:45:04 140439568443200 [ERROR] InnoDB: The error means the system cannot find the path specified.
2019-07-05 21:45:04 140439568443200 [ERROR] InnoDB: If you are installing InnoDB, remember that you must create directories yourself, InnoDB does not create them.
2019-07-05 21:45:04 140439568443200 [ERROR] InnoDB: Cannot open datafile for read-only: './test/#sql-2498_10.ibd' OS error: 71
2019-07-05 21:45:04 140439568443200 [ERROR] InnoDB: Operating system error number 2 in a file operation.
2019-07-05 21:45:04 140439568443200 [ERROR] InnoDB: The error means the system cannot find the path specified.
2019-07-05 21:45:04 140439568443200 [ERROR] InnoDB: If you are installing InnoDB, remember that you must create directories yourself, InnoDB does not create them.
2019-07-05 21:45:04 140439568443200 [ERROR] InnoDB: Could not find a valid tablespace file for `test/#sql-2498_10`. Please refer to https://mariadb.com/kb/en/innodb-data-dictionary-troubleshooting/ for how to resolve the issue.
2019-07-05 21:45:04 140439568443200 [Note] InnoDB: 1 transaction(s) which must be rolled back or cleaned up in total 1 row operations to undo
2019-07-05 21:45:04 140439568443200 [Note] InnoDB: Trx id counter is 5120
2019-07-05 21:45:04 140439568443200 [Note] InnoDB: Deleting ./test/#sql-2498_10.ibd
2019-07-05 21:45:04 140439568443200 [Note] InnoDB: Removed datafile ./test/#sql-2498_10.ibd for table test/#sql-2498_10
2019-07-05 21:45:05 140439043770112 [Note] InnoDB: Starting in background the rollback of recovered transactions
2019-07-05 21:45:05 140439568443200 [Note] InnoDB: 128 out of 128 rollback segments are active.
2019-07-05 21:45:05 140439568443200 [Note] InnoDB: Creating shared tablespace for temporary tables
2019-07-05 21:45:05 140439568443200 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
2019-07-05 21:45:05 140439568443200 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
2019-07-05 21:45:05 140439568443200 [Note] InnoDB: Waiting for purge to start
2019-07-05 21:45:05 140439043770112 [Note] InnoDB: Rolled back recovered transaction 4617
2019-07-05 21:45:05 140439043770112 [Note] InnoDB: Rollback of non-prepared transactions completed

To reproduce:

git clone https://github.com/MariaDB/randgen --branch mdev18200 rqg-mdev18200
cd rqg-mdev18200
. ./mdev18200.cmd <your basedir> <your vardir>

Use on-disk location for vardir, not shm.

Comment by Marko Mäkelä [ 2021-05-11 ]

The discovery of data files during recovery would be cleaned up by MDEV-24626. However, this bug is about mariabackup --backup and hence MDEV-24626 should not provide any direct help.

Comment by Daniel Black [ 2022-08-29 ]

User complained on [kb questions](https://mariadb.com/kb/en/mariabackup-gives-core-dump/)

It doesn't appear blocked by MDEV-24044, this is just another case of innodb asserting of filesystem issues during mariabackup. However it would be good to handle it the same way.

A simpler case is just a permission denied on ib_logfile0:

$ sudo -u tom gdb --args extra/mariabackup/mariabackup --user=root --target-dir=/tmp/b --socket=/tmp/build-mariadb-server-10.3.sock  --backup
GNU gdb (GDB) Fedora 12.1-1.fc36
Copyright (C) 2022 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law.
Type "show copying" and "show warranty" for details.
This GDB was configured as "x86_64-redhat-linux-gnu".
Type "show configuration" for configuration details.
For bug reporting instructions, please see:
<https://www.gnu.org/software/gdb/bugs/>.
Find the GDB manual and other documentation resources online at:
    <http://www.gnu.org/software/gdb/documentation/>.
 
For help, type "help".
Type "apropos word" to search for commands related to "word"...
Reading symbols from extra/mariabackup/mariabackup...
(gdb) run
Starting program: /home/dan/repos/build-mariadb-server-10.3/extra/mariabackup/mariabackup --user=root --target-dir=/tmp/b --socket=/tmp/build-mariadb-server-10.3.sock --backup
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib64/libthread_db.so.1".
[00] 2022-08-29 09:43:16 Connecting to MySQL server host: localhost, user: root, password: not set, port: not set, socket: /tmp/build-mariadb-server-10.3.sock
[00] 2022-08-29 09:43:16 Using server version 10.3.37-MariaDB
[00] 2022-08-29 09:43:16 Warning: option 'datadir' has different values:
  '/var/lib/mysql' in defaults file
  '/tmp/build-mariadb-server-10.3-datadir/' in SHOW VARIABLES
/home/dan/repos/build-mariadb-server-10.3/extra/mariabackup/mariabackup based on MariaDB server 10.3.37-MariaDB Linux (x86_64)
[00] 2022-08-29 09:43:16 uses posix_fadvise().
[00] 2022-08-29 09:43:16 cd to /tmp/build-mariadb-server-10.3-datadir/
[00] 2022-08-29 09:43:16 open files limit requested 0, set to 1024
[00] 2022-08-29 09:43:16 mariabackup: using the following InnoDB configuration:
[00] 2022-08-29 09:43:16 innodb_data_home_dir = 
[00] 2022-08-29 09:43:16 innodb_data_file_path = ibdata1:12M:autoextend
[00] 2022-08-29 09:43:16 innodb_log_group_home_dir = ./
[00] 2022-08-29 09:43:16 InnoDB: Using Linux native AIO
2022-08-29  9:43:16 0 [Note] InnoDB: Number of pools: 1
2022-08-29  9:43:16 0 [Warning] InnoDB: Unable to open "./ib_logfile0" to check native AIO read support.
2022-08-29  9:43:16 0 [Warning] InnoDB: Linux Native AIO disabled.
2022-08-29  9:43:16 0 [ERROR] InnoDB: Operating system error number 13 in a file operation.
2022-08-29  9:43:16 0 [ERROR] InnoDB: The error means mysqld does not have the access rights to the directory.
2022-08-29 09:43:16 0x7ffff7c447c0  InnoDB: Assertion failure in file /home/dan/repos/mariadb-server-10.3/storage/innobase/fil/fil0fil.cc line 668
InnoDB: Failing assertion: success
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 mysqld 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.
 
Program received signal SIGABRT, Aborted.
0x00007ffff768ec4c in __pthread_kill_implementation () from /lib64/libc.so.6
Missing separate debuginfos, use: dnf debuginfo-install bzip2-libs-1.0.8-11.fc36.x86_64 glibc-2.35-15.fc36.x86_64 libaio-0.3.111-13.fc36.x86_64 libcap-2.48-4.fc36.x86_64 libgcc-12.2.1-1.fc36.x86_64 libgcrypt-1.10.1-3.fc36.x86_64 libgpg-error-1.45-1.fc36.x86_64 libstdc++-12.2.1-1.fc36.x86_64 libxcrypt-4.4.28-1.fc36.x86_64 libzstd-1.5.2-2.fc36.x86_64 lz4-libs-1.9.3-4.fc36.x86_64 pcre-8.45-1.fc36.1.x86_64 snappy-1.1.9-4.fc36.x86_64 systemd-libs-250.8-1.fc36.x86_64 xz-libs-5.2.5-9.fc36.x86_64 zlib-1.2.11-32.fc36.x86_64
(gdb) bt
#0  0x00007ffff768ec4c in __pthread_kill_implementation () from /lib64/libc.so.6
#1  0x00007ffff763e9c6 in raise () from /lib64/libc.so.6
#2  0x00007ffff76287f4 in abort () from /lib64/libc.so.6
#3  0x0000000000c4954b in ut_dbg_assertion_failed (expr=0xf3116f "success", 
    file=0xf161c0 "/home/dan/repos/mariadb-server-10.3/storage/innobase/fil/fil0fil.cc", line=668)
    at /home/dan/repos/mariadb-server-10.3/storage/innobase/ut/ut0dbg.cc:60
#4  0x0000000000ade1b4 in fil_node_open_file (node=0x1ed7160) at /home/dan/repos/mariadb-server-10.3/storage/innobase/fil/fil0fil.cc:668
#5  0x0000000000add6b4 in fil_node_prepare_for_io (node=0x1ed7160, space=0x1ed6f00)
    at /home/dan/repos/mariadb-server-10.3/storage/innobase/fil/fil0fil.cc:4068
#6  0x0000000000ae0b0d in fil_io (type=..., sync=false, page_id=..., page_size=..., byte_offset=0, len=512, buf=0x1675600 <log_sys+1024>, 
    message=0x0, ignore_missing_space=<optimized out>) at /home/dan/repos/mariadb-server-10.3/storage/innobase/fil/fil0fil.cc:4334
#7  0x0000000000b8537d in log_header_read (header=0) at /home/dan/repos/mariadb-server-10.3/storage/innobase/log/log0log.cc:1372
#8  recv_find_max_checkpoint (max_field=<optimized out>) at /home/dan/repos/mariadb-server-10.3/storage/innobase/log/log0recv.cc:1248
#9  0x00000000005a0708 in xtrabackup_backup_func () at /home/dan/repos/mariadb-server-10.3/extra/mariabackup/xtrabackup.cc:4409
#10 0x000000000059fe58 in main_low (argv=0x1e9f6f8) at /home/dan/repos/mariadb-server-10.3/extra/mariabackup/xtrabackup.cc:6745
#11 main (argc=<optimized out>, argv=0x7fffffffe468) at /home/dan/repos/mariadb-server-10.3/extra/mariabackup/xtrabackup.cc:6548

To avoid assertions on just filesystem permissions and other errors out of control of mariabackup a form of:

diff --git a/storage/innobase/fil/fil0fil.cc b/storage/innobase/fil/fil0fil.cc
index a196303c39f..9ea9fa025f1 100644
--- a/storage/innobase/fil/fil0fil.cc
+++ b/storage/innobase/fil/fil0fil.cc
@@ -665,8 +665,14 @@ static bool fil_node_open_file(fil_node_t* node)
                                        .physical())));
        }
 
+#ifdef MYSQL_SERVER
        ut_a(success);
        ut_a(node->is_open());
+#else
+       if (!success || !node->is_open()) {
+               exit(1);
+       }
+#endif
 
        fil_system.n_open++;
 

Comment by Daniel Black [ 2022-12-06 ]

pr #2281 updated. Sorry for the delay.

Comment by Daniel Black [ 2022-12-07 ]

From marko paraphrased:
pr #2281 - may be pragmatic for 10.3 and 10.4, but for 10.5 or 10.6 and later I’d like to see a "fold up all tents" version.

10.6 - make an effort to propagate errors up the call stack (like MDEV-13542 set the framework for)

Comment by Daniel Black [ 2023-09-19 ]

Tends folded, PR #2281 updated.

Comment by Marko Mäkelä [ 2023-10-06 ]

There is no function log_header_read() in 10.5. In 10.8, MDEV-14425 changed the logic even further. Please create separate pull requests for 10.5 and 10.10.

Generated at Thu Feb 08 08:42:15 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.