Xtrabackup --prepare crashes, please help get a valid backup (solved)

Kevin_Watt · November 2, 2022, 8:59pm

My production server is currently on Server version: 8.0.22-13 Percona Server (GPL), Release ‘13’, Revision ‘6f7822f’. I’d like to get a working backup before I upgrade to the latest percona-server.

In a routine test of my backup system, I’m getting an error when trying to prepare the created backup on a new server for testing.

I’ve upgraded to the latest xtrabackup (xtrabackup version 8.0.29-22 based on MySQL server 8.0.29 Linux (x86_64) (revision id: c31e7ddcce3) on both machines & re-created the backup but am still getting errors.

I’d be open to trying a backup using replication. The database is about 50gb so would rather not have downtime during a full mysqldump & restore that way.

Here’s my prepare log:

xtrabackup --no-defaults --target-dir=/root/db/ --prepare

2022-11-02T13:52:48.726715-07:00 0 [Note] [MY-011825] [Xtrabackup] recognized server arguments: --innodb_checksum_algorithm=crc32 --innodb_log_checksums=1 --innodb_data_file_path=ibdata:500M:autoextend --innodb_log_files_in_group=2 --innodb_log_file_size=50331648 --innodb_page_size=16384 --innodb_undo_directory=./ --innodb_undo_tablespaces=2 --server-id=42 --innodb_log_checksums=ON --innodb_redo_log_encrypt=0 --innodb_undo_log_encrypt=0

2022-11-02T13:52:48.726867-07:00 0 [Note] [MY-011825] [Xtrabackup] recognized client arguments: --target-dir=/root/db/ --prepare=1

xtrabackup version 8.0.29-22 based on MySQL server 8.0.29 Linux (x86_64) (revision id: c31e7ddcce3)

2022-11-02T13:52:48.726892-07:00 0 [Note] [MY-011825] [Xtrabackup] cd to /root/db/

2022-11-02T13:52:48.727140-07:00 0 [Note] [MY-011825] [Xtrabackup] This target seems to be not prepared yet.

2022-11-02T13:52:48.728399-07:00 0 [Note] [MY-013251] [InnoDB] Number of pools: 1

2022-11-02T13:52:48.742793-07:00 0 [Note] [MY-011825] [Xtrabackup] xtrabackup_logfile detected: size=56229888, start_lsn=(4562103519497)

2022-11-02T13:52:48.744817-07:00 0 [Note] [MY-011825] [Xtrabackup] using the following InnoDB configuration for recovery:

2022-11-02T13:52:48.744879-07:00 0 [Note] [MY-011825] [Xtrabackup] innodb_data_home_dir = .

2022-11-02T13:52:48.744889-07:00 0 [Note] [MY-011825] [Xtrabackup] innodb_data_file_path = ibdata:500M:autoextend

2022-11-02T13:52:48.744925-07:00 0 [Note] [MY-011825] [Xtrabackup] innodb_log_group_home_dir = .

2022-11-02T13:52:48.744941-07:00 0 [Note] [MY-011825] [Xtrabackup] innodb_log_files_in_group = 1

2022-11-02T13:52:48.744959-07:00 0 [Note] [MY-011825] [Xtrabackup] innodb_log_file_size = 56229888

2022-11-02T13:52:48.746771-07:00 0 [Note] [MY-011825] [Xtrabackup] inititialize_service_handles suceeded

2022-11-02T13:52:48.747935-07:00 0 [Note] [MY-011825] [Xtrabackup] using the following InnoDB configuration for recovery:

2022-11-02T13:52:48.747988-07:00 0 [Note] [MY-011825] [Xtrabackup] innodb_data_home_dir = .

2022-11-02T13:52:48.747997-07:00 0 [Note] [MY-011825] [Xtrabackup] innodb_data_file_path = ibdata:500M:autoextend

2022-11-02T13:52:48.748011-07:00 0 [Note] [MY-011825] [Xtrabackup] innodb_log_group_home_dir = .

2022-11-02T13:52:48.748018-07:00 0 [Note] [MY-011825] [Xtrabackup] innodb_log_files_in_group = 1

2022-11-02T13:52:48.748029-07:00 0 [Note] [MY-011825] [Xtrabackup] innodb_log_file_size = 56229888

2022-11-02T13:52:48.748038-07:00 0 [Note] [MY-011825] [Xtrabackup] Starting InnoDB instance for recovery.

2022-11-02T13:52:48.748044-07:00 0 [Note] [MY-011825] [Xtrabackup] Using 104857600 bytes for buffer pool (set by --use-memory parameter)

2022-11-02T13:52:48.748073-07:00 0 [Note] [MY-012932] [InnoDB] PUNCH HOLE support available

2022-11-02T13:52:48.748093-07:00 0 [Note] [MY-012944] [InnoDB] Uses event mutexes

2022-11-02T13:52:48.748098-07:00 0 [Note] [MY-012945] [InnoDB] GCC builtin __atomic_thread_fence() is used for memory barrier

2022-11-02T13:52:48.748117-07:00 0 [Note] [MY-012948] [InnoDB] Compressed tables use zlib 1.2.11

2022-11-02T13:52:48.748295-07:00 0 [Note] [MY-013251] [InnoDB] Number of pools: 1

2022-11-02T13:52:48.749109-07:00 0 [Note] [MY-012951] [InnoDB] Using hardware accelerated crc32 and polynomial multiplication.

2022-11-02T13:52:48.749735-07:00 0 [Note] [MY-012203] [InnoDB] Directories to scan './'

2022-11-02T13:52:48.749802-07:00 0 [Note] [MY-012204] [InnoDB] Scanning './'

2022-11-02T13:52:48.799577-07:00 0 [Note] [MY-012208] [InnoDB] Completed space ID check of 132 files.

2022-11-02T13:52:48.800977-07:00 0 [Note] [MY-012955] [InnoDB] Initializing buffer pool, total size = 128.000000M, instances = 1, chunk size =128.000000M

2022-11-02T13:52:48.811817-07:00 0 [Note] [MY-012957] [InnoDB] Completed initialization of buffer pool

2022-11-02T13:52:48.854615-07:00 0 [Note] [MY-011951] [InnoDB] page_cleaner coordinator priority: -20

2022-11-02T13:52:48.854939-07:00 0 [Note] [MY-011954] [InnoDB] page_cleaner worker priority: -20

2022-11-02T13:52:48.855006-07:00 0 [Note] [MY-011954] [InnoDB] page_cleaner worker priority: -20

2022-11-02T13:52:48.858943-07:00 0 [Note] [MY-011954] [InnoDB] page_cleaner worker priority: -20

2022-11-02T13:52:48.940224-07:00 0 [Note] [MY-012529] [InnoDB] Redo log format is v4. The redo log was created before MySQL 8.0.3.

2022-11-02T13:52:48.940492-07:00 0 [Note] [MY-012560] [InnoDB] The log sequence number 12 in the system tablespace does not match the log sequence number 4562103519497 in the ib_logfiles!

2022-11-02T13:52:48.940552-07:00 0 [Note] [MY-012551] [InnoDB] Database was not shutdown normally!

2022-11-02T13:52:48.940596-07:00 0 [Note] [MY-012552] [InnoDB] Starting crash recovery.

2022-11-02T13:52:48.941318-07:00 0 [Note] [MY-013086] [InnoDB] Starting to parse redo log at lsn = 4562103521936, whereas checkpoint_lsn = 4562103519497 and start_lsn = 4562103519232

2022-11-02T13:52:49.022145-07:00 0 [Note] [MY-012550] [InnoDB] Doing recovery: scanned up to log sequence number 4562108762112

2022-11-02T13:52:49.097379-07:00 0 [Note] [MY-012550] [InnoDB] Doing recovery: scanned up to log sequence number 4562114004992

2022-11-02T13:52:49.176228-07:00 0 [Note] [MY-012550] [InnoDB] Doing recovery: scanned up to log sequence number 4562119247872

2022-11-02T13:52:49.256916-07:00 0 [Note] [MY-012550] [InnoDB] Doing recovery: scanned up to log sequence number 4562124490752

2022-11-02T13:52:49.336586-07:00 0 [Note] [MY-012550] [InnoDB] Doing recovery: scanned up to log sequence number 4562129733632

2022-11-02T13:52:49.405506-07:00 0 [Note] [MY-012550] [InnoDB] Doing recovery: scanned up to log sequence number 4562134976512

2022-11-02T13:52:49.468591-07:00 0 [Note] [MY-012550] [InnoDB] Doing recovery: scanned up to log sequence number 4562140219392

2022-11-02T13:52:49.538394-07:00 0 [Note] [MY-012550] [InnoDB] Doing recovery: scanned up to log sequence number 4562145462272

2022-11-02T13:52:49.604370-07:00 0 [Note] [MY-012550] [InnoDB] Doing recovery: scanned up to log sequence number 4562150705152

2022-11-02T13:52:49.640398-07:00 0 [Note] [MY-012550] [InnoDB] Doing recovery: scanned up to log sequence number 4562153449160

2022-11-02T13:52:49.672334-07:00 0 [Note] [MY-013083] [InnoDB] Log background threads are being started...

2022-11-02T13:52:49.675578-07:00 0 [Note] [MY-012532] [InnoDB] Applying a batch of 31805 redo log records ...

2022-11-02T13:52:50.460635-07:00 0 [Note] [MY-012533] [InnoDB] 10%

2022-11-02T13:52:50.826901-07:00 0 [Note] [MY-012533] [InnoDB] 20%

2022-11-02T13:52:51.641616-07:00 0 [Note] [MY-012533] [InnoDB] 30%

2022-11-02T13:52:51.793117-07:00 0 [Note] [MY-012533] [InnoDB] 40%

2022-11-02T13:52:52.079905-07:00 0 [Note] [MY-012533] [InnoDB] 50%

2022-11-02T13:52:52.912349-07:00 0 [Note] [MY-012533] [InnoDB] 60%

2022-11-02T13:52:53.695173-07:00 0 [Note] [MY-012533] [InnoDB] 70%

2022-11-02T13:52:53.983195-07:00 0 [Note] [MY-012533] [InnoDB] 80%

2022-11-02T13:52:54.123063-07:00 0 [Note] [MY-012533] [InnoDB] 90%

2022-11-02T13:52:54.207883-07:00 0 [Note] [MY-012533] [InnoDB] 100%

2022-11-02T13:52:54.719168-07:00 0 [Note] [MY-012535] [InnoDB] Apply batch completed!

2022-11-02T13:52:54.822283-07:00 0 [Note] [MY-013252] [InnoDB] Using undo tablespace './undo_001'.

2022-11-02T13:52:54.822477-07:00 0 [Note] [MY-013252] [InnoDB] Using undo tablespace './undo_002'.

2022-11-02T13:52:54.822915-07:00 0 [Note] [MY-012910] [InnoDB] Opened 2 existing undo tablespaces.

2022-11-02T13:52:54.823081-07:00 0 [Note] [MY-011980] [InnoDB] GTID recovery trx_no: 2214195620

2022-11-02T13:52:54.851211-07:00 0 [Note] [MY-013776] [InnoDB] Parallel initialization of rseg complete

2022-11-02T13:52:54.851295-07:00 0 [Note] [MY-013777] [InnoDB] Time taken to initialize rseg using 4 thread: 28223 ms.

2022-11-02T13:52:54.851579-07:00 0 [Note] [MY-012923] [InnoDB] Creating shared tablespace for temporary tables

2022-11-02T13:52:54.851693-07:00 0 [Note] [MY-012265] [InnoDB] Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...

2022-11-02T13:52:54.881856-07:00 0 [Note] [MY-012266] [InnoDB] File './ibtmp1' size is now 12 MB.

2022-11-02T13:52:54.882830-07:00 0 [Note] [MY-013627] [InnoDB] Scanning temp tablespace dir:'./#innodb_temp/'

2022-11-02T13:52:54.915432-07:00 0 [Note] [MY-013018] [InnoDB] Created 128 and tracked 128 new rollback segment(s) in the temporary tablespace. 128 are now active.

2022-11-02T13:52:54.915776-07:00 0 [Note] [MY-012976] [InnoDB] 8.0.29 started; log sequence number 4562153449519

2022-11-02T13:52:54.915784-07:00 0 [Note] [MY-011953] [InnoDB] Page cleaner took 6064ms to flush 0 and evict 0 pages

2022-11-02T13:52:54.916501-07:00 0 [Warning] [MY-012091] [InnoDB] Allocated tablespace ID 67 for apm/tocs, old maximum was 0

2022-11-02T13:52:55.009425-07:00 0 [ERROR] [MY-011825] [Xtrabackup] innodb_init(): Error occured

Nothing seems strange with the tocs table:

-rw-r--r-- 1 root root 18M Nov 2 13:42 tocs.ibd

If I run the prepare command again, there’s even more errors:

root@temp2:~/db# xtrabackupxtrabackup --no-defaults --target-dir=/root/db/ --prepare

2022-11-02T13:57:38.657154-07:00 0 [Note] [MY-011825] [Xtrabackup] recognized server arguments: --innodb_checksum_algorithm=crc32 --innodb_log_checksums=1 --innodb_data_file_path=ibdata:500M:autoextend --innodb_log_files_in_group=2 --innodb_log_file_size=50331648 --innodb_page_size=16384 --innodb_undo_directory=./ --innodb_undo_tablespaces=2 --server-id=42 --innodb_log_checksums=ON --innodb_redo_log_encrypt=0 --innodb_undo_log_encrypt=0

2022-11-02T13:57:38.657305-07:00 0 [Note] [MY-011825] [Xtrabackup] recognized client arguments: --target-dir=/root/db/ --prepare=1

xtrabackup version 8.0.29-22 based on MySQL server 8.0.29 Linux (x86_64) (revision id: c31e7ddcce3)

2022-11-02T13:57:38.657330-07:00 0 [Note] [MY-011825] [Xtrabackup] cd to /root/db/

2022-11-02T13:57:38.657364-07:00 0 [Note] [MY-011825] [Xtrabackup] This target seems to be not prepared yet.

2022-11-02T13:57:38.657888-07:00 0 [Note] [MY-013251] [InnoDB] Number of pools: 1

2022-11-02T13:57:38.670549-07:00 0 [Note] [MY-011825] [Xtrabackup] xtrabackup_logfile detected: size=63242240, start_lsn=(4562151352008)

2022-11-02T13:57:38.671802-07:00 0 [Note] [MY-011825] [Xtrabackup] using the following InnoDB configuration for recovery:

2022-11-02T13:57:38.671867-07:00 0 [Note] [MY-011825] [Xtrabackup] innodb_data_home_dir = .

2022-11-02T13:57:38.671877-07:00 0 [Note] [MY-011825] [Xtrabackup] innodb_data_file_path = ibdata:500M:autoextend

2022-11-02T13:57:38.671912-07:00 0 [Note] [MY-011825] [Xtrabackup] innodb_log_group_home_dir = .

2022-11-02T13:57:38.671924-07:00 0 [Note] [MY-011825] [Xtrabackup] innodb_log_files_in_group = 1

2022-11-02T13:57:38.671940-07:00 0 [Note] [MY-011825] [Xtrabackup] innodb_log_file_size = 63242240

2022-11-02T13:57:38.672192-07:00 0 [Note] [MY-011825] [Xtrabackup] inititialize_service_handles suceeded

2022-11-02T13:57:38.672425-07:00 0 [Note] [MY-011825] [Xtrabackup] using the following InnoDB configuration for recovery:

2022-11-02T13:57:38.672468-07:00 0 [Note] [MY-011825] [Xtrabackup] innodb_data_home_dir = .

2022-11-02T13:57:38.672485-07:00 0 [Note] [MY-011825] [Xtrabackup] innodb_data_file_path = ibdata:500M:autoextend

2022-11-02T13:57:38.672505-07:00 0 [Note] [MY-011825] [Xtrabackup] innodb_log_group_home_dir = .

2022-11-02T13:57:38.672519-07:00 0 [Note] [MY-011825] [Xtrabackup] innodb_log_files_in_group = 1

2022-11-02T13:57:38.672532-07:00 0 [Note] [MY-011825] [Xtrabackup] innodb_log_file_size = 63242240

2022-11-02T13:57:38.672552-07:00 0 [Note] [MY-011825] [Xtrabackup] Starting InnoDB instance for recovery.

2022-11-02T13:57:38.672567-07:00 0 [Note] [MY-011825] [Xtrabackup] Using 104857600 bytes for buffer pool (set by --use-memory parameter)

2022-11-02T13:57:38.672614-07:00 0 [Note] [MY-012932] [InnoDB] PUNCH HOLE support available

2022-11-02T13:57:38.672658-07:00 0 [Note] [MY-012944] [InnoDB] Uses event mutexes

2022-11-02T13:57:38.672668-07:00 0 [Note] [MY-012945] [InnoDB] GCC builtin __atomic_thread_fence() is used for memory barrier

2022-11-02T13:57:38.672679-07:00 0 [Note] [MY-012948] [InnoDB] Compressed tables use zlib 1.2.11

2022-11-02T13:57:38.672881-07:00 0 [Note] [MY-013251] [InnoDB] Number of pools: 1

2022-11-02T13:57:38.672993-07:00 0 [Note] [MY-012951] [InnoDB] Using hardware accelerated crc32 and polynomial multiplication.

2022-11-02T13:57:38.673424-07:00 0 [Note] [MY-012203] [InnoDB] Directories to scan './'

2022-11-02T13:57:38.673492-07:00 0 [Note] [MY-012204] [InnoDB] Scanning './'

2022-11-02T13:57:38.676929-07:00 0 [Note] [MY-012208] [InnoDB] Completed space ID check of 132 files.

2022-11-02T13:57:38.677672-07:00 0 [Note] [MY-012955] [InnoDB] Initializing buffer pool, total size = 128.000000M, instances = 1, chunk size =128.000000M

2022-11-02T13:57:38.688881-07:00 0 [Note] [MY-012957] [InnoDB] Completed initialization of buffer pool

2022-11-02T13:57:38.692851-07:00 0 [Note] [MY-011951] [InnoDB] page_cleaner coordinator priority: -20

2022-11-02T13:57:38.693089-07:00 0 [Note] [MY-011954] [InnoDB] page_cleaner worker priority: -20

2022-11-02T13:57:38.693180-07:00 0 [Note] [MY-011954] [InnoDB] page_cleaner worker priority: -20

2022-11-02T13:57:38.693286-07:00 0 [Note] [MY-011954] [InnoDB] page_cleaner worker priority: -20

2022-11-02T13:57:38.787518-07:00 0 [Note] [MY-012529] [InnoDB] Redo log format is v4. The redo log was created before MySQL 8.0.3.

2022-11-02T13:57:38.787770-07:00 0 [Note] [MY-012560] [InnoDB] The log sequence number 12 in the system tablespace does not match the log sequence number 4562151352008 in the ib_logfiles!

2022-11-02T13:57:38.787830-07:00 0 [Note] [MY-012551] [InnoDB] Database was not shutdown normally!

2022-11-02T13:57:38.787874-07:00 0 [Note] [MY-012552] [InnoDB] Starting crash recovery.

2022-11-02T13:57:38.791001-07:00 0 [Note] [MY-012550] [InnoDB] Doing recovery: scanned up to log sequence number 4562151351808

2022-11-02T13:57:38.791182-07:00 0 [ERROR] [MY-012562] [InnoDB] We scanned the log up to 4562151351808. A checkpoint was at 4562151352008 and the maximum LSN on a database page was 0. It is possible that the database is now corrupt!

2022-11-02T13:57:38.791252-07:00 0 [Warning] [MY-013412] [InnoDB] The last block of redo had corrupted first_rec_group and became fixed (0 -> 200).

2022-11-02T13:57:38.807244-07:00 0 [Note] [MY-013083] [InnoDB] Log background threads are being started...

2022-11-02T13:57:38.819570-07:00 0 [Note] [MY-012532] [InnoDB] Applying a batch of 0 redo log records ...

2022-11-02T13:57:38.820115-07:00 0 [Note] [MY-012535] [InnoDB] Apply batch completed!

2022-11-02T13:57:38.920567-07:00 0 [ERROR] [MY-011971] [InnoDB] Tablespace 'innodb_system' Page [page id: space=0, page number=5] log sequence number 4562153449160 is in the future! Current system log sequence number 4562151352008.

2022-11-02T13:57:38.920761-07:00 0 [ERROR] [MY-011972] [InnoDB] Your database may be corrupt or you may have copied the InnoDB tablespace but not the InnoDB log files. Please refer to link for information about forcing recovery.

2022-11-02T13:57:38.920928-07:00 0 [Note] [MY-013252] [InnoDB] Using undo tablespace './undo_001'.

2022-11-02T13:57:38.921715-07:00 0 [Note] [MY-013252] [InnoDB] Using undo tablespace './undo_002'.

2022-11-02T13:57:38.922336-07:00 0 [Note] [MY-012910] [InnoDB] Opened 2 existing undo tablespaces.

2022-11-02T13:57:38.922460-07:00 0 [Note] [MY-011980] [InnoDB] GTID recovery trx_no: 2214195620

2022-11-02T13:57:38.923189-07:00 0 [ERROR] [MY-011971] [InnoDB] Tablespace 'innodb_undo_002' Page [page id: space=4294966643, page number=132] log sequence number 4562153429560 is in the future! Current system log sequence number 4562151352008.

2022-11-02T13:57:38.923237-07:00 0 [ERROR] [MY-011972] [InnoDB] Your database may be corrupt or you may have copied the InnoDB tablespace but not the InnoDB log files. Please refer to link for information about forcing recovery.

… a lot of these …

2022-11-02T13:57:38.990157-07:00 0 [ERROR] [MY-011971] [InnoDB] Tablespace 'innodb_undo_001' Page [page id: space=4294965755, page number=426] log sequence number 4562153412735 is in the future! Current system log sequence number 4562151352008.

2022-11-02T13:57:38.990179-07:00 0 [ERROR] [MY-011972] [InnoDB] Your database may be corrupt or you may have copied the InnoDB tablespace but not the InnoDB log files. Please refer to link for information about forcing recovery.

2022-11-02T13:57:38.990867-07:00 0 [Note] [MY-013776] [InnoDB] Parallel initialization of rseg complete

2022-11-02T13:57:38.990918-07:00 0 [Note] [MY-013777] [InnoDB] Time taken to initialize rseg using 4 thread: 68468 ms.

2022-11-02T13:57:38.993221-07:00 0 [Note] [MY-012255] [InnoDB] Removed temporary tablespace data file: "ibtmp1"

2022-11-02T13:57:38.993285-07:00 0 [Note] [MY-012923] [InnoDB] Creating shared tablespace for temporary tables

2022-11-02T13:57:38.993353-07:00 0 [Note] [MY-012265] [InnoDB] Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...

2022-11-02T13:57:39.023640-07:00 0 [Note] [MY-012266] [InnoDB] File './ibtmp1' size is now 12 MB.

2022-11-02T13:57:39.023873-07:00 0 [Note] [MY-013627] [InnoDB] Scanning temp tablespace dir:'./#innodb_temp/'

2022-11-02T13:57:39.065087-07:00 0 [Note] [MY-013018] [InnoDB] Created 128 and tracked 128 new rollback segment(s) in the temporary tablespace. 128 are now active.

2022-11-02T13:57:39.065727-07:00 0 [Note] [MY-012976] [InnoDB] 8.0.29 started; log sequence number 4562151352018

2022-11-02T13:57:39.068544-07:00 0 [Warning] [MY-012091] [InnoDB] Allocated tablespace ID 67 for apm/tocs, old maximum was 0

2022-11-02T13:57:39.146863-07:00 0 [ERROR] [MY-011971] [InnoDB] Tablespace 'apm/view_refs' Page [page id: space=64, page number=1] log sequence number 4562153375314 is in the future! Current system log sequence number 4562151352018.

2022-11-02T13:57:39.146932-07:00 0 [ERROR] [MY-011972] [InnoDB] Your database may be corrupt or you may have copied the InnoDB tablespace but not the InnoDB log files. Please refer to link for information about forcing recovery.

2022-11-02T13:57:39.159259-07:00 0 [ERROR] [MY-011971] [InnoDB] Tablespace 'apm/group_users' Page [page id: space=140, page number=1] log sequence number 4562152236520 is in the future! Current system log sequence number 4562151352018.

2022-11-02T13:57:39.159319-07:00 0 [ERROR] [MY-011972] [InnoDB] Your database may be corrupt or you may have copied the InnoDB tablespace but not the InnoDB log files. Please refer to link for information about forcing recovery.

2022-11-02T13:57:39.164645-07:00 0 [ERROR] [MY-011825] [Xtrabackup] innodb_init(): Error occurred

matthewb · November 2, 2022, 9:22pm

That’s because you ran --prepare twice. Don’t do that. You ran it once and it completed

8.0.29 started; log sequence number 4562153449519

For some unknown reason, InnoDB says it failed to initialize. No other errors? Nothing in dmesg or syslog around that same time?

That’s why people don’t use mysqldump anymore Use mydumper instead and cut the time down drastically.

satya.bodapati · November 2, 2022, 10:51pm

Hi @Kevin_Watt Can you please share your backup-my.cnf?

It seems in the first attempt, after applying all the redo successfully, xtrabackup is about to create empty redo logs. For this, it does an init of innodb engine again. Unfortunately, your prepare crashed at this moment.

Do you have a copy of this backup directory? I assume starting fresh from a new copy of the backup would result in the same error? innodb_init() failed?

xtrabackup at the end creates a checkpoints file and a backup info file. Unfortunately, your first prepare didn’t reach this state.

Your second attempt of --prepare is invalid because of this reason.

Kevin_Watt · November 3, 2022, 1:37am

@matthewb The first prepare didn’t complete actually though…

@satya.bodapati Thanks for takin ga look! Here’s the backup-my.cnf

# This MySQL options file was generated by innobackupex.

# The MySQL server
[mysqld]
innodb_checksum_algorithm=crc32
innodb_log_checksums=1
innodb_data_file_path=ibdata:500M:autoextend
innodb_log_files_in_group=2
innodb_log_file_size=50331648
innodb_page_size=16384
innodb_undo_directory=./
innodb_undo_tablespaces=2
server_id=42
innodb_log_checksums=ON
innodb_redo_log_encrypt=OFF
innodb_undo_log_encrypt=OFF
server_uuid=9c77fcfe-edited-out
master_key_id=0

matthewb · November 3, 2022, 4:17am

@Kevin_Watt,
The first prepare did finish, just not completely. It even says so in the logs, which I quoted in my previous post. And then the output of your 2nd attempt also confirms this: ...is in the future! Those messages mean the LSN was rolled forward (ie: prepared) and when you tried to do it again, it said “hang on, this LSN is too new!”. So, for some reason, your prepare is only completing partially, as @satya.bodapati said about the redo logs.

satya.bodapati · November 3, 2022, 12:47pm

Right, the prepare finished applying redo logs. Maybe it is caused by your innodb_undo_directory=./ can u please remove this and check?

I assume have copy of backup?

Marcelo_Altmann · November 3, 2022, 1:16pm

@Kevin_Watt one thing that caught my attention:

You mentioned you have server and xtrabackup both on 8.0.29, however, your xtrabackup log indicates that you are trying to prepare a backup that was created on a version prior to 8.0.29.

2022-11-02T13:52:48.811817-07:00 0 [Note] [MY-012957] [InnoDB] Completed initialization of buffer pool

2022-11-02T13:52:48.854615-07:00 0 [Note] [MY-011951] [InnoDB] page_cleaner coordinator priority: -20

2022-11-02T13:52:48.854939-07:00 0 [Note] [MY-011954] [InnoDB] page_cleaner worker priority: -20

2022-11-02T13:52:48.855006-07:00 0 [Note] [MY-011954] [InnoDB] page_cleaner worker priority: -20

2022-11-02T13:52:48.858943-07:00 0 [Note] [MY-011954] [InnoDB] page_cleaner worker priority: -20

2022-11-02T13:52:48.940224-07:00 0 [Note] [MY-012529] [InnoDB] Redo log format is v4. The redo log was created before MySQL 8.0.3.
^^ This message ^^


2022-11-02T13:52:48.940492-07:00 0 [Note] [MY-012560] [InnoDB] The log sequence number 12 in the system tablespace does not match the log sequence number 4562103519497 in the ib_logfiles!

2022-11-02T13:52:48.940552-07:00 0 [Note] [MY-012551] [InnoDB] Database was not shutdown normally!

2022-11-02T13:52:48.940596-07:00 0 [Note] [MY-012552] [InnoDB] Starting crash recovery.

MySQL version 8.0.28 and prior has redo log version 4
MySQL version 8.0.29 has redo log version 5.
So the above message means you are using xtrabackup 8.0.29 but the --backup was taken on a server of version 8.0.28 or prior.

Kevin_Watt · November 3, 2022, 8:38pm

Downgrading back to Percona-XtraBackup-8.0.22-15 to match the percona-server version on both machines solved the crash I was seeing and now everything is working well.

Thanks for the help, I really appreciate it!

Kevin

Topic		Replies	Views
Prepare: innodb_init(): Error occured Percona XtraBackup	1	950	December 27, 2021
xtrabackup 8.0.5 mysql 8.0.15 prepare failes with xtrabackup: Unknown error 3611 Percona XtraBackup	2	1144	May 1, 2019
Xtrabackup --prepare crash with federate database Percona XtraBackup	11	1045	May 21, 2021
xtrabackup errors Percona XtraBackup	4	2944	February 13, 2024
xtrabackup 8 stuck on prepare Percona XtraBackup	9	1400	May 13, 2019

Xtrabackup --prepare crashes, please help get a valid backup (solved)

Related topics