[MDEV-29050] mariabackup issues error messages during InnoDB tablespaces export on partial backup preparing Created: 2022-07-06  Updated: 2023-05-03  Resolved: 2023-03-28

Status: Closed
Project: MariaDB Server
Component/s: mariabackup
Affects Version/s: 10.4.20, 10.6.8
Fix Version/s: 10.11.3, 10.4.29, 10.5.20, 10.6.13, 10.8.8, 10.9.6, 10.10.4

Type: Bug Priority: Critical
Reporter: Rob Schwyzer Assignee: Vladislav Lesin
Resolution: Fixed Votes: 1
Labels: None
Environment:

COLO running CentOS Linux release 7.9.2009 (Core)

Attachments: Zip Archive mariabackup_file_missing.zip    
Issue Links:
Relates
relates to MDEV-30670 Partial backup/restore operation fail... Open

 Description   

User upgraded from MariaDB Community Server 10.2 to 10.4. User had setup automation to check output of mariabackup --prepare to ensure no errors occurred which could imperil the health of the backup.

The basic procedure is to take a partial backup using tables-exclude or similar. Prepare is then performed with export.

In general, mariabackup does not seem to explicitly track what tables were excluded between backup and prepare steps. In 10.2, during prepare export we see-

2022-07-06 18:01:51 140608802916480 [Warning] InnoDB: Tablespace 5 was not found at ./mariadbslap/Slap2.ibd when restoring a (partial?) backup. All redo log for this file will be ignored!

To be clear, the backup stage for the above log snippet used tables-exclude='Slap2' successfully. The good news for 10.2 is this is flagged as a Warning, recognizing that prepare export simply does not know if this is a problem or not and it may be legitimate/intended behavior.

10.4 (possibly 10.3; most explicitly, possibly 10.3.5) changes this for the worse-

2022-07-06 17:00:51 0 [ERROR] InnoDB: Operating system error number 2 in a file operation.
 
2022-07-06 17:00:51 0 [ERROR] InnoDB: The error means the system cannot find the path specified.
 
2022-07-06 17:00:51 0 [ERROR] InnoDB: If you are installing InnoDB, remember that you must create directories yourself, InnoDB does not create them.
 
2022-07-06 17:00:51 0 [ERROR] InnoDB: Cannot open datafile for read-only: './mariadbslap/Slap2.ibd' OS error: 71
 
2022-07-06 17:00:51 0 [ERROR] InnoDB: Operating system error number 2 in a file operation.
 
2022-07-06 17:00:51 0 [ERROR] InnoDB: The error means the system cannot find the path specified.
 
2022-07-06 17:00:51 0 [ERROR] InnoDB: If you are installing InnoDB, remember that you must create directories yourself, InnoDB does not create them.
 
2022-07-06 17:00:51 0 [ERROR] InnoDB: Could not find a valid tablespace file for ``mariadbslap`.`Slap2``. Please refer to https://mariadb.com/kb/en/innodb-data-dictionary-troubleshooting/ for how to resolve the issue.

So now in 10.4, it is referencing the same table which 10.2 identified, but instead of throwing a WARNING, 10.4 is putting an ERROR into its output. While it seems both 10.2 and 10.4 return 0 indicating a successful process exit, users practicing due diligence are rightly going to see an ERROR entry and figure out what to do about it. Between the 10.2 and 10.4 behaviors, the 10.2 behavior of flagging this as a WARNING is preferable because it differentiates the issue from breaking errors, especially given this is just expected partial backup operation. And while the specific concern being expressed here is for how this makes life difficult for automation, it is also worth pointing out that 10.4's behavior makes it less clear than 10.2 does for what is going on and what may be the cause, such that it is likely to cause even experienced DBAs who have not encountered this situation yet cause to panic and worry that their partial backup is broken.

In an ideal case though, no errors or warnings should be thrown for table files which are missing due to exclusions made during mariabackup backup. According to our KB documentation for --tables-exclude-

If a backup is a partial backup, then Mariabackup will record that detail in the xtrabackup_info file.

In short, mariabackup currently advertises retaining this information for it to use later. This is the behavior we would like to see mariabackup prepare export provide.

The problematic behavior can be reproduced via the following steps on MariaDB Community Server 10.6.8:

# Note that binary logging must be enabled and active in the MariaDB Server instance for this to work
 
mariabackup_password='securePasswordHere';
 
