Details
-
Bug
-
Status: Closed (View Workflow)
-
Major
-
Resolution: Fixed
-
10.5, 10.6, 10.11, 11.4, 11.8
-
None
Description
mariabackup.partial test case fails with
mariabackup.partial w8 [ fail ]
Test ended at 2025-03-14 13:40:14
CURRENT_TEST: mariabackup.partial
|
mysqltest: At line 44: exec of '/home/buildbot/amd64-rhel-9/build/extra/mariabackup/mariabackup --defaults-file=/home/buildbot/amd64-rhel-9/build/mysql-test/var/8/tmp/backup/server.cnf --defaults-group-suffix=.1 --prepare --export --target-dir=/home/buildbot/amd64-rhel-9/build/mysql-test/var/8/tmp/backup 2>&1' failed, error: 256, status: 1, errno: 0
|
Output from before failure:
|
Warning: option 'use-memory': signed value -1 adjusted to 8388608
|
[00] 2025-03-14 20:37:06 mariabackup: auto-enabling --innodb-file-per-table due to the --export option
|
[00] 2025-03-14 20:37:06 cd to /home/thiru/source_file/server/11.4-test/bld_new-debug/backup/
|
[00] 2025-03-14 20:37:06 open files limit requested 0, set to 1024
|
[00] 2025-03-14 20:37:06 This target seems to be not prepared yet.
|
[00] 2025-03-14 20:37:07 mariabackup: using the following InnoDB configuration for recovery:
|
[00] 2025-03-14 20:37:07 innodb_data_home_dir = .
|
[00] 2025-03-14 20:37:07 innodb_data_file_path = ibdata1:12M:autoextend
|
[00] 2025-03-14 20:37:07 innodb_log_group_home_dir = .
|
[00] 2025-03-14 20:37:07 InnoDB: Using Linux native AIO
|
[00] 2025-03-14 20:37:07 Starting InnoDB instance for recovery.
|
[00] 2025-03-14 20:37:07 mariabackup: Using 104857600 bytes for buffer pool (set by --use-memory parameter)
|
2025-03-14 20:37:07 0 [Note] InnoDB: !!!!!!!! UNIV_DEBUG switched on !!!!!!!!!
|
2025-03-14 20:37:07 0 [Note] InnoDB: Compressed tables use zlib 1.3
|
2025-03-14 20:37:07 0 [Note] InnoDB: Number of transaction pools: 1
|
2025-03-14 20:37:07 0 [Note] InnoDB: Using crc32 + pclmulqdq instructions
|
2025-03-14 20:37:07 0 [Note] InnoDB: Using Linux native AIO
|
2025-03-14 20:37:07 0 [Note] InnoDB: Initializing buffer pool, total size = 100.000MiB, chunk size = 100.000MiB
|
2025-03-14 20:37:07 0 [Note] InnoDB: Completed initialization of buffer pool
|
2025-03-14 20:37:07 0 [Note] InnoDB: Memory-mapped log (block size=512 bytes)
|
2025-03-14 20:37:07 0 [Note] InnoDB: Starting crash recovery from checkpoint LSN=62015
|
2025-03-14 20:37:07 0 [Note] InnoDB: End of log at LSN=73164
|
2025-03-14 20:37:07 0 [ERROR] InnoDB: Missing FILE_CREATE, FILE_DELETE or FILE_MODIFY before FILE_CHECKPOINT for tablespace 4
|
[00] 2025-03-14 20:37:07 mariadb-backup: srv_start() returned 37 (Data structure corruption).
|
This issue happens only when mariabackup --backup does partial backup. Attaching the failed backup directory to repeat
the scenario.
Let me explain why this test case fails:
|
|
During first scan:
|
==================
|
checkpoint_lsn : 62015 end_lsn: 71115
|
fil_name_process name ./test/t1.ibd space_id 11 lsn 71115 deleted 0
|
fil_name_process name ./test/t21.ibd space_id 12 lsn 71115 deleted 0
|
fil_name_process name ./test/t2.ibd space_id 13 lsn 71115 deleted 0
|
lsn 71183 space_id 0 page_no 0
|
lsn 71183 FILE_CHECKPOINT 62015
|
|
|
2nd scan:
|
=========
|
2025-03-13 13:02:36 0 [Note] InnoDB: Starting crash recovery from checkpoint LSN=62015
|
lsn 62025 space_id 0 page_no 7
|
lsn 62081 space_id 3 page_no 45
|
lsn 62095 space_id 0 page_no 8
|
lsn 62109 space_id 0 page_no 9
|
lsn 62133 space_id 0 page_no 9
|
lsn 62192 space_id 3 page_no 45
|
lsn 62213 space_id 0 page_no 10
|
lsn 62240 space_id 3 page_no 45
|
lsn 62296 space_id 0 page_no 10
|
lsn 62355 space_id 3 page_no 45
|
lsn 62376 space_id 0 page_no 10
|
lsn 62403 space_id 3 page_no 45
|
lsn 62454 space_id 0 page_no 10
|
lsn 62520 space_id 3 page_no 45
|
lsn 62535 space_id 0 page_no 11
|
lsn 62566 space_id 3 page_no 45
|
lsn 62639 space_id 0 page_no 11
|
......
|
......
|
lsn 63281 space_id 4 page_no 3
|
lsn 63338 space_id 2 page_no 46
|
.....
|
....
|
fil_name_process name ./test/t1.ibd space_id 11 lsn 70401 deleted 0
|
fil_name_process name ./test/t21.ibd space_id 12 lsn 70401 deleted 0
|
fil_name_process name ./test/t2.ibd space_id 13 lsn 70401 deleted 0
|
lsn 70537 space_id 0 page_no 0
|
lsn 70537 FILE_CHECKPOINT 59814
|
....
|
.....
|
fil_name_process name ./mysql/innodb_table_stats.ibd space_id 4 lsn 70673 deleted 0
|
fil_name_process name ./mysql/innodb_index_stats.ibd space_id 5 lsn 70673 deleted 0
|
fil_name_process name ./test/t1.ibd space_id 11 lsn 70673 deleted 0
|
fil_name_process name ./test/t21.ibd space_id 12 lsn 70673 deleted 0
|
fil_name_process name ./test/t2.ibd space_id 13 lsn 70673 deleted 0
|
lsn 70809 FILE_CHECKPOINT 59910
|
.....
|
fil_name_process name ./test/t1.ibd space_id 11 lsn 71047 deleted 0
|
fil_name_process name ./test/t21.ibd space_id 12 lsn 71047 deleted 0
|
fil_name_process name ./test/t2.ibd space_id 13 lsn 71047 deleted 0
|
lsn 71115 space_id 0 page_no 0
|
lsn 71115 FILE_CHECKPOINT 61700
|
fil_name_process name ./test/t1.ibd space_id 11 lsn 71115 deleted 0
|
fil_name_process name ./test/t21.ibd space_id 12 lsn 71115 deleted 0
|
fil_name_process name ./test/t2.ibd space_id 13 lsn 71115 deleted 0
|
lsn 71183 space_id 0 page_no 0
|
lsn 71183 FILE_CHECKPOINT 62015
|
.....
|
.....
|
.....
|
fil_name_process name ./mysql/innodb_table_stats.ibd space_id 4 lsn 73045 deleted 0
|
fil_name_process name ./test/t1.ibd space_id 11 lsn 73045 deleted 0
|
fil_name_process name ./mysql/innodb_index_stats.ibd space_id 5 lsn 73045 deleted 0
|
fil_name_process name ./test/t21.ibd space_id 12 lsn 73045 deleted 0
|
lsn 73164 space_id 0 page_no 0
|
lsn 73164 FILE_CHECKPOINT 71526
|
|
|
2025-03-13 13:02:36 0 [Note] InnoDB: End of log at LSN=73164
|
2025-03-13 13:02:36 0 [ERROR] InnoDB: Missing FILE_CREATE, FILE_DELETE or FILE_MODIFY before FILE_CHECKPOINT for tablespace 4
|
backup is done using "--tables=test.*1" So it doesn't backup index_stats.ibd and table_stats.ibd file
While parsing lsn 63281 space_id 4 page_no 3 , InnoDB adds the space id in recv_spaces with "" empty string.
It anticipates that in future, it may encounter the FILE_MODIFY for the tablespace.
During lsn 70673, InnoDB does read FILE_MODIFY for innodb_index_stats and innodb_table_stats table.
But fil_name_process() fails to load the tablespace (fil_ibd_load() ) fails with FIL_LOAD_NOT_FOUND
and left the recv_spaces with empty string
else if (lsn < file_checkpoint)
|
/* We have not seen all records between the checkpoint and
|
FILE_CHECKPOINT. There should be a FILE_DELETE for this
|
tablespace later. */
|
recv_spaces.emplace_hint(i, space_id, file_name_t("", false));
|
This error is wrong though:
2025-03-13 13:02:36 0 [ERROR] InnoDB: Missing FILE_CREATE, FILE_DELETE or FILE_MODIFY before FILE_CHECKPOINT for tablespace 4
|
We encounter the FIL_MODIFY for the tablespace 4 and failed to open it due to partial backup.
|
Note: There is no way to identify whether mariabackup --prepare has been executed on some partial backup target directory.
We do write the partial: Y in xtrabackup_info file. But during --prepare, we don't read the file though. Can we read the file during --prepare
and create new srv_operation mode as SRV_OPERATION_RESTORE_EXPORT_PARTIAL or SRV_OPERATION_RESTORE_PARTIAL.?
Attachments
Activity
I would like us to distinguish the case where the FILE_ records are actually missing (the log is corrupted), and the case where no file by any of the names is found. In the latter case, it would be good if the error message disclosed one of the parsed file names. When we are preparing a partial backup, then we would suppress the latter error but not the former one.
The backup.zip
is from MariaDB Server 11.4. I reproduced the problem using it and posted some suggestions to https://github.com/MariaDB/server/pull/3990 on how to improve the fix further. The following is what I got when preparing the backup with a 10.11 based executable with my suggested fixes:
10.11/extra/mariabackup/mariadb-backup based on MariaDB server 10.11.12-MariaDB Linux (x86_64)
|
[00] 2025-04-22 13:27:58 cd to /dev/shm/backup/
|
[00] 2025-04-22 13:27:58 open files limit requested 0, set to 1024
|
[00] 2025-04-22 13:27:58 This target seems to be already prepared.
|
[00] 2025-04-22 13:27:58 mariabackup: using the following InnoDB configuration for recovery:
|
[00] 2025-04-22 13:27:58 innodb_data_home_dir = .
|
[00] 2025-04-22 13:27:58 innodb_data_file_path = ibdata1:12M:autoextend
|
[00] 2025-04-22 13:27:58 innodb_log_group_home_dir = .
|
[00] 2025-04-22 13:27:58 InnoDB: Using liburing
|
[00] 2025-04-22 13:27:58 Starting InnoDB instance for recovery.
|
[00] 2025-04-22 13:27:58 mariabackup: Using 100663296 bytes for buffer pool (set by --use-memory parameter)
|
2025-04-22 13:27:58 0 [Note] InnoDB: !!!!!!!! UNIV_DEBUG switched on !!!!!!!!!
|
2025-04-22 13:27:58 0 [Note] InnoDB: Compressed tables use zlib 1.3.1
|
2025-04-22 13:27:58 0 [Note] InnoDB: Number of transaction pools: 1
|
2025-04-22 13:27:58 0 [Note] InnoDB: Using crc32 + pclmulqdq instructions
|
2025-04-22 13:27:58 0 [Note] InnoDB: innodb_buffer_pool_size_max=96m, innodb_buffer_pool_size=96m
|
2025-04-22 13:27:58 0 [Note] InnoDB: Completed initialization of buffer pool
|
2025-04-22 13:27:58 0 [Note] InnoDB: Memory-mapped log (block size=512 bytes)
|
2025-04-22 13:27:58 0 [Note] InnoDB: At LSN: 71183: unable to open file ./test/t2.ibd for tablespace 13
|
2025-04-22 13:27:58 0 [Note] InnoDB: Starting crash recovery from checkpoint LSN=62015
|
2025-04-22 13:27:58 0 [Note] InnoDB: At LSN: 70537: unable to open file ./mysql/innodb_table_stats.ibd for tablespace 4
|
2025-04-22 13:27:58 0 [Note] InnoDB: At LSN: 70537: unable to open file ./mysql/innodb_index_stats.ibd for tablespace 5
|
2025-04-22 13:27:58 0 [Note] InnoDB: End of log at LSN=73164
|
2025-04-22 13:27:58 0 [Warning] InnoDB: Tablespace 4 was not found at ./mysql/innodb_table_stats.ibd when restoring a (partial?) backup. All redo log for this file will be ignored!
|
2025-04-22 13:27:58 0 [Warning] InnoDB: Tablespace 5 was not found at ./mysql/innodb_index_stats.ibd when restoring a (partial?) backup. All redo log for this file will be ignored!
|
2025-04-22 13:27:58 0 [Warning] InnoDB: Tablespace 13 was not found at ./test/t2.ibd when restoring a (partial?) backup. All redo log for this file will be ignored!
|
2025-04-22 13:27:58 0 [Note] InnoDB: To recover: 30 pages
|
2025-04-22 13:27:58 0 [Note] InnoDB: Buffered log writes (block size=512 bytes)
|
[00] 2025-04-22 13:27:58 Last binlog file , position 0
|
[00] 2025-04-22 13:27:58 completed OK!
|
I think that the existing warnings for missing files should be sufficient for now, even though they can be considered to be ‘noise’ when restoring a partial backup. But then again, the output is rather noisy to begin with.
https://github.com/MariaDB/server/pull/3908