Xtrabackup backup error

pangbin · February 3, 2023, 7:45am

error log :
230202 09:30:23 Executing FLUSH NO_WRITE_TO_BINLOG BINARY LOGS
xtrabackup: Unknown error 1158
Error: failed to execute query ‘FLUSH NO_WRITE_TO_BINLOG BINARY LOGS’: 2013 (HY000) Lost connection to MySQL server during query

mysql8.0 variables：
wait_timeout=30
interactive_timeout=28800

mysql has not been restarted,backup for more than 8 hours;I wonder if the mysql connection is over interactive_timeout.

pangbin · February 3, 2023, 8:10am

repl:

Marcelo_Altmann · February 6, 2023, 7:19pm

Hi @pangbin

xtrabackup is not an interactive session, so its connection should be closed after wait_timeout. However, xtrabackup sets wait timeout to its maximum value of 2147483.

Do you have any other process that look for long running idle connections and kills it, like pt-kill ?

Shmuel_Fogel · November 21, 2023, 10:29am

Hello Marcelo,
I am facing exactly the same error, after the files are backed up, we have about 1.2 million tables copied, I get the above error from MySQL 8.0.33
and xtrabackup image: percona/percona-xtrabackup:latest
When I look inside the container I see even after the error is triggered, and the backup exec command is terminated, inside the mysql, the lock remains and I see this query statement continue being processed, A select from table spaces that list the tables …
The variables timeouts are default, and we do not pass 8 hours of interactive.
What should I do? please help?

anil.joshi · November 22, 2023, 8:50am

@Shmuel_Fogel

Are you using the PXB inside the docker container ? Can you please confirm the exact version ?

xtrabackup --version

Ideally if the backup process completed it should be close in few intervals and shouldn’t be affected by interactive_timeout. Might be you hit with some bug thingy but not sure at the moment.

xtrabackup --user sbtest_user --password xxx --backup --target-dir=/home/vagrant/backups/

2023-11-22T07:54:41.793451-00:00 0 [Note] [MY-011825] [Xtrabackup] Transaction log of lsn (24404660652) to (24404660682) was copied.
2023-11-22T07:54:42.105068-00:00 0 [Note] [MY-011825] [Xtrabackup] completed OK!

| 246611 | sbtest_user | localhost | NULL | Sleep | 18 | | NULL | 17478 | 178 | 1092 |

mysql> show processlist;
+--------+-----------------+-----------------+------+---------+---------+------------------------+------------------+------------+-----------+---------------+
| Id     | User            | Host            | db   | Command | Time    | State                  | Info             | Time_ms    | Rows_sent | Rows_examined |
+--------+-----------------+-----------------+------+---------+---------+------------------------+------------------+------------+-----------+---------------+
|      5 | event_scheduler | localhost       | NULL | Daemon  | 2323801 | Waiting on empty queue | NULL             | 2323801305 |         0 |             0 |
| 208290 | pmm             | localhost:40758 | NULL | Sleep   |       0 |                        | NULL             |        364 |        44 |            50 |
| 246581 | root            | localhost       | NULL | Query   |       0 | init                   | show processlist |          0 |         0 |             0 |
| 246613 | pmm             | localhost:58266 | NULL | Sleep   |       1 |                        | NULL             |        596 |       543 |           543 |
| 246614 | pmm             | localhost:58290 | NULL | Sleep   |       1 |                        | NULL             |        590 |         0 |             0 |
| 246615 | pmm             | localhost:58302 | NULL | Sleep   |       1 |                        | NULL             |        594 |        75 |           316 |
+--------+-----------------+-----------------+------+---------+---------+------------------------+------------------+------------+-----------+---------------+

mysql> select @@global.interactive_timeout;
+------------------------------+
| @@global.interactive_timeout |
+------------------------------+
|                        28800 |
+------------------------------+
1 row in set (0.00 sec)