backup_path='/where/i/want/my/backup/to/go;
 
backup_log='/where/i/want/my/prepre/log/to/go;
 
 
 
mariadb -e "CREATE USER 'mariabackup'@'localhost' IDENTIFIED BY '${mariabackup_password}';";
 
mariadb -e "GRANT RELOAD, PROCESS, LOCK TABLES, BINLOG MONITOR ON *.* TO 'mariabackup'@'localhost';";
 
 
 
# Create database and tables
 
mariadb -e 'CREATE DATABASE mariadbslap';
 
mariadb mariadbslap -e 'CREATE TABLE Slap (i int);';
 
mariadb mariadbslap -e 'CREATE TABLE Slap2 (i int);';
 
 
 
# Create some writes on the table
 
for ((i=1; i<2000; i++)) ; do
 
  # Once the workload has gotten a little bit in...
 
  if (($i == 100)) ; then
 
    # Start a backup in parallel so writes can continue to roll in during the backup (forces mariabackup to need to leverage logs to obtain point in time consistency during prepare later on)
 
   mariabackup --backup -u mariabackup -p"${mariabackup_password}" --target-dir="${backup_path}" --tables-exclude='Slap2' &
 
  fi;
 
 
 
  # Generate writes on both the included and excluded tables
 
  mariadb mariadbslap -e 'INSERT INTO Slap VALUES ('"${i}"');';
 
  mariadb mariadbslap -e 'INSERT INTO Slap2 VALUES ('"${i}"');';
 
done;
 
 
 
# Prepare the backup
 
mariabackup --export --prepare -u mariabackup -p"${mariabackup_password}" --target-dir="${backup_path}" 2>&1 | tee "${backup_log}";

In the output for the last mariabackup command you should see [ERROR] InnoDB: Operating system error number 2 in a file operation..

You can adapt the above procedure for Community Server 10.2 by adjusting the mariabackup user GRANT to-

GRANT RELOAD, PROCESS, LOCK TABLES, REPLICATION CLIENT ON *.* TO 'mariabackup'@'localhost';

The process is otherwise the same and should output a WARNING instead of an ERROR.

A .zip is attached with log output from backup and {{prepare}] commands run from the above procedure for MariaDB versions 10.2.27, 10.2.43, 10.4.20, and 10.6.8.

 Comments   
Comment by Thejaka Kanewala [ 2022-07-07 ]

In an attempt to fix this issue, I created this PR – https://github.com/MariaDB/server/pull/2183.
The PR also includes a MTR test case that reproduces the issue.

Appreciate your review comments.
Further, if there are issues with PR, please let me know.

Thanks
Thejaka

Comment by Thejaka Kanewala [ 2022-07-07 ]

Further, I have a feeling the issue might have an impact on incremental 'backup restores' and restores with rollback_xa. Yet to test this in a MTR test, in the mean time I would like to know Maria's opinion on this.

Thanks
Thejaka

Comment by Thejaka Kanewala [ 2022-08-04 ]

Addressed the review comments for https://github.com/MariaDB/server/pull/2183.
I am sorry for the delay.

Thank you
-Thejaka

Comment by Marko Mäkelä [ 2022-08-24 ]

I am only guessing here, because I did not investigate this in detail. Possibly the undo log format change of MDEV-12288 is playing a role here. The undo log would refer to an excluded table, which would cause the export operation to fail. Before MDEV-12288, the undo log written by INSERT operations would be discarded already on transaction commit.

I posted a comment to thejaka’s pull request. I think that it may break the export logic. If the problem is that undo log records are referring to excluded tables, that should be addressed at a lower level. If my guess about MDEV-12288 is correct, then a similar problem should be possible in 10.2 if the INSERT statement was replaced with an UPDATE or DELETE.

Comment by Thejaka Kanewala [ 2022-09-01 ]

Addressed the above review feedback from Marko and revised the PR. The revised PR is in https://github.com/MariaDB/server/pull/2183.

The revised fix has the following:

1. Revert the code changes made in the previous submission
2. Added code to exclude tables that are not in the data directory when processing undo log records during recovery and in RESTORE_EXPORT mode. The basic idea is that if a transaction includes multiple tables and if we export only a subset of those tables, then during recovery we apply relevant to non-existing tables.

Appreciate your feedback on the revised PR.

Comment by Marko Mäkelä [ 2022-09-09 ]

