Apply log on partial backup is giving table space errors

[René Feiner]

I'm using innobackupex 2.4.3 to backup some selected tables from a Percona Server 5.7.11-4-1.wheezy server running on Debian Wheezy. We have innodb-file-per-table enabled.

When applying the log its crashes with reports about tables that are not included in the backup (and not in the backup directory). Please find output here:

InnoDB: xtrabackup: Last MySQL binlog file position 138024332, file name mysql-bin.111408
InnoDB: Creating shared tablespace for temporary tables
InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
InnoDB: File './ibtmp1' size is now 12 MB.
InnoDB: 96 redo rollback segment(s) found. 1 redo rollback segment(s) are active.
InnoDB: 32 non-redo rollback segment(s) are active.
InnoDB: 5.7.11 started; log sequence number 43935355195374
InnoDB: page_cleaner: 1000ms intended loop took 55452ms. The settings might not be optimal. (flushed=0 and evicted=0, during the time.)
InnoDB: Failed to find tablespace for table `[database_name_1]`.`[table_name_1]` in the cache. Attempting to load the tablespace with space id 1002
InnoDB: Operating system error number 2 in a file operation.
InnoDB: The error means the system cannot find the path specified.
InnoDB: Cannot open datafile for read-only: './[database_name_1]/[table_name_1].ibd' OS error: 71
InnoDB: Operating system error number 2 in a file operation.
InnoDB: The error means the system cannot find the path specified.
InnoDB: Could not find a valid tablespace file for `[database_name_1]/[table_name_1]`. Please refer to http://dev.mysql.com/doc/refman/5.7/en/innodb-troubleshooting-datadict.html for how to resolve the issue.
InnoDB: Failed to find tablespace for table `[database_name_2]`.`[table_name_2]` in the cache. Attempting to load the tablespace with space id 878
InnoDB: Operating system error number 2 in a file operation.
InnoDB: The error means the system cannot find the path specified.
InnoDB: Cannot open datafile for read-only: './[database_name_2]/[table_name_2].ibd' OS error: 71
InnoDB: Operating system error number 2 in a file operation.
InnoDB: The error means the system cannot find the path specified.
InnoDB: Could not find a valid tablespace file for `[database_name_2]/[table_name_2]`. Please refer to http://dev.mysql.com/doc/refman/5.7/en/innodb-troubleshooting-datadict.html for how to resolve the issue.
09:46:02 UTC - xtrabackup got signal 11 ;
This could be because you hit a bug or data is corrupted.
This error can also be caused by malfunctioning hardware.
Attempting to collect some information that could help diagnose the problem.
As this is a crash and something is definitely wrong, the information
collection process might fail.

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 = 0 thread_stack 0x10000
innobackupex(my_print_stacktrace+0x2e)[0xd5663e]
innobackupex(handle_fatal_signal+0x252)[0xcf1b32]
/lib/x86_64-linux-gnu/libpthread.so.0(+0xf0a0)[0x7fb5338c20a0]
innobackupex(_Z10ER_DEFAULTi+0x11)[0xb5ce41]
innobackupex(_Z16explain_filenameP3THDPKcPcm26enum_explain_filename_mode+0x400)[0xb833a0]
innobackupex(_Z27innobase_convert_identifierPcmPKcmP3THD+0x6b)[0x93457b]
innobackupex(_Z11ut_get_namePK5trx_tPKc+0x56)[0x9b8e96]
innobackupex(_ZlsRSoRK12table_name_t+0x1c)[0x912ddc]
innobackupex[0xa71dc7]
innobackupex(_Z15dict_load_tablePKcb17dict_err_ignore_t+0x1a3)[0xa72303]
innobackupex(_Z21dict_load_table_on_idm17dict_err_ignore_t+0x59a)[0xa72f1a]
innobackupex(_Z21dict_table_open_on_idmm15dict_table_op_t+0x118)[0x99d868]
innobackupex(_Z14row_purge_stepP9que_thr_t+0x1a2)[0xa44e92]
innobackupex(_Z15que_run_threadsP9que_thr_t+0x635)[0x9f6de5]
innobackupex(_Z9trx_purgemmb+0x5a6)[0x9d1a26]
innobackupex(srv_purge_coordinator_thread+0x675)[0xb49c75]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x6b50)[0x7fb5338b9b50]
/lib/x86_64-linux-gnu/libc.so.6(clone+0x6d)[0x7fb531d7bfbd]

