Xtrabackup 8.0.30 issue. [ERROR] [MY-011825] [Xtrabackup] read_logfile() failed

Hello folks.

After upgrade from MySQL 8.0.26 to 8.0.30 and xtrabackup to the corresponding version for xtrabackup is 8.0.30-23 I faced that I can’t take a backup from few clusters.

I have 9 clusters from 10Gb up to 7Tb. Clusters up to 1Tb size with not intensive traffic works ok, but bigger doesn’t work at all.

Here is the log file of the latest failed backup.

2023-04-04T00:00:01.927212-00:00 0 [Note] [MY-011825] [Xtrabackup] recognized server arguments: --datadir=/mysql --tmpdir=/mysqltmp --innodb_flush_log_at_trx_commit=2 --innodb_file_per_table=1 --inn
odb_read_io_threads=16 --innodb_write_io_threads=16 --innodb_flush_method=O_DIRECT --log_bin=/mysql/mysql-bin --innodb_buffer_pool_size=175G --innodb_io_capacity=6000 --innodb_log_file_size=1G --server-i
2023-04-04T00:00:01.927479-00:00 0 [Note] [MY-011825] [Xtrabackup] recognized client arguments: --port=3306 --socket=/var/run/mysqld/mysqld.sock --compress --compress-threads=4 --parallel=4 --use-memory=100G
--user=backup_user_name --password=* --backup=1 --slave-info=1 --stream=xbstream --target-dir=/backup
xtrabackup version 8.0.31-24 based on MySQL server 8.0.31 Linux (x86_64) (revision id: f0754edb)
230404 00:00:02  version_check Connecting to MySQL server with DSN 'dbi:mysql:;mysql_read_default_group=xtrabackup;port=3306;mysql_socket=/var/run/mysqld/mysqld.sock' as 'backup_user_name'  (using password: YES).
230404 00:00:02  version_check Connected to MySQL server
230404 00:00:02  version_check Executing a version check against the server...

# A software update is available:
230404 00:00:02  version_check Done.
2023-04-04T00:00:02.268295-00:00 0 [Note] [MY-011825] [Xtrabackup] Connecting to MySQL server host: localhost, user: backup_user_name, password: set, port: 3306, socket: /var/run/mysqld/mysqld.sock
2023-04-04T00:00:02.273686-00:00 0 [Note] [MY-011825] [Xtrabackup] Using server version 8.0.30-22
2023-04-04T00:00:02.304498-00:00 0 [Note] [MY-011825] [Xtrabackup] Executing LOCK TABLES FOR BACKUP ...
2023-04-04T00:00:02.311769-00:00 0 [Note] [MY-011825] [Xtrabackup] uses posix_fadvise().
2023-04-04T00:00:02.311816-00:00 0 [Note] [MY-011825] [Xtrabackup] cd to /mysql
2023-04-04T00:00:02.311837-00:00 0 [Note] [MY-011825] [Xtrabackup] open files limit requested 0, set to 1024
2023-04-04T00:00:02.311886-00:00 0 [Note] [MY-011825] [Xtrabackup] using the following InnoDB configuration:
2023-04-04T00:00:02.311902-00:00 0 [Note] [MY-011825] [Xtrabackup] innodb_data_home_dir = .
2023-04-04T00:00:02.311934-00:00 0 [Note] [MY-011825] [Xtrabackup] innodb_data_file_path = ibdata1:12M:autoextend
2023-04-04T00:00:02.311963-00:00 0 [Note] [MY-011825] [Xtrabackup] innodb_log_group_home_dir = ./
2023-04-04T00:00:02.311997-00:00 0 [Note] [MY-011825] [Xtrabackup] innodb_log_files_in_group = 2
2023-04-04T00:00:02.312005-00:00 0 [Note] [MY-011825] [Xtrabackup] innodb_log_file_size = 1073741824
2023-04-04T00:00:02.312020-00:00 0 [Note] [MY-011825] [Xtrabackup] using O_DIRECT
2023-04-04T00:00:02.317443-00:00 0 [Note] [MY-011825] [Xtrabackup] inititialize_service_handles suceeded
2023-04-04T00:00:03.205895-00:00 0 [Note] [MY-011825] [Xtrabackup] Connecting to MySQL server host: localhost, user: backup_user_name, password: set, port: 3306, socket: /var/run/mysqld/mysqld.sock
2023-04-04T00:00:03.211120-00:00 0 [Note] [MY-011825] [Xtrabackup] Redo Log Archiving is not set up.
2023-04-04T00:00:03.306214-00:00 0 [Warning] [MY-011825] [Xtrabackup] --compress using quicklz is deprecated and the ability to take backups using this compression algorithm will be removed in a future releas
e. Please use ZSTD or LZ4 instead.
2023-04-04T00:00:03.363782-00:00 0 [Note] [MY-011825] [Xtrabackup] Starting to parse redo log at lsn = 142932686118568
2023-04-04T00:00:03.365821-00:00 0 [Note] [MY-012564] [InnoDB] Recovery parsing buffer extended to 4194304.
2023-04-04T00:00:03.367853-00:00 0 [Note] [MY-012564] [InnoDB] Recovery parsing buffer extended to 8388608.
2023-04-04T00:03:26.090575-00:00 0 [Note] [MY-011825] [Xtrabackup] Generating a list of tablespaces
2023-04-04T00:03:26.092577-00:00 0 [Note] [MY-011825] [Xtrabackup] Generating a list of tablespaces
2023-04-04T00:03:26.092606-00:00 0 [Note] [MY-012204] [InnoDB] Scanning './'
2023-04-04T00:03:26.100115-00:00 0 [Note] [MY-012208] [InnoDB] Completed space ID check of 2 files.
2023-04-04T00:03:26.102992-00:00 0 [Warning] [MY-012091] [InnoDB] Allocated tablespace ID 1151307 for mtmtool_db/deleted_mh, old maximum was 0
2023-04-04T00:03:26.585705-00:00 0 [Note] [MY-013252] [InnoDB] Using undo tablespace './undo_001'.
2023-04-04T00:03:26.590459-00:00 0 [Note] [MY-013252] [InnoDB] Using undo tablespace './undo_002'.
2023-04-04T00:03:26.595639-00:00 0 [Note] [MY-012910] [InnoDB] Opened 2 existing undo tablespaces.
2023-04-04T00:03:26.595696-00:00 0 [Note] [MY-011825] [Xtrabackup] Starting 4 threads for parallel data files transfer
2023-04-04T00:03:26.596230-00:00 2 [Note] [MY-011825] [Xtrabackup] Compressing and streaming
2023-04-04T00:08:12.112657-00:00 1 [ERROR] [MY-012894] [InnoDB] Unable to open './#innodb_redo/#ib_redo51692' (error: 1504).
2023-04-04T00:08:12.115437-00:00 1 [ERROR] [MY-011825] [Xtrabackup] read_logfile() failed.
2023-04-04T00:08:13.056143-00:00 0 [ERROR] [MY-011825] [Xtrabackup] log copying failed.

As I understand the problem is connected to a small redo_log size - it was 1Gb before the upgrade and regarding PMM it’s not enough:

So I tried to play on another server with redo_log_capacity. I changed it to 2-3-5-10-50-100Gb (the last 2 it was desperate :grin:), but what changed is the time of failure with the same error. Also, I tried to add this preference, but it led to MySQL crush.

The next try was to upgrade MySQL and xtrabackup to the latest version 8.0.32. But it wasn’t helpful.

I am sure I missing sth urgent but small. Could you please help me to investigate what is going on and what I am missing? Thanks in advance.

P.S. There was one successful backup on the weekend when the traffic was super low.

Hi @Stateros I believe you are facing [PXB-2979] Xtrabackup with 8.0.30 processes redo log files too slowly - Percona JIRA .

Can you please clarify which exact 8.0.32 version you tried?
We have 8.0.32-25 that has this bug present. Today we released 8.0.32-26 which has a fix for this. If you can please ensure you are using xtrabackup 8.0.32-26 and try again.

Another option to avoid the server removing redo logs that have not been consumed is to instruct xtrabackup to register itself as a redo log consumer, this way, the server will block new writes if its redo log is full and xtrabackup has not copied them. To enable it, start xtrabackup with --register-redo-log-consumer parameter;

1 Like

thanks for the quick response. I used 8.0.32-25 xtrabackup, so I will try to upgrade and try again. I will share the result.

Using --register-redo-log-consumer didn’t help as I mentioned before - it just led to crash MySQL at some point during the backup process

upgrading XtraBackup to 8.0.32-26 helped. Backup was successful. Thank you very much.

1 Like