thejaka, I think that it would be better to adjust the low-level code that triggers the error than to duplicate some logic. I think that a better approach would be to check the latest 10.6 branch and identify the code that causes the trouble, and add some conditions of srv_operation as needed.

Once we have something that works for 10.6, we can see how to backport that to earlier major versions. The data dictionary interface was heavily refactored in 10.6 to support atomic DDL.

Comment by Marko Mäkelä [ 2022-09-14 ]

I can reproduce the following with some changes to an existing test:

diff --git a/mysql-test/suite/mariabackup/partial_exclude.test b/mysql-test/suite/mariabackup/partial_exclude.test
 
index 3642a2c6f46..a404daa9ff6 100644
 
--- a/mysql-test/suite/mariabackup/partial_exclude.test
 
+++ b/mysql-test/suite/mariabackup/partial_exclude.test
 
@@ -14,10 +14,14 @@ INSERT INTO t1 VALUES(1);
 
 CREATE TABLE t2(i int) ENGINE INNODB;
 
 
 CREATE DATABASE db2;
 
-USE db2;
 
-CREATE TABLE t1(i INT) ENGINE INNODB;
 
+CREATE TABLE db2.t1(i INT) ENGINE INNODB;
 
+
 
+connect con1,localhost,root;
 
+send INSERT INTO t1 SELECT * FROM seq_1_to_2000;
 
+connect con2,localhost,root;
 
+send INSERT INTO db2.t1 SELECT * FROM seq_1_to_2000;
 
 
-USE test;
 
+connection default;
 
 
 echo # xtrabackup backup;
 
 
@@ -47,4 +51,9 @@ DROP DATABASE db2;
 
 rmdir $MYSQLD_DATADIR/db3;
 
 rmdir $MYSQLD_DATADIR/db4;
 
 rmdir $MYSQLD_DATADIR/db5;
 
+
 
+--disable_result_log
 
+exec rr record $XTRABACKUP --defaults-file=$MYSQLTEST_VARDIR/my.cnf --export --prepare --target-dir="$targetdir";
 
+--enable_result_log
 
+
 
 rmdir $targetdir;


mkdir /dev/shm/rr
 
_RR_TRACE_DIR=/dev/shm/rr ./mtr mariabackup.partial_exclude
 
rr replay /dev/shm/rr/latest-trace

(The rr record command in the test should not be part of the final modification to the test.)

10.6 1872a142b5f827758a68e7ee745b3451f5dbea2e

 
2022-09-14 16:44:38 0 [Note] InnoDB: 128 rollback segments are active.
 
2022-09-14 16:44:38 0 [ERROR] InnoDB: Operating system error number 2 in a file operation.
 
2022-09-14 16:44:38 0 [ERROR] InnoDB: The error means the system cannot find the path specified.
 
2022-09-14 16:44:38 0 [ERROR] InnoDB: Cannot open datafile for read-only: './db2/t1.ibd' OS error: 71
 
2022-09-14 16:44:38 0 [ERROR] InnoDB: Operating system error number 2 in a file operation.
 
2022-09-14 16:44:38 0 [ERROR] InnoDB: The error means the system cannot find the path specified.
 
2022-09-14 16:44:38 0 [ERROR] InnoDB: Could not find a valid tablespace file for db2/t1. Please refer to https://mariadb.com/kb/en/innodb-data-dictionary-troubleshooting/ for how to resolve the issue.
 
2022-09-14 16:44:38 0 [Warning] InnoDB: Ignoring tablespace for db2/t1 because it could not be opened.
 
2022-09-14 16:44:38 0 [ERROR] InnoDB: Operating system error number 2 in a file operation.
 
2022-09-14 16:44:38 0 [ERROR] InnoDB: The error means the system cannot find the path specified.
 
2022-09-14 16:44:38 0 [ERROR] InnoDB: Cannot open datafile for read-only: './test/t2.ibd' OS error: 71
 
2022-09-14 16:44:38 0 [ERROR] InnoDB: Operating system error number 2 in a file operation.
 
2022-09-14 16:44:38 0 [ERROR] InnoDB: The error means the system cannot find the path specified.
 
2022-09-14 16:44:38 0 [ERROR] InnoDB: Could not find a valid tablespace file for test/t2. Please refer to https://mariadb.com/kb/en/innodb-data-dictionary-troubleshooting/ for how to resolve the issue.
 
2022-09-14 16:44:38 0 [Warning] InnoDB: Ignoring tablespace for test/t2 because it could not be opened.
 