[database_name_1].[table_name_1] and [database_name_2].[table_name_2] are not included/defined in the --database argument when the backup is created.

I tried to also define the tables using --database when applying the log, but that doesn't help.

[Muhammad Irfan (muhammad-irfan)]

Can you please show us the exact commands used for the backup along with MySQL server my.cnf file contents so we can replicate it to investigate.

[Launchpad Janitor (janitor)]

[Expired for Percona XtraBackup because there has been no activity for 60 days.]

[MikeG (mikegriffin)]

Source server db2 config (trying to create chained slave db3):

[mysqld]
sql_mode=ERROR_FOR_DIVISION_BY_ZERO,NO_AUTO_CREATE_USER,NO_ENGINE_SUBSTITUTION
datadir=/data/mysqldata
socket=/data/mysqldata/mysql.sock

bind-address = 0.0.0.0
local-infile = 0

symbolic-links=0

innodb-buffer-pool-size = 90G
innodb-log-file-size = 256M

sync-binlog = 1
innodb-flush-log-at-trx-commit = 1

relay_log_info_repository = TABLE
relay_log_recovery = ON

max-connections = 2000
binlog-format = ROW
log-slave-updates = 1
super-read-only = 1
server-id = 2

log-error=/var/log/mysqld.log
pid-file=/var/run/mysqld/mysqld.pid

#####################
# Export

innobackupex --databases="mysql foo1 foo2 foo3" --stream=xbstream --parallel=3 /home/mg/xtrabackup 2> /home/mg/xtrabackup/xtrabackup_log | pv | ssh

Output:

innobackupex version 2.4.6 based on MySQL server 5.7.13 Linux (x86_64) (revision id: 8ec05b7)

171117 07:37:38 [00] Streaming backup-my.cnf
171117 07:37:38 [00] ...done
171117 07:37:38 [00] Streaming xtrabackup_info
171117 07:37:38 [00] ...done
xtrabackup: Transaction log of lsn (31870395680105) to (31871656801126) was copied.
171117 07:37:39 completed OK!

#####################
# Apply

innobackupex --defaults-file=/data1/add_databases_replication/backup-my.cnf --use-memory=2G --apply-log /data1/add_databases_replication/
171117 10:34:45 innobackupex: Starting the apply-log operation

IMPORTANT: Please check that the apply-log run completes successfully.
           At the end of a successful apply-log run innobackupex
           prints "completed OK!".

innobackupex version 2.4.8 based on MySQL server 5.7.13 Linux (x86_64) (revision id: 97330f7)
xtrabackup: cd to /data1/add_databases_replication/
xtrabackup: This target seems to be not prepared yet.
InnoDB: Number of pools: 1
xtrabackup: xtrabackup_logfile detected: size=1418788864, start_lsn=(31870395680105)
xtrabackup: using the following InnoDB configuration for recovery:
xtrabackup: innodb_data_home_dir = .
xtrabackup: innodb_data_file_path = ibdata1:12M:autoextend
xtrabackup: innodb_log_group_home_dir = .
xtrabackup: innodb_log_files_in_group = 1
xtrabackup: innodb_log_file_size = 1418788864
xtrabackup: using the following InnoDB configuration for recovery:
xtrabackup: innodb_data_home_dir = .
xtrabackup: innodb_data_file_path = ibdata1:12M:autoextend
xtrabackup: innodb_log_group_home_dir = .
xtrabackup: innodb_log_files_in_group = 1
xtrabackup: innodb_log_file_size = 1418788864
xtrabackup: Starting InnoDB instance for recovery.
xtrabackup: Using 2147483648 bytes for buffer pool (set by --use-memory parameter)

InnoDB: 5.7.13 started; log sequence number 31871656801126
InnoDB: page_cleaner: 1000ms intended loop took 148392ms. The settings might not be optimal. (flushed=0 and evicted=0, during the time.)
InnoDB: Failed to find tablespace for table `bar123`.`session` in the cache. Attempting to load the tablespace with space id 456
InnoDB: Operating system error number 2 in a file operation.
InnoDB: The error means the system cannot find the path specified.
InnoDB: Cannot open datafile for read-only: './bar123/session.ibd' OS error: 71
InnoDB: Operatin...

[MikeG (mikegriffin)]

This was a transient error - retrying the same commands worked out ok. I don't have the old binary logs during the failed run unfortunately.

[Shahriyar Rzayev (rzayev-sehriyar)]

Percona now uses JIRA for bug reports so this bug report is migrated to: https://jira.percona.com/browse/PXB-1389