Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

broken test: xtrabackup TestRecovery #8315

Closed
vmg opened this issue Jun 11, 2021 · 1 comment
Closed

broken test: xtrabackup TestRecovery #8315

vmg opened this issue Jun 11, 2021 · 1 comment
Labels
Component: Build/CI Type: CI/Build Type: Testing

Comments

@vmg
Copy link
Collaborator

vmg commented Jun 11, 2021

This test seems to have regressed and reliably fails on main.

Branch: main
MySQL version: mysql-5.7.34-linux-glibc2.12-x86_64
Xtrabackup version: percona-xtrabackup-2.4.22-Linux-x86_64.glibc2.12

Logs:

> go test -v .
E0611 17:10:10.666117  354584 topo_process.go:92] Starting etcd with command: etcd --name global --data-dir /home/vmg/src/vitess/vtdataroot/vtroot_41001/topo_41002 --listen-client-urls http://localhost:41002 --advertise-client-urls http://localhost:41002 --initial-advertise-peer-urls http://localhost:41004 --listen-peer-urls http://localhost:41004 --initial-cluster global=http://localhost:41004 --enable-v2=true
=== RUN   TestRecovery
E0611 17:10:32.971006  354584 vtctlclient_process.go:158] Output:
E0611 17:10:32.967821  357716 main.go:67] E0611 15:10:32.967632 backup.go:163] E0611 15:10:32.967551 backup.go:123] backup is not usable, aborting it: [exit status 1
xtrabackup failed with error. Output=xtrabackup: recognized server arguments: --datadir=/home/vmg/src/vitess/vtdataroot/vtroot_41001/vt_0000009287/data --innodb_data_home_dir=/home/vmg/src/vitess/vtdataroot/vtroot_41001/vt_0000009287/innodb/data --innodb_log_group_home_dir=/home/vmg/src/vitess/vtdataroot/vtroot_41001/vt_0000009287/innodb/logs --log_bin=/home/vmg/src/vitess/vtdataroot/vtroot_41001/vt_0000009287/bin-logs/vt-0000009287-bin --server-id=1833938403 --tmpdir=/home/vmg/src/vitess/vtdataroot/vtroot_41001/vt_0000009287/tmp 
xtrabackup: recognized client arguments: --backup=1 --socket=/home/vmg/src/vitess/vtdataroot/vtroot_41001/vt_0000009287/mysql.sock --slave-info=1 --user=vt_dba --target-dir=/home/vmg/src/vitess/vtdataroot/vtroot_41001/vt_0000009287/tmp --stream=xbstream --password=* 
210611 17:10:31  version_check Connecting to MySQL server with DSN 'dbi:mysql:;mysql_read_default_group=xtrabackup;mysql_socket=/home/vmg/src/vitess/vtdataroot/vtroot_41001/vt_0000009287/mysql.sock' as 'vt_dba'  (using password: YES).
Failed to connect to MySQL server as DBD::mysql module is not installed at - line 1327.
210611 17:10:31 Connecting to MySQL server host: localhost, user: vt_dba, password: set, port: not set, socket: /home/vmg/src/vitess/vtdataroot/vtroot_41001/vt_0000009287/mysql.sock
Using server version 5.7.34-log
xtrabackup version 2.4.22 based on MySQL server 5.7.32 Linux (x86_64) (revision id: c99a781)
xtrabackup: uses posix_fadvise().
xtrabackup: cd to /home/vmg/src/vitess/vtdataroot/vtroot_41001/vt_0000009287/data
xtrabackup: open files limit requested 0, set to 1024
xtrabackup: using the following InnoDB configuration:
xtrabackup:   innodb_data_home_dir = /home/vmg/src/vitess/vtdataroot/vtroot_41001/vt_0000009287/innodb/data
xtrabackup:   innodb_data_file_path = ibdata1:12M:autoextend
xtrabackup:   innodb_log_group_home_dir = /home/vmg/src/vitess/vtdataroot/vtroot_41001/vt_0000009287/innodb/logs
xtrabackup:   innodb_log_files_in_group = 2
xtrabackup:   innodb_log_file_size = 50331648
InnoDB: Number of pools: 1
InnoDB: Last flushed lsn: 2830506 load_index lsn 2760548
InnoDB: An optimized (without redo logging) DDL operation has been performed. All modified pages may not have been flushed to the disk yet.
InnoDB: Last flushed lsn: 2830506 load_index lsn 2792219
InnoDB: An optimized (without redo logging) DDL operation has been performed. All modified pages may not have been flushed to the disk yet.
210611 17:10:31 >> log scanned up to (2830506)
xtrabackup: Generating a list of tablespaces
InnoDB: Allocated tablespace ID 21 for sys/sys_config, old maximum was 0
210611 17:10:32 [01] Streaming /home/vmg/src/vitess/vtdataroot/vtroot_41001/vt_0000009287/innodb/data/ibdata1
210611 17:10:32 [01]        ...done
210611 17:10:32 [01] Streaming ./sys/sys_config.ibd
210611 17:10:32 [01]        ...done
210611 17:10:32 [01] Streaming ./_vt/shard_metadata.ibd
210611 17:10:32 [01]        ...done
210611 17:10:32 [01] Streaming ./_vt/reparent_journal.ibd
210611 17:10:32 [01]        ...done
210611 17:10:32 [01] Streaming ./_vt/local_metadata.ibd
210611 17:10:32 [01]        ...done
210611 17:10:32 [01] Streaming ./vt_ks/vt_insert_test.ibd
210611 17:10:32 [01]        ...done
210611 17:10:32 [01] Streaming ./mysql/innodb_index_stats.ibd
210611 17:10:32 [01]        ...done
210611 17:10:32 [01] Streaming ./mysql/engine_cost.ibd
210611 17:10:32 [01]        ...done
210611 17:10:32 [01] Streaming ./mysql/slave_relay_log_info.ibd
210611 17:10:32 [01]        ...done
210611 17:10:32 [01] Streaming ./mysql/help_category.ibd
210611 17:10:32 [01]        ...done
210611 17:10:32 [01] Streaming ./mysql/server_cost.ibd
210611 17:10:32 [01]        ...done
210611 17:10:32 [01] Streaming ./mysql/time_zone_transition.ibd
210611 17:10:32 [01]        ...done
210611 17:10:32 [01] Streaming ./mysql/time_zone_transition_type.ibd
210611 17:10:32 [01]        ...done
210611 17:10:32 [01] Streaming ./mysql/help_keyword.ibd
210611 17:10:32 [01]        ...done
210611 17:10:32 [01] Streaming ./mysql/slave_master_info.ibd
210611 17:10:32 [01]        ...done
210611 17:10:32 [01] Streaming ./mysql/innodb_table_stats.ibd
210611 17:10:32 [01]        ...done
210611 17:10:32 [01] Streaming ./mysql/time_zone_name.ibd
210611 17:10:32 [01]        ...done
210611 17:10:32 [01] Streaming ./mysql/servers.ibd
210611 17:10:32 [01]        ...done
210611 17:10:32 [01] Streaming ./mysql/time_zone_leap_second.ibd
210611 17:10:32 [01]        ...done
210611 17:10:32 [01] Streaming ./mysql/help_relation.ibd
210611 17:10:32 [01]        ...done
210611 17:10:32 [01] Streaming ./mysql/slave_worker_info.ibd
210611 17:10:32 [01]        ...done
210611 17:10:32 [01] Streaming ./mysql/gtid_executed.ibd
210611 17:10:32 [01]        ...done
210611 17:10:32 [01] Streaming ./mysql/plugin.ibd
210611 17:10:32 [01]        ...done
210611 17:10:32 [01] Streaming ./mysql/time_zone.ibd
210611 17:10:32 [01]        ...done
210611 17:10:32 [01] Streaming ./mysql/help_topic.ibd
210611 17:10:32 [01]        ...done
InnoDB: Last flushed lsn: 2830506 load_index lsn 2859558
InnoDB: An optimized (without redo logging) DDL operation has been performed. All modified pages may not have been flushed to the disk yet. 
PXB will not be able to make a consistent backup. Retry the backup operation
]
Backup Error: rpc error: code = Unknown desc = TabletManager.Backup on zone1-0000009287 error: xtrabackup failed with error. Output=xtrabackup: recognized server arguments: --datadir=/home/vmg/src/vitess/vtdataroot/vtroot_41001/vt_0000009287/data --innodb_data_home_dir=/home/vmg/src/vitess/vtdataroot/vtroot_41001/vt_0000009287/innodb/data --innodb_log_group_home_dir=/home/vmg/src/vitess/vtdataroot/vtroot_41001/vt_0000009287/innodb/logs --log_bin=/home/vmg/src/vitess/vtdataroot/vtroot_41001/vt_0000009287/bin-logs/vt-0000009287-bin --server-id=1833938403 --tmpdir=/home/vmg/src/vitess/vtdataroot/vtroot_41001/vt_0000009287/tmp 
xtrabackup: recognized client arguments: --backup=1 --socket=/home/vmg/src/vitess/vtdataroot/vtroot_41001/vt_0000009287/mysql.sock --slave-info=1 --user=vt_dba --target-dir=/home/vmg/src/vitess/vtdataroot/vtroot_41001/vt_0000009287/tmp --stream=xbstream --password=* 
210611 17:10:31  version_check Connecting to MySQL server with DSN 'dbi:mysql:;mysql_read_default_group=xtrabackup;mysql_socket=/home/vmg/src/vitess/vtdataroot/vtroot_41001/vt_0000009287/mysql.sock' as 'vt_dba'  (using password: YES).
Failed to connect to MySQL server as DBD::mysql module is not installed at - line 1327.
210611 17:10:31 Connecting to MySQL server host: localhost, user: vt_dba, password: set, port: not set, socket: /home/vmg/src/vitess/vtdataroot/vtroot_41001/vt_0000009287/mysql.sock
Using server version 5.7.34-log
xtrabackup version 2.4.22 based on MySQL server 5.7.32 Linux (x86_64) (revision id: c99a781)
xtrabackup: uses posix_fadvise().
xtrabackup: cd to /home/vmg/src/vitess/vtdataroot/vtroot_41001/vt_0000009287/data
xtrabackup: open files limit requested 0, set to 1024
xtrabackup: using the following InnoDB configuration:
xtrabackup:   innodb_data_home_dir = /home/vmg/src/vitess/vtdataroot/vtroot_41001/vt_0000009287/innodb/data
xtrabackup:   innodb_data_file_path = ibdata1:12M:autoextend
xtrabackup:   innodb_log_group_home_dir = /home/vmg/src/vitess/vtdataroot/vtroot_41001/vt_0000009287/innodb/logs
xtrabackup:   innodb_log_files_in_group = 2
xtrabackup:   innodb_log_file_size = 50331648
InnoDB: Number of pools: 1
InnoDB: Last flushed lsn: 2830506 load_index lsn 2760548
InnoDB: An optimized (without redo logging) DDL operation has been performed. All modified pages may not have been flushed to the disk yet.
InnoDB: Last flushed lsn: 2830506 load_index lsn 2792219
InnoDB: An optimized (without redo logging) DDL operation has been performed. All modified pages may not have been flushed to the disk yet.
210611 17:10:31 >> log scanned up to (2830506)
xtrabackup: Generating a list of tablespaces
InnoDB: Allocated tablespace ID 21 for sys/sys_config, old maximum was 0
210611 17:10:32 [01] Streaming /home/vmg/src/vitess/vtdataroot/vtroot_41001/vt_0000009287/innodb/data/ibdata1
210611 17:10:32 [01]        ...done
210611 17:10:32 [01] Streaming ./sys/sys_config.ibd
210611 17:10:32 [01]        ...done
210611 17:10:32 [01] Streaming ./_vt/shard_metadata.ibd
210611 17:10:32 [01]        ...done
210611 17:10:32 [01] Streaming ./_vt/reparent_journal.ibd
210611 17:10:32 [01]        ...done
210611 17:10:32 [01] Streaming ./_vt/local_metadata.ibd
210611 17:10:32 [01]        ...done
210611 17:10:32 [01] Streaming ./vt_ks/vt_insert_test.ibd
210611 17:10:32 [01]        ...done
210611 17:10:32 [01] Streaming ./mysql/innodb_index_stats.ibd
210611 17:10:32 [01]        ...done
210611 17:10:32 [01] Streaming ./mysql/engine_cost.ibd
210611 17:10:32 [01]        ...done
210611 17:10:32 [01] Streaming ./mysql/slave_relay_log_info.ibd
210611 17:10:32 [01]        ...done
210611 17:10:32 [01] Streaming ./mysql/help_category.ibd
210611 17:10:32 [01]        ...done
210611 17:10:32 [01] Streaming ./mysql/server_cost.ibd
210611 17:10:32 [01]        ...done
210611 17:10:32 [01] Streaming ./mysql/time_zone_transition.ibd
210611 17:10:32 [01]        ...done
210611 17:10:32 [01] Streaming ./mysql/time_zone_transition_type.ibd
210611 17:10:32 [01]        ...done
210611 17:10:32 [01] Streaming ./mysql/help_keyword.ibd
210611 17:10:32 [01]        ...done
210611 17:10:32 [01] Streaming ./mysql/slave_master_info.ibd
210611 17:10:32 [01]        ...done
210611 17:10:32 [01] Streaming ./mysql/innodb_table_stats.ibd
210611 17:10:32 [01]        ...done
210611 17:10:32 [01] Streaming ./mysql/time_zone_name.ibd
210611 17:10:32 [01]        ...done
210611 17:10:32 [01] Streaming ./mysql/servers.ibd
210611 17:10:32 [01]        ...done
210611 17:10:32 [01] Streaming ./mysql/time_zone_leap_second.ibd
210611 17:10:32 [01]        ...done
210611 17:10:32 [01] Streaming ./mysql/help_relation.ibd
210611 17:10:32 [01]        ...done
210611 17:10:32 [01] Streaming ./mysql/slave_worker_info.ibd
210611 17:10:32 [01]        ...done
210611 17:10:32 [01] Streaming ./mysql/gtid_executed.ibd
210611 17:10:32 [01]        ...done
210611 17:10:32 [01] Streaming ./mysql/plugin.ibd
210611 17:10:32 [01]        ...done
210611 17:10:32 [01] Streaming ./mysql/time_zone.ibd
210611 17:10:32 [01]        ...done
210611 17:10:32 [01] Streaming ./mysql/help_topic.ibd
210611 17:10:32 [01]        ...done
InnoDB: Last flushed lsn: 2830506 load_index lsn 2859558
InnoDB: An optimized (without redo logging) DDL operation has been performed. All modified pages may not have been flushed to the disk yet. 
PXB will not be able to make a consistent backup. Retry the backup operation
: exit status 1: xtrabackup failed with error. Output=xtrabackup: recognized server arguments: --datadir=/home/vmg/src/vitess/vtdataroot/vtroot_41001/vt_0000009287/data --innodb_data_home_dir=/home/vmg/src/vitess/vtdataroot/vtroot_41001/vt_0000009287/innodb/data --innodb_log_group_home_dir=/home/vmg/src/vitess/vtdataroot/vtroot_41001/vt_0000009287/innodb/logs --log_bin=/home/vmg/src/vitess/vtdataroot/vtroot_41001/vt_0000009287/bin-logs/vt-0000009287-bin --server-id=1833938403 --tmpdir=/home/vmg/src/vitess/vtdataroot/vtroot_41001/vt_0000009287/tmp 
xtrabackup: recognized client arguments: --backup=1 --socket=/home/vmg/src/vitess/vtdataroot/vtroot_41001/vt_0000009287/mysql.sock --slave-info=1 --user=vt_dba --target-dir=/home/vmg/src/vitess/vtdataroot/vtroot_41001/vt_0000009287/tmp --stream=xbstream --password=* 
210611 17:10:31  version_check Connecting to MySQL server with DSN 'dbi:mysql:;mysql_read_default_group=xtrabackup;mysql_socket=/home/vmg/src/vitess/vtdataroot/vtroot_41001/vt_0000009287/mysql.sock' as 'vt_dba'  (using password: YES).
Failed to connect to MySQL server as DBD::mysql module is not installed at - line 1327.
210611 17:10:31 Connecting to MySQL server host: localhost, user: vt_dba, password: set, port: not set, socket: /home/vmg/src/vitess/vtdataroot/vtroot_41001/vt_0000009287/mysql.sock
Using server version 5.7.34-log
xtrabackup version 2.4.22 based on MySQL server 5.7.32 Linux (x86_64) (revision id: c99a781)
xtrabackup: uses posix_fadvise().
xtrabackup: cd to /home/vmg/src/vitess/vtdataroot/vtroot_41001/vt_0000009287/data
xtrabackup: open files limit requested 0, set to 1024
xtrabackup: using the following InnoDB configuration:
xtrabackup:   innodb_data_home_dir = /home/vmg/src/vitess/vtdataroot/vtroot_41001/vt_0000009287/innodb/data
xtrabackup:   innodb_data_file_path = ibdata1:12M:autoextend
xtrabackup:   innodb_log_group_home_dir = /home/vmg/src/vitess/vtdataroot/vtroot_41001/vt_0000009287/innodb/logs
xtrabackup:   innodb_log_files_in_group = 2
xtrabackup:   innodb_log_file_size = 50331648
InnoDB: Number of pools: 1
InnoDB: Last flushed lsn: 2830506 load_index lsn 2760548
InnoDB: An optimized (without redo logging) DDL operation has been performed. All modified pages may not have been flushed to the disk yet.
InnoDB: Last flushed lsn: 2830506 load_index lsn 2792219
InnoDB: An optimized (without redo logging) DDL operation has been performed. All modified pages may not have been flushed to the disk yet.
210611 17:10:31 >> log scanned up to (2830506)
xtrabackup: Generating a list of tablespaces
InnoDB: Allocated tablespace ID 21 for sys/sys_config, old maximum was 0
210611 17:10:32 [01] Streaming /home/vmg/src/vitess/vtdataroot/vtroot_41001/vt_0000009287/innodb/data/ibdata1
210611 17:10:32 [01]        ...done
210611 17:10:32 [01] Streaming ./sys/sys_config.ibd
210611 17:10:32 [01]        ...done
210611 17:10:32 [01] Streaming ./_vt/shard_metadata.ibd
210611 17:10:32 [01]        ...done
210611 17:10:32 [01] Streaming ./_vt/reparent_journal.ibd
210611 17:10:32 [01]        ...done
210611 17:10:32 [01] Streaming ./_vt/local_metadata.ibd
210611 17:10:32 [01]        ...done
210611 17:10:32 [01] Streaming ./vt_ks/vt_insert_test.ibd
210611 17:10:32 [01]        ...done
210611 17:10:32 [01] Streaming ./mysql/innodb_index_stats.ibd
210611 17:10:32 [01]        ...done
210611 17:10:32 [01] Streaming ./mysql/engine_cost.ibd
210611 17:10:32 [01]        ...done
210611 17:10:32 [01] Streaming ./mysql/slave_relay_log_info.ibd
210611 17:10:32 [01]        ...done
210611 17:10:32 [01] Streaming ./mysql/help_category.ibd
210611 17:10:32 [01]        ...done
210611 17:10:32 [01] Streaming ./mysql/server_cost.ibd
210611 17:10:32 [01]        ...done
210611 17:10:32 [01] Streaming ./mysql/time_zone_transition.ibd
210611 17:10:32 [01]        ...done
210611 17:10:32 [01] Streaming ./mysql/time_zone_transition_type.ibd
210611 17:10:32 [01]        ...done
210611 17:10:32 [01] Streaming ./mysql/help_keyword.ibd
210611 17:10:32 [01]        ...done
210611 17:10:32 [01] Streaming ./mysql/slave_master_info.ibd
210611 17:10:32 [01]        ...done
210611 17:10:32 [01] Streaming ./mysql/innodb_table_stats.ibd
210611 17:10:32 [01]        ...done
210611 17:10:32 [01] Streaming ./mysql/time_zone_name.ibd
210611 17:10:32 [01]        ...done
210611 17:10:32 [01] Streaming ./mysql/servers.ibd
210611 17:10:32 [01]        ...done
210611 17:10:32 [01] Streaming ./mysql/time_zone_leap_second.ibd
210611 17:10:32 [01]        ...done
210611 17:10:32 [01] Streaming ./mysql/help_relation.ibd
210611 17:10:32 [01]        ...done
210611 17:10:32 [01] Streaming ./mysql/slave_worker_info.ibd
210611 17:10:32 [01]        ...done
210611 17:10:32 [01] Streaming ./mysql/gtid_executed.ibd
210611 17:10:32 [01]        ...done
210611 17:10:32 [01] Streaming ./mysql/plugin.ibd
210611 17:10:32 [01]        ...done
210611 17:10:32 [01] Streaming ./mysql/time_zone.ibd
210611 17:10:32 [01]        ...done
210611 17:10:32 [01] Streaming ./mysql/help_topic.ibd
210611 17:10:32 [01]        ...done
InnoDB: Last flushed lsn: 2830506 load_index lsn 2859558
InnoDB: An optimized (without redo logging) DDL operation has been performed. All modified pages may not have been flushed to the disk yet. 
PXB will not be able to make a consistent backup. Retry the backup operation
: exit status 1
E0611 17:10:32.970059  357716 main.go:76] remote error: rpc error: code = Unknown desc = TabletManager.Backup on zone1-0000009287 error: xtrabackup failed with error. Output=xtrabackup: recognized server arguments: --datadir=/home/vmg/src/vitess/vtdataroot/vtroot_41001/vt_0000009287/data --innodb_data_home_dir=/home/vmg/src/vitess/vtdataroot/vtroot_41001/vt_0000009287/innodb/data --innodb_log_group_home_dir=/home/vmg/src/vitess/vtdataroot/vtroot_41001/vt_0000009287/innodb/logs --log_bin=/home/vmg/src/vitess/vtdataroot/vtroot_41001/vt_0000009287/bin-logs/vt-0000009287-bin --server-id=1833938403 --tmpdir=/home/vmg/src/vitess/vtdataroot/vtroot_41001/vt_0000009287/tmp 
xtrabackup: recognized client arguments: --backup=1 --socket=/home/vmg/src/vitess/vtdataroot/vtroot_41001/vt_0000009287/mysql.sock --slave-info=1 --user=vt_dba --target-dir=/home/vmg/src/vitess/vtdataroot/vtroot_41001/vt_0000009287/tmp --stream=xbstream --password=* 
210611 17:10:31  version_check Connecting to MySQL server with DSN 'dbi:mysql:;mysql_read_default_group=xtrabackup;mysql_socket=/home/vmg/src/vitess/vtdataroot/vtroot_41001/vt_0000009287/mysql.sock' as 'vt_dba'  (using password: YES).
Failed to connect to MySQL server as DBD::mysql module is not installed at - line 1327.
210611 17:10:31 Connecting to MySQL server host: localhost, user: vt_dba, password: set, port: not set, socket: /home/vmg/src/vitess/vtdataroot/vtroot_41001/vt_0000009287/mysql.sock
Using server version 5.7.34-log
xtrabackup version 2.4.22 based on MySQL server 5.7.32 Linux (x86_64) (revision id: c99a781)
xtrabackup: uses posix_fadvise().
xtrabackup: cd to /home/vmg/src/vitess/vtdataroot/vtroot_41001/vt_0000009287/data
xtrabackup: open files limit requested 0, set to 1024
xtrabackup: using the following InnoDB configuration:
xtrabackup:   innodb_data_home_dir = /home/vmg/src/vitess/vtdataroot/vtroot_41001/vt_0000009287/innodb/data
xtrabackup:   innodb_data_file_path = ibdata1:12M:autoextend
xtrabackup:   innodb_log_group_home_dir = /home/vmg/src/vitess/vtdataroot/vtroot_41001/vt_0000009287/innodb/logs
xtrabackup:   innodb_log_files_in_group = 2
xtrabackup:   innodb_log_file_size = 50331648
InnoDB: Number of pools: 1
InnoDB: Last flushed lsn: 2830506 load_index lsn 2760548
InnoDB: An optimized (without redo logging) DDL operation has been performed. All modified pages may not have been flushed to the disk yet.
InnoDB: Last flushed lsn: 2830506 load_index lsn 2792219
InnoDB: An optimized (without redo logging) DDL operation has been performed. All modified pages may not have been flushed to the disk yet.
210611 17:10:31 >> log scanned up to (2830506)
xtrabackup: Generating a list of tablespaces
InnoDB: Allocated tablespace ID 21 for sys/sys_config, old maximum was 0
210611 17:10:32 [01] Streaming /home/vmg/src/vitess/vtdataroot/vtroot_41001/vt_0000009287/innodb/data/ibdata1
210611 17:10:32 [01]        ...done
210611 17:10:32 [01] Streaming ./sys/sys_config.ibd
210611 17:10:32 [01]        ...done
210611 17:10:32 [01] Streaming ./_vt/shard_metadata.ibd
210611 17:10:32 [01]        ...done
210611 17:10:32 [01] Streaming ./_vt/reparent_journal.ibd
210611 17:10:32 [01]        ...done
210611 17:10:32 [01] Streaming ./_vt/local_metadata.ibd
210611 17:10:32 [01]        ...done
210611 17:10:32 [01] Streaming ./vt_ks/vt_insert_test.ibd
210611 17:10:32 [01]        ...done
210611 17:10:32 [01] Streaming ./mysql/innodb_index_stats.ibd
210611 17:10:32 [01]        ...done
210611 17:10:32 [01] Streaming ./mysql/engine_cost.ibd
210611 17:10:32 [01]        ...done
210611 17:10:32 [01] Streaming ./mysql/slave_relay_log_info.ibd
210611 17:10:32 [01]        ...done
210611 17:10:32 [01] Streaming ./mysql/help_category.ibd
210611 17:10:32 [01]        ...done
210611 17:10:32 [01] Streaming ./mysql/server_cost.ibd
210611 17:10:32 [01]        ...done
210611 17:10:32 [01] Streaming ./mysql/time_zone_transition.ibd
210611 17:10:32 [01]        ...done
210611 17:10:32 [01] Streaming ./mysql/time_zone_transition_type.ibd
210611 17:10:32 [01]        ...done
210611 17:10:32 [01] Streaming ./mysql/help_keyword.ibd
210611 17:10:32 [01]        ...done
210611 17:10:32 [01] Streaming ./mysql/slave_master_info.ibd
210611 17:10:32 [01]        ...done
210611 17:10:32 [01] Streaming ./mysql/innodb_table_stats.ibd
210611 17:10:32 [01]        ...done
210611 17:10:32 [01] Streaming ./mysql/time_zone_name.ibd
210611 17:10:32 [01]        ...done
210611 17:10:32 [01] Streaming ./mysql/servers.ibd
210611 17:10:32 [01]        ...done
210611 17:10:32 [01] Streaming ./mysql/time_zone_leap_second.ibd
210611 17:10:32 [01]        ...done
210611 17:10:32 [01] Streaming ./mysql/help_relation.ibd
210611 17:10:32 [01]        ...done
210611 17:10:32 [01] Streaming ./mysql/slave_worker_info.ibd
210611 17:10:32 [01]        ...done
210611 17:10:32 [01] Streaming ./mysql/gtid_executed.ibd
210611 17:10:32 [01]        ...done
210611 17:10:32 [01] Streaming ./mysql/plugin.ibd
210611 17:10:32 [01]        ...done
210611 17:10:32 [01] Streaming ./mysql/time_zone.ibd
210611 17:10:32 [01]        ...done
210611 17:10:32 [01] Streaming ./mysql/help_topic.ibd
210611 17:10:32 [01]        ...done
InnoDB: Last flushed lsn: 2830506 load_index lsn 2859558
InnoDB: An optimized (without redo logging) DDL operation has been performed. All modified pages may not have been flushed to the disk yet. 
PXB will not be able to make a consistent backup. Retry the backup operation
: exit status 1: xtrabackup failed with error. Output=xtrabackup: recognized server arguments: --datadir=/home/vmg/src/vitess/vtdataroot/vtroot_41001/vt_0000009287/data --innodb_data_home_dir=/home/vmg/src/vitess/vtdataroot/vtroot_41001/vt_0000009287/innodb/data --innodb_log_group_home_dir=/home/vmg/src/vitess/vtdataroot/vtroot_41001/vt_0000009287/innodb/logs --log_bin=/home/vmg/src/vitess/vtdataroot/vtroot_41001/vt_0000009287/bin-logs/vt-0000009287-bin --server-id=1833938403 --tmpdir=/home/vmg/src/vitess/vtdataroot/vtroot_41001/vt_0000009287/tmp 
xtrabackup: recognized client arguments: --backup=1 --socket=/home/vmg/src/vitess/vtdataroot/vtroot_41001/vt_0000009287/mysql.sock --slave-info=1 --user=vt_dba --target-dir=/home/vmg/src/vitess/vtdataroot/vtroot_41001/vt_0000009287/tmp --stream=xbstream --password=* 
210611 17:10:31  version_check Connecting to MySQL server with DSN 'dbi:mysql:;mysql_read_default_group=xtrabackup;mysql_socket=/home/vmg/src/vitess/vtdataroot/vtroot_41001/vt_0000009287/mysql.sock' as 'vt_dba'  (using password: YES).
Failed to connect to MySQL server as DBD::mysql module is not installed at - line 1327.
210611 17:10:31 Connecting to MySQL server host: localhost, user: vt_dba, password: set, port: not set, socket: /home/vmg/src/vitess/vtdataroot/vtroot_41001/vt_0000009287/mysql.sock
Using server version 5.7.34-log
xtrabackup version 2.4.22 based on MySQL server 5.7.32 Linux (x86_64) (revision id: c99a781)
xtrabackup: uses posix_fadvise().
xtrabackup: cd to /home/vmg/src/vitess/vtdataroot/vtroot_41001/vt_0000009287/data
xtrabackup: open files limit requested 0, set to 1024
xtrabackup: using the following InnoDB configuration:
xtrabackup:   innodb_data_home_dir = /home/vmg/src/vitess/vtdataroot/vtroot_41001/vt_0000009287/innodb/data
xtrabackup:   innodb_data_file_path = ibdata1:12M:autoextend
xtrabackup:   innodb_log_group_home_dir = /home/vmg/src/vitess/vtdataroot/vtroot_41001/vt_0000009287/innodb/logs
xtrabackup:   innodb_log_files_in_group = 2
xtrabackup:   innodb_log_file_size = 50331648
InnoDB: Number of pools: 1
InnoDB: Last flushed lsn: 2830506 load_index lsn 2760548
InnoDB: An optimized (without redo logging) DDL operation has been performed. All modified pages may not have been flushed to the disk yet.
InnoDB: Last flushed lsn: 2830506 load_index lsn 2792219
InnoDB: An optimized (without redo logging) DDL operation has been performed. All modified pages may not have been flushed to the disk yet.
210611 17:10:31 >> log scanned up to (2830506)
xtrabackup: Generating a list of tablespaces
InnoDB: Allocated tablespace ID 21 for sys/sys_config, old maximum was 0
210611 17:10:32 [01] Streaming /home/vmg/src/vitess/vtdataroot/vtroot_41001/vt_0000009287/innodb/data/ibdata1
210611 17:10:32 [01]        ...done
210611 17:10:32 [01] Streaming ./sys/sys_config.ibd
210611 17:10:32 [01]        ...done
210611 17:10:32 [01] Streaming ./_vt/shard_metadata.ibd
210611 17:10:32 [01]        ...done
210611 17:10:32 [01] Streaming ./_vt/reparent_journal.ibd
210611 17:10:32 [01]        ...done
210611 17:10:32 [01] Streaming ./_vt/local_metadata.ibd
210611 17:10:32 [01]        ...done
210611 17:10:32 [01] Streaming ./vt_ks/vt_insert_test.ibd
210611 17:10:32 [01]        ...done
210611 17:10:32 [01] Streaming ./mysql/innodb_index_stats.ibd
210611 17:10:32 [01]        ...done
210611 17:10:32 [01] Streaming ./mysql/engine_cost.ibd
210611 17:10:32 [01]        ...done
210611 17:10:32 [01] Streaming ./mysql/slave_relay_log_info.ibd
210611 17:10:32 [01]        ...done
210611 17:10:32 [01] Streaming ./mysql/help_category.ibd
210611 17:10:32 [01]        ...done
210611 17:10:32 [01] Streaming ./mysql/server_cost.ibd
210611 17:10:32 [01]        ...done
210611 17:10:32 [01] Streaming ./mysql/time_zone_transition.ibd
210611 17:10:32 [01]        ...done
210611 17:10:32 [01] Streaming ./mysql/time_zone_transition_type.ibd
210611 17:10:32 [01]        ...done
210611 17:10:32 [01] Streaming ./mysql/help_keyword.ibd
210611 17:10:32 [01]        ...done
210611 17:10:32 [01] Streaming ./mysql/slave_master_info.ibd
210611 17:10:32 [01]        ...done
210611 17:10:32 [01] Streaming ./mysql/innodb_table_stats.ibd
210611 17:10:32 [01]        ...done
210611 17:10:32 [01] Streaming ./mysql/time_zone_name.ibd
210611 17:10:32 [01]        ...done
210611 17:10:32 [01] Streaming ./mysql/servers.ibd
210611 17:10:32 [01]        ...done
210611 17:10:32 [01] Streaming ./mysql/time_zone_leap_second.ibd
210611 17:10:32 [01]        ...done
210611 17:10:32 [01] Streaming ./mysql/help_relation.ibd
210611 17:10:32 [01]        ...done
210611 17:10:32 [01] Streaming ./mysql/slave_worker_info.ibd
210611 17:10:32 [01]        ...done
210611 17:10:32 [01] Streaming ./mysql/gtid_executed.ibd
210611 17:10:32 [01]        ...done
210611 17:10:32 [01] Streaming ./mysql/plugin.ibd
210611 17:10:32 [01]        ...done
210611 17:10:32 [01] Streaming ./mysql/time_zone.ibd
210611 17:10:32 [01]        ...done
210611 17:10:32 [01] Streaming ./mysql/help_topic.ibd
210611 17:10:32 [01]        ...done
InnoDB: Last flushed lsn: 2830506 load_index lsn 2859558
InnoDB: An optimized (without redo logging) DDL operation has been performed. All modified pages may not have been flushed to the disk yet. 
PXB will not be able to make a consistent backup. Retry the backup operation
: exit status 1
    recovery.go:190: 
        	Error Trace:	recovery.go:190
        	Error:      	Received unexpected error:
        	           	exit status 1
        	Test:       	TestRecovery
    recovery.go:193: 
        	Error Trace:	recovery.go:193
        	Error:      	Not equal: 
        	           	expected: 0
        	           	actual  : 1
        	Test:       	TestRecovery