2022-09-14 16:44:38 0 [Note] InnoDB: Creating shared tablespace for temporary tables
 
2022-09-14 16:44:38 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
 
2022-09-14 16:44:38 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
 
2022-09-14 16:44:38 0 [Note] InnoDB: 10.6.10 started; log sequence number 0; transaction id 43
 
…
 
2022-09-14 16:44:38 0 [Note] InnoDB: Loading buffer pool(s) from /dev/shm/10.6/mysql-test/var/tmp/backup/ib_buffer_pool
 
2022-09-14 16:44:38 0 [Note] InnoDB: Cannot open '/dev/shm/10.6/mysql-test/var/tmp/backup/ib_buffer_pool' for reading: No such file or directory
 
2022-09-14 16:44:38 0 [ERROR] InnoDB: Operating system error number 2 in a file operation.
 
2022-09-14 16:44:38 0 [ERROR] InnoDB: The error means the system cannot find the path specified.
 
2022-09-14 16:44:38 0 [ERROR] InnoDB: Cannot open datafile for read-only: './db2/t1.ibd' OS error: 71
 
2022-09-14 16:44:38 0 [ERROR] InnoDB: Operating system error number 2 in a file operation.
 
2022-09-14 16:44:38 0 [ERROR] InnoDB: The error means the system cannot find the path specified.
 
2022-09-14 16:44:38 0 [ERROR] InnoDB: Could not find a valid tablespace file for db2/t1. Please refer to https://mariadb.com/kb/en/innodb-data-dictionary-troubleshooting/ for how to resolve the issue.

For some reason, my breakpoints would not work in rr, so I cannot determine the call stacks for those messages.

When it comes to the server version that I tested, this appears to be a cosmetic error to me: the non-excluded data files ought to be exported just fine. I think that the correct fix would be to suppress those messages if the file names match the exclude patterns.

Side note: In mariabackup --export, there should be no need to create an InnoDB temporary tablespace.

Comment by Marko Mäkelä [ 2022-09-14 ]

10.4 is a bit more spammy:

10.4 3e3cfa893481abe9524a1657c4246fa9f91d4826

 
2022-09-14 17:00:53 0 [Note] InnoDB: Completed initialization of buffer pool
 
2022-09-14 17:00:53 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
 
2022-09-14 17:00:53 0 [Note] InnoDB: Setting log file ./ib_logfile101 size to 5242880 bytes
 
2022-09-14 17:00:53 0 [Note] InnoDB: Setting log file ./ib_logfile1 size to 5242880 bytes
 
2022-09-14 17:00:53 0 [Note] InnoDB: Renaming log file ./ib_logfile101 to ./ib_logfile0
 
2022-09-14 17:00:53 0 [Note] InnoDB: New log files created, LSN=406567
 
2022-09-14 17:00:53 0 [ERROR] InnoDB: Operating system error number 2 in a file operation.
 
2022-09-14 17:00:53 0 [ERROR] InnoDB: The error means the system cannot find the path specified.
 
2022-09-14 17:00:53 0 [ERROR] InnoDB: If you are installing InnoDB, remember that you must create directories yourself, InnoDB does not create them.
 
2022-09-14 17:00:53 0 [ERROR] InnoDB: Cannot open datafile for read-only: './db2/t1.ibd' OS error: 71
 
2022-09-14 17:00:53 0 [ERROR] InnoDB: Operating system error number 2 in a file operation.
 
2022-09-14 17:00:53 0 [ERROR] InnoDB: The error means the system cannot find the path specified.
 
2022-09-14 17:00:53 0 [ERROR] InnoDB: If you are installing InnoDB, remember that you must create directories yourself, InnoDB does not create them.
 
2022-09-14 17:00:53 0 [ERROR] InnoDB: Could not find a valid tablespace file for ``db2`.`t1``. Please refer to https://mariadb.com/kb/en/innodb-data-dictionary-troubleshooting/ for how to resolve the issue.
 
2022-09-14 17:00:53 0 [Warning] InnoDB: Ignoring tablespace for `db2`.`t1` because it could not be opened.
 
2022-09-14 17:00:53 0 [ERROR] InnoDB: Operating system error number 2 in a file operation.
 
2022-09-14 17:00:53 0 [ERROR] InnoDB: The error means the system cannot find the path specified.
 
2022-09-14 17:00:53 0 [ERROR] InnoDB: If you are installing InnoDB, remember that you must create directories yourself, InnoDB does not create them.
 
2022-09-14 17:00:53 0 [ERROR] InnoDB: Cannot open datafile for read-only: './test/t2.ibd' OS error: 71
 
2022-09-14 17:00:53 0 [ERROR] InnoDB: Operating system error number 2 in a file operation.
 
2022-09-14 17:00:53 0 [ERROR] InnoDB: The error means the system cannot find the path specified.
 
2022-09-14 17:00:53 0 [ERROR] InnoDB: If you are installing InnoDB, remember that you must create directories yourself, InnoDB does not create them.
 
2022-09-14 17:00:53 0 [ERROR] InnoDB: Could not find a valid tablespace file for ``test`.`t2``. Please refer to https://mariadb.com/kb/en/innodb-data-dictionary-troubleshooting/ for how to resolve the issue.
 
2022-09-14 17:00:53 0 [Warning] InnoDB: Ignoring tablespace for `test`.`t2` because it could not be opened.
 
2022-09-14 17:00:53 0 [Note] InnoDB: 128 out of 128 rollback segments are active.
 
2022-09-14 17:00:53 0 [Note] InnoDB: Creating shared tablespace for temporary tables
 
2022-09-14 17:00:53 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
 
2022-09-14 17:00:53 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
 
…
 
2022-09-14 17:00:53 6 [Note] InnoDB: Sync to disk of `mysql`.`innodb_index_stats` started.
 
2022-09-14 17:00:53 6 [Note] InnoDB: Stopping purge
 
2022-09-14 17:00:53 4 [ERROR] InnoDB: Operating system error number 2 in a file operation.
 
2022-09-14 17:00:53 4 [ERROR] InnoDB: The error means the system cannot find the path specified.
 
2022-09-14 17:00:53 4 [ERROR] InnoDB: Cannot open datafile for read-only: './db2/t1.ibd' OS error: 71
 
2022-09-14 17:00:53 4 [ERROR] InnoDB: Operating system error number 2 in a file operation.
 
2022-09-14 17:00:53 4 [ERROR] InnoDB: The error means the system cannot find the path specified.
 
2022-09-14 17:00:53 4 [ERROR] InnoDB: Could not find a valid tablespace file for ``db2`.`t1``. Please refer to https://mariadb.com/kb/en/innodb-data-dictionary-troubleshooting/ for how to resolve the issue.
 
2022-09-14 17:00:54 6 [Note] InnoDB: Writing table metadata to './mysql/innodb_index_stats.cfg'
 
2022-09-14 17:00:54 6 [Note] InnoDB: Table `mysql`.`innodb_index_stats` flushed to disk
 
2022-09-14 17:00:54 6 [Note] InnoDB: Resuming purge
 
…

Comment by Vladislav Lesin [ 2023-03-20 ]

The difference between 10.3 and 10.6 is in "strict" variable calculation in fil_ibd_open() .

10.3:

        /* Always look for a file at the default location. But don't log        
        an error if the tablespace is already open in remote or dict. */        
        ut_a(df_default.filepath());                                            
        const bool      strict = (tablespaces_found == 0);                      
        if (df_default.open_read_only(strict) == DB_SUCCESS) {                  
                ut_ad(df_default.is_open());                                    
                ++tablespaces_found;                                            
        }

10.6

        /* Always look for a file at the default location. But don't log        
        an error if the tablespace is already open in remote or dict. */        
        ut_a(df_default.filepath());                                            
                                                                                
        /* Mariabackup will not copy files whose names start with               
        #sql-. We will suppress messages about such files missing on            
        the first server startup. The tables ought to be dropped by             
        drop_garbage_tables_after_restore() a little later. */                  
                                                                                
        const bool strict = validate && !tablespaces_found                      
                && !(srv_operation == SRV_OPERATION_NORMAL                      
                     && srv_start_after_restore                                 
                     && srv_force_recovery < SRV_FORCE_NO_BACKGROUND            
                     && dict_table_t::is_temporary_name(                        
                             df_default.filepath()));                           
                                                                                
        if (df_default.open_read_only(strict) == DB_SUCCESS) {                  
                ut_ad(df_default.is_open());                                    
                ++tablespaces_found;                                            
        }

We could partially repeat the logic in 10.[345] to fix the bug.

Generated at Thu Feb 08 10:05:30 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.