mysql> SELECT @@global.wait_timeout;
+-----------------------+
| @@global.wait_timeout |
+-----------------------+
|                    30 |
+-----------------------+
1 row in set (0.00 sec)

Is that you doing backups on the PXC instance or a normal setup ? Is that reproducible or you just faced a one time issue ?

Can you please share the complete backup log file along with the database/mysql error logs as well for a review ?

Do you have the output of SHOW ENGINE INNODB STATUS\G resembling the issue duration ?

Lastly, please share the backup command also to have a quick look over there.

Shmuel_Fogel · November 22, 2023, 7:01pm

Hi @anil.joshi ,
We are using PXB in docker container , xtrabackup version 8.0.33-28 based on MySQL server 8.0.33 Linux (x86_64) (revision id: b3a3c3dd) .

We are running this command:
xtrabackup --user=user --password=password --host=host --port=3306 --backup --strict --slave-info --safe-slave-backup --safe-slave-backup-timeout=300 --check-privileges=1 --ftwrl-wait-timeout=100 --ftwrl-wait-query-type=all --kill-long-queries-timeout=50 --target-dir=/backups/up1 --parallel=8 --lock-ddl --no-lock 2>/backup.log

select @@global.interactive_timeout;
31536000

SELECT @@global.wait_timeout;
28800

We are running the command on Replica.
The amount of table we get when PXB runs "
SELECT T2.PATH, T2.NAME, T1.SPACE_TYPE FROM INFORMATION_SCHEMA.INNODB_TABLESPACES T1 JOIN INFORMATION_SCHEMA.INNODB_TABLESPACES_BRIEF T2 USING (SPACE) WHERE T1.SPACE_TYPE = ‘Single’ && T1.ROW_FORMAT != 'Undo’UNION SELECT T2.PATH, SUBSTRING_INDEX(SUBSTRING_INDEX(T2.PATH, ‘/’, -1), ‘.’, 1) NAME, T1.SPACE_TYPE FROM INFORMATION_SCHEMA .INNODB_TABLESPACES T1 JOIN INFORMATION_SCHEMA .INNODB_TABLESPACES_BRIEF T2 USING (SPACE) WHERE T1.SPACE_TYPE = ‘General’ && T1.ROW_FORMAT != ‘Undo’
"

is over 1.2 million rows
show variables like ‘%open_files_limit%’; == 1,048,576

2023-11-22T18:19:49.371305-00:00 0 [Note] [MY-011825] [Xtrabackup] recognized client arguments: --user=user --password=* --host=host --port=3306 --backup=1 --strict=1 --slave-info=1 --safe-slave-backup=1 --safe-slave-backup-timeout=300 --check-privileges=1 --target-dir=/backups/back1 --parallel=8 --lock-ddl=1
xtrabackup version 8.0.33-28 based on MySQL server 8.0.33 Linux (x86_64) (revision id: b3a3c3dd)
2023-11-22T18:19:49.375085-00:00 0 [Note] [MY-011825] [Xtrabackup] perl binary not found. Skipping the version check
2023-11-22T18:19:49.375149-00:00 0 [Note] [MY-011825] [Xtrabackup] Connecting to MySQL server host: host, user: user, password: set, port: 3306, socket: not set
2023-11-22T18:19:49.389427-00:00 0 [Note] [MY-011825] [Xtrabackup] Using server version 8.0.33
2023-11-22T18:19:52.094618-00:00 0 [Note] [MY-011825] [Xtrabackup] Slave open temp tables: 0
2023-11-22T18:19:52.098375-00:00 0 [Note] [MY-011825] [Xtrabackup] Slave is safe to backup.
2023-11-22T18:19:52.098628-00:00 0 [Note] [MY-011825] [Xtrabackup] Executing LOCK INSTANCE FOR BACKUP …
2023-11-22T18:19:52.101945-00:00 0 [Note] [MY-011825] [Xtrabackup] uses posix_fadvise().
2023-11-22T18:19:52.101994-00:00 0 [Note] [MY-011825] [Xtrabackup] cd to /var/lib/mysql/
2023-11-22T18:19:52.102011-00:00 0 [Note] [MY-011825] [Xtrabackup] open files limit requested 0, set to 1048576
2023-11-22T18:20:07.147226-00:00 0 [Note] [MY-011825] [Xtrabackup] using the following InnoDB configuration:
2023-11-22T18:20:07.147314-00:00 0 [Note] [MY-011825] [Xtrabackup] innodb_data_home_dir = .
2023-11-22T18:20:07.147326-00:00 0 [Note] [MY-011825] [Xtrabackup] innodb_data_file_path = ibdata1:12M:autoextend
2023-11-22T18:20:07.148161-00:00 0 [Note] [MY-011825] [Xtrabackup] innodb_log_group_home_dir = ./
2023-11-22T18:20:07.148227-00:00 0 [Note] [MY-011825] [Xtrabackup] innodb_log_files_in_group = 2
2023-11-22T18:20:07.148255-00:00 0 [Note] [MY-011825] [Xtrabackup] innodb_log_file_size = 50331648
2023-11-22T18:20:07.152628-00:00 0 [Note] [MY-011825] [Xtrabackup] inititialize_service_handles suceeded
2023-11-22T18:20:09.566487-00:00 0 [Note] [MY-011825] [Xtrabackup] Connecting to MySQL server host: host, user: user, password: set, port: 3306, socket: not set
2023-11-22T18:20:09.572851-00:00 0 [Note] [MY-011825] [Xtrabackup] Redo Log Archiving is not set up.
2023-11-22T18:20:09.669006-00:00 1 [Note] [MY-011825] [Xtrabackup] >> log scanned up to (46995286792)
2023-11-22T18:20:10.669296-00:00 1 [Note] [MY-011825] [Xtrabackup] >> log scanned up to (46995286792)
2023-11-22T18:20:11.669657-00:00 1 [Note] [MY-011825] [Xtrabackup] >> log scanned up to (46995286792)
2023-11-22T18:20:12.670072-00:00 1 [Note] [MY-011825] [Xtrabackup] >> log scanned up to (46995286792)
2023-11-22T18:20:13.670504-00:00 1 [Note] [MY-011825] [Xtrabackup] >> log scanned up to (46995286792)
2023-11-22T18:20:14.670922-00:00 1 [Note] [MY-011825] [Xtrabackup] >> log scanned up to (46995286792)
2023-11-22T18:20:15.671272-00:00 1 [Note] [MY-011825] [Xtrabackup] >> log scanned up to (46995286792)
2023-11-22T18:20:16.671629-00:00 1 [Note] [MY-011825] [Xtrabackup] >> log scanned up to (46995286792)
2023-11-22T18:20:17.671966-00:00 1 [Note] [MY-011825] [Xtrabackup] >> log scanned up to (46995286792)
2023-11-22T18:20:18.672304-00:00 1 [Note] [MY-011825] [Xtrabackup] >> log scanned up to (46995286792)

…

tail -n 10 backup.log
2023-11-22T18:50:33.208651-00:00 14 [Note] [MY-011825] [Xtrabackup] Copying mysql/general_log_213.sdi to /backups/db_fra1_self_hosted_0_2/v1/christy2/mysql/general_log_213.sdi
2023-11-22T18:50:33.208678-00:00 10 [Note] [MY-011825] [Xtrabackup] Copying mysql/general_log.CSV to /backups/db_fra1_self_hosted_0_2/v1/christy2/mysql/general_log.CSV
2023-11-22T18:50:33.208726-00:00 10 [Note] [MY-011825] [Xtrabackup] Done: Copying mysql/general_log.CSV to /backups/db_fra1_self_hosted_0_2/v1/christy2/mysql/general_log.CSV
2023-11-22T18:50:33.209795-00:00 15 [Note] [MY-011825] [Xtrabackup] Done: Copying mysql/general_log.CSM to /backups/db_fra1_self_hosted_0_2/v1/christy2/mysql/general_log.CSM
2023-11-22T18:50:33.209803-00:00 14 [Note] [MY-011825] [Xtrabackup] Done: Copying mysql/general_log_213.sdi to /backups/db_fra1_self_hosted_0_2/v1/christy2/mysql/general_log_213.sdi
2023-11-22T18:50:33.209805-00:00 16 [Note] [MY-011825] [Xtrabackup] Done: Copying mysql/slow_log_214.sdi to /backups/db_fra1_self_hosted_0_2/v1/christy2/mysql/slow_log_214.sdi
2023-11-22T18:50:33.247351-00:00 0 [Note] [MY-011825] [Xtrabackup] Finished backing up non-InnoDB tables and files
2023-11-22T18:50:33.247490-00:00 0 [Note] [MY-011825] [Xtrabackup] Executing FLUSH NO_WRITE_TO_BINLOG BINARY LOGS
xtrabackup: Unknown error 1158
2023-11-22T18:50:33.250430-00:00 0 [ERROR] [MY-011825] [Xtrabackup] failed to execute query ‘FLUSH NO_WRITE_TO_BINLOG BINARY LOGS’ : 2013 (HY000) Lost connection to MySQL server during query

Christy_Jacob · November 25, 2023, 8:41pm

Hi, we would really appreciate if we can get some insights / help on this issue. We’ve spent a lot of time searching online and trying various xtrabackup --options but none of them have helped so far.

We’ve also increased the system ulimit ( open files ) to well over 2M but that did not give us any fruitful results either.

anil.joshi · November 27, 2023, 10:38am

@Christy_Jacob

Thanks for the details. While checking it further we noticed some close matching bug reports:- [PXB-2639] xtrabackup and wait_timeout - Percona JIRA & [PS-6916] MySQL 8.0.16-7 crash on centos 7 - Percona JIRA however the behaviour not reproduced.

The PXB can have max wait timeout(24 days) while doing backups.

xb_mysql_query(connection, "SET SESSION wait_timeout=2147483", false, true);

It appears to be happening with long running backups more specifically exceeding wait_timeout. How frequently you are getting that error ? Is there any particular time period when you observe the error ?

By any chance, did you observe anything in the mysql error logs if any crash or something happens. Can you pls share the same for a review ?

Did you also check if anything like pt-kill or any such cron scheduled which could kill the long running process on database ?

Are you doing the backups locally or using some NFS/ Streaming etc ? Did you see anything suspicious in the kernel/os logs ?

Shmuel_Fogel · November 27, 2023, 4:12pm

Thank you for your reply!
We have increased wait_timeout to max allowed by MySQL , this had no affect.
We are getting this error on EVERY iteration we run a backup.
We see nothing special in MySQL error logs.

Shmuel_Fogel · November 27, 2023, 4:36pm

We’re doing backups locally. We have MySQL and Xtrabackup running on docker containers on the same host. They are on the same network and share a volume that contains the /var/lib/mysql folder

Topic		Replies	Views
Xtrabackup not getting completed due lock_wait_timeout issue Percona XtraBackup	4	1668	August 13, 2021
Strange error (At least for me). Percona XtraBackup	2	823	January 13, 2021
Xtrabackup Error - SET SESSION lock_wait_timeout=31536000: MySQL server has gone away Percona XtraBackup	1	2443	March 30, 2017
Error: Connection to mysql child process (pid=123) timedout Percona XtraBackup	1	953	August 21, 2012
[Xtrabackup] failed to execute query 'FLUSH NO_WRITE_TO_BINLOG BINARY LOGS' : 2013 (HY000) Lost connection to MySQL server during query Percona XtraBackup	1	69	July 4, 2024

Xtrabackup backup error

Related topics