--- FAIL: TestRecovery (13.64s)
FAIL
FAIL	vitess.io/vitess/go/test/endtoend/recovery/xtrabackup	34.570s
FAIL

Note that by default the full output of xtrabackup is not passed through verbatim. A small change is required to obtain the full stderr of the process that shows the actual error, which AFAICT is:

InnoDB: An optimized (without redo logging) DDL operation has been performed. All modified pages may not have been flushed to the disk yet.
PXB will not be able to make a consistent backup. Retry the backup operation
@deepthi deepthi mentioned this issue Jun 11, 2021
Closed
2 tasks
@ajm188 ajm188 mentioned this issue Jun 14, 2021
Closed
@shlomi-noach shlomi-noach mentioned this issue Jun 15, 2021
Merged
2 tasks
@deepthi
Copy link
Member

deepthi commented Jul 6, 2021

Closing since #8340 has merged.
Note that this error might occur in production environments, not just in tests. The solution in #8340 is only a workaround for tests.

@deepthi deepthi closed this as completed Jul 6, 2021
@rsajwani rsajwani mentioned this issue Mar 8, 2023
Merged
3 tasks
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
Component: Build/CI Type: CI/Build Type: Testing
Projects
None yet
Milestone
No milestone
Development

Successfully merging a pull request may close this issue.

workaround xtrabackup error with old_alter_table planetscale/vitess
3 participants
@vmg @deepthi @askdba