we have one database server that is now failing the prepare stage of our backup and we cant find what could be wrong here… we are now stuck with backups that are older than binlog files on the server. We have tried different versions of xtrabackup from 8.0.20 to 8.0.27. Our server is running 8.0.20 on Debian 10. This is the error and where xtrbackup exits the backup:
Apply batch completed!
Using undo tablespace ‘./undo_001’.
Using undo tablespace ‘./undo_002’.
Opened 2 existing undo tablespaces.
GTID recovery trx_no: 6141955518
Parallel initialization of rseg complete
Time taken to initialize rseg using 4 thread: 25704 ms.
Creating shared tablespace for temporary tables
Setting file ‘./ibtmp1’ size to 12 MB. Physically writing the file full; Please wait …
File ‘./ibtmp1’ size is now 12 MB.
Scanning temp tablespace dir:‘./#innodb_temp/’
Created 128 and tracked 128 new rollback segment(s) in the temporary tablespace. 128 are now active.
8.0.27 started; log sequence number 16093724676457
Page cleaner took 290617ms to flush 0 and evict 0 pages
Allocated tablespace ID 2296 for ym/ym_aa_action_entity_map, old maximum was 0
xtrabackup: innodb_init(): Error occured.
we get different table names in the last Allocated tablespace line… We normally take a backup to our NFS server but this also fails if we stream to secondary server or take a local backup.
would love some suggestions… btw this database is 2.3TB
is there more information available in logs? it is hard to say what is wrong from provided information.
I would start checking permissions, do you have enough space on disk and if you use --use-memory is that amount of memory available to allocate.
we tried moving the backup to our slave and that host has 5.5TB available disk space with about 200GB/ram… we have tried with and without setting use-memory and it fails at the same location every time… we also tried to set apply-log-only option and prepare still failed…
at the top of the prepare I see this:
Operating system error number 2 in a file operation.
The error means the system cannot find the path specified.
xtrabackup: Warning: cannot open ./xtrabackup_logfile. will try to find.
xtrabackup: ‘ib_logfile0’ seems to be ‘xtrabackup_logfile’. will retry.
xtrabackup: xtrabackup_logfile detected: size=3207266304, start_lsn=(16091472430688)
This also looks interesting:
Initializing buffer pool, total size = 128.000000M, instances = 1, chunk size =128.000000M
Completed initialization of buffer pool
page_cleaner coordinator priority: -20
page_cleaner worker priority: -20
page_cleaner worker priority: -20
page_cleaner worker priority: -20
The log sequence number 14904705545163 in the system tablespace does not match the log sequence number 16091472430688 in the ib_logfiles!
Database was not shutdown normally!
Starting crash recovery.
Starting to parse redo log at lsn = 16091472430787, whereas checkpoint_lsn = 16091472430688 and start_lsn = 16091472430592
in the backup log I see lots of these (23 checksum mismatch):
220215 13:01:04 >> log scanned up to (16092394215905)
xtrabackup: warning: Log block checksum mismatch (block no 0 at lsn 16092394574336):
expected 0, calculated checksum 3965168067
xtrabackup: warning: this is possible when the log block has not been fully written by the server, will retry later.
220215 13:01:05 >> log scanned up to (16092394574336)
there are only warnings in this log, no errors… this is the bottom which makes it look like everything was fine
220215 14:08:54 Executing FLUSH NO_WRITE_TO_BINLOG ENGINE LOGS…
xtrabackup: The latest check point (for incremental): ‘16092808336617’
xtrabackup: Stopping log copying thread at LSN 16093724676447.
220215 14:08:54 >> log scanned up to (16093724681940)
220215 14:08:55 Executing UNLOCK TABLES
220215 14:08:55 All tables unlocked
220215 14:08:55 Backup created in directory ‘/srv/upload/’
MySQL binlog position: filename ‘mysql-bin.000087’, position ‘3190’, GTID of the last change ‘551122b7-708e-11eb-9fda-246e9656ce2c:1-27151062’
220215 14:08:55 [00] Writing /srv/upload/backup-my.cnf
220215 14:08:55 [00] …done
220215 14:08:55 [00] Writing /srv/upload/xtrabackup_info
220215 14:08:55 [00] …done
xtrabackup: Transaction log of lsn (16091472430688) to (16093725049279) was copied.
220215 14:08:56 completed OK!
that was my fault … I wanted to capture the log and just re-ran the prepare in a failed directory… here is a run I did on a fresh backup
xtrabackup: recognized server arguments: --innodb_checksum_algorithm=crc32 --innodb_log_checksums=1 --innodb_data_file_path=ibdata1:12M:autoextend --innodb_log_files_in_group=2 --innodb_log_file_size=1073741824 --innodb_page_size=16384 --innodb_undo_directory=./ --innodb_undo_tablespaces=2 --server-id=0 --innodb_log_checksums=ON --innodb_redo_log_encrypt=0 --innodb_undo_log_encrypt=0
xtrabackup: recognized client arguments: --prepare=1 --target-dir=/srv/datadir --use-memory=25G
xtrabackup version 8.0.27-19 based on MySQL server 8.0.27 Linux (x86_64) (revision id: 50dbc8dadda)
xtrabackup: cd to /srv/datadir/
xtrabackup: This target seems to be not prepared yet.
Number of pools: 1
xtrabackup: xtrabackup_logfile detected: size=8388608, start_lsn=(14907979855307)
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 = 8388608
xtrabackup: inititialize_service_handles suceeded
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 = 8388608
xtrabackup: Starting InnoDB instance for recovery.
xtrabackup: Using 26843545600 bytes for buffer pool (set by --use-memory parameter)
PUNCH HOLE support available
Uses event mutexes
GCC builtin __atomic_thread_fence() is used for memory barrier
Compressed tables use zlib 1.2.11
Number of pools: 1
Using hardware accelerated crc32 and polynomial multiplication.
Directories to scan './'
Scanning './'
Directory '/srv/datadir/.gnupg' will not be scanned because it is a hidden directory.
Completed space ID check of 808 files.
Initializing buffer pool, total size = 25.000000G, instances = 1, chunk size =128.000000M
Completed initialization of buffer pool
page_cleaner coordinator priority: -20
page_cleaner worker priority: -20
page_cleaner worker priority: -20
page_cleaner worker priority: -20
The log sequence number 14904705545163 in the system tablespace does not match the log sequence number 14907979855307 in the ib_logfiles!
Database was not shutdown normally!
Starting crash recovery.
Starting to parse redo log at lsn = 14907979854867, whereas checkpoint_lsn = 14907979855307 and start_lsn = 14907979854848
Doing recovery: scanned up to log sequence number 14907979858719
Log background threads are being started...
Applying a batch of 1 redo log records ...
100%
Apply batch completed!
Using undo tablespace './undo_001'.
Using undo tablespace './undo_002'.
Opened 2 existing undo tablespaces.
GTID recovery trx_no: 5826738769
Parallel initialization of rseg complete
Time taken to initialize rseg using 4 thread: 29487 ms.
Creating shared tablespace for temporary tables
Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
File './ibtmp1' size is now 12 MB.
Scanning temp tablespace dir:'./#innodb_temp/'
Created 128 and tracked 128 new rollback segment(s) in the temporary tablespace. 128 are now active.
8.0.27 started; log sequence number 14907979858729
Allocated tablespace ID 1955 for ym/ym_mb_history_old#p#p53, old maximum was 0
xtrabackup: innodb_init(): Error occured.