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

Flaky xb_recovery test #8330

Closed
ajm188 opened this issue Jun 14, 2021 · 1 comment
Closed

Flaky xb_recovery test #8330

ajm188 opened this issue Jun 14, 2021 · 1 comment
Labels
Component: Build/CI Type: CI/Build

Comments

@ajm188
Copy link
Contributor

ajm188 commented Jun 14, 2021

Immediate failure snippet:

I0614 14:33:23.705407   14191 vtctlclient_process.go:177] Executing vtctlclient with command: vtctlclient -server localhost:16006 Backup zone1-0000002433
E0614 14:33:25.539111   14191 vtctlclient_process.go:158] Output:
E0614 14:33:25.537726   17227 main.go:67] E0614 14:33:25.537448 backup.go:163] E0614 14:33:25.537318 backup.go:123] backup is not usable, aborting it: [exit status 1
Backup Error: rpc error: code = Unknown desc = TabletManager.Backup on zone1-0000002433 error: xtrabackup failed with error. Output=: exit status 1: xtrabackup failed with error. Output=: exit status 1
E0614 14:33:25.538497   17227 main.go:76] remote error: rpc error: code = Unknown desc = TabletManager.Backup on zone1-0000002433 error: xtrabackup failed with error. Output=: exit status 1: xtrabackup failed with error. Output=: exit status 1
    recovery.go:190: 
        	Error Trace:	recovery.go:190
        	Error:      	Received unexpected error:
        	            	exit status 1
        	Test:       	TestRecovery
I0614 14:33:25.539218   14191 vtctlclient_process.go:177] Executing vtctlclient with command: vtctlclient -server localhost:16006 ListBackups ks/0
    recovery.go:193: 
        	Error Trace:	recovery.go:193
        	Error:      	Not equal: 
        	            	expected: 0
        	            	actual  : 1
        	Test:       	TestRecovery
--- FAIL: TestRecovery (13.93s)
FAIL
FAIL	vitess.io/vitess/go/test/endtoend/recovery/xtrabackup	28.376s
FAIL
Full logs: 
2021/06/14 14:30:05 Output directory: _test/20210614-143005.5733
2021/06/14 14:30:05 Running make build...
2021/06/14 14:32:52 local.xb_recovery: running (try 1/3)...
running tests for  vitess.io/vitess/go/test/endtoend/recovery/xtrabackup
I0614 14:33:09.409267   14191 cluster_process.go:633] Attempting to reserve port: 16001
I0614 14:33:09.409779   14191 cluster_process.go:641] Port 16001 is available, reserving..
I0614 14:33:09.410125   14191 cluster_process.go:475] Created cluster on /home/runner/work/vitess/vitess/vtdataroot/vt_805034223/vtroot_16001. ReusingVTDATAROOT=false
I0614 14:33:09.410154   14191 cluster_process.go:633] Attempting to reserve port: 16002
I0614 14:33:09.410179   14191 cluster_process.go:641] Port 16002 is available, reserving..
I0614 14:33:09.410194   14191 cluster_process.go:633] Attempting to reserve port: 16003
I0614 14:33:09.410207   14191 cluster_process.go:641] Port 16003 is available, reserving..
I0614 14:33:09.410849   14191 cluster_process.go:633] Attempting to reserve port: 16004
I0614 14:33:09.410874   14191 cluster_process.go:641] Port 16004 is available, reserving..
I0614 14:33:09.410908   14191 cluster_process.go:186] Starting topo server etcd2 on port: 16002
E0614 14:33:09.411448   14191 topo_process.go:92] Starting etcd with command: etcd --name global --data-dir /home/runner/work/vitess/vitess/vtdataroot/vt_805034223/vtroot_16001/topo_16002 --listen-client-urls http://localhost:16002 --advertise-client-urls http://localhost:16002 --initial-advertise-peer-urls http://localhost:16004 --listen-peer-urls http://localhost:16004 --initial-cluster global=http://localhost:16004 --enable-v2=true
I0614 14:33:10.434799   14191 cluster_process.go:193] Creating global and cell topo dirs
I0614 14:33:10.436836   14191 vtctl_process.go:55] Adding CellInfo for cell zone1 with command: vtctl -topo_implementation etcd2 -topo_global_server_address localhost:16002 -topo_global_root /vitess/global AddCellInfo -root /zone1 -server_address localhost:16002 zone1
I0614 14:33:10.478137   14191 cluster_process.go:633] Attempting to reserve port: 16005
I0614 14:33:10.478199   14191 cluster_process.go:641] Port 16005 is available, reserving..
I0614 14:33:10.478213   14191 cluster_process.go:633] Attempting to reserve port: 16006
I0614 14:33:10.478245   14191 cluster_process.go:641] Port 16006 is available, reserving..
I0614 14:33:10.478264   14191 cluster_process.go:215] Starting vtctld server on port: 16005
I0614 14:33:10.478387   14191 vtctld_process.go:86] Starting vtctld with command: vtctld -enable_queries -topo_implementation etcd2 -topo_global_server_address localhost:16002 -topo_global_root /vitess/global -cell zone1 -workflow_manager_init -workflow_manager_use_election -service_map grpc-vtctl -backup_storage_implementation file -file_backup_storage_root /home/runner/work/vitess/vitess/vtdataroot/vt_805034223/vtroot_16001/backups -wait_for_drain_sleep_rdonly 1s -wait_for_drain_sleep_replica 1s -online_ddl_check_interval 2s -log_dir /home/runner/work/vitess/vitess/vtdataroot/vt_805034223/vtroot_16001/tmp_16003 -port 16005 -grpc_port 16006
I0614 14:33:10.781526   14191 mysqlctl_process.go:124] Starting mysqlctl with command: [mysqlctl -log_dir /home/runner/work/vitess/vitess/vtdataroot/vt_805034223/vtroot_16001/tmp_16003 -tablet_uid 100 -mysql_port 15000 init -init_db_sql_file /home/runner/work/vitess/vitess/config/init_db.sql start]
I0614 14:33:13.895485   14191 mysqlctl_process.go:130] Shutting down MySQL: 100
I0614 14:33:15.927106   14191 mysqlctl_process.go:136] MySQL shutdown complete: 100
I0614 14:33:15.952068   14191 cluster_process.go:633] Attempting to reserve port: 16007
I0614 14:33:15.952130   14191 cluster_process.go:641] Port 16007 is available, reserving..
I0614 14:33:15.952144   14191 cluster_process.go:633] Attempting to reserve port: 16008
I0614 14:33:15.952163   14191 cluster_process.go:641] Port 16008 is available, reserving..
I0614 14:33:15.952170   14191 cluster_process.go:633] Attempting to reserve port: 16009
I0614 14:33:15.952185   14191 cluster_process.go:641] Port 16009 is available, reserving..
I0614 14:33:15.952226   14191 mysqlctl_process.go:124] Starting mysqlctl with command: [mysqlctl -log_dir /home/runner/work/vitess/vitess/vtdataroot/vt_805034223/vtroot_16001/tmp_16003 -tablet_uid 2432 -mysql_port 16009 -db-credentials-file /home/runner/work/vitess/vitess/vtdataroot/vt_805034223/vtroot_16001/tmp_16003/db_credentials.json init -init_db_sql_file /home/runner/work/vitess/vitess/vtdataroot/vt_805034223/vtroot_16001/tmp_16003/init_db_with_passwords.sql start]
I0614 14:33:15.953314   14191 cluster_process.go:633] Attempting to reserve port: 16010
I0614 14:33:15.953359   14191 cluster_process.go:641] Port 16010 is available, reserving..
I0614 14:33:15.953373   14191 cluster_process.go:633] Attempting to reserve port: 16011
I0614 14:33:15.953387   14191 cluster_process.go:641] Port 16011 is available, reserving..
I0614 14:33:15.953394   14191 cluster_process.go:633] Attempting to reserve port: 16012
I0614 14:33:15.953408   14191 cluster_process.go:641] Port 16012 is available, reserving..
I0614 14:33:15.953441   14191 mysqlctl_process.go:124] Starting mysqlctl with command: [mysqlctl -log_dir /home/runner/work/vitess/vitess/vtdataroot/vt_805034223/vtroot_16001/tmp_16003 -tablet_uid 2433 -mysql_port 16012 -db-credentials-file /home/runner/work/vitess/vitess/vtdataroot/vt_805034223/vtroot_16001/tmp_16003/db_credentials.json init -init_db_sql_file /home/runner/work/vitess/vitess/vtdataroot/vt_805034223/vtroot_16001/tmp_16003/init_db_with_passwords.sql start]
I0614 14:33:15.955063   14191 cluster_process.go:633] Attempting to reserve port: 16013
I0614 14:33:15.955103   14191 cluster_process.go:641] Port 16013 is available, reserving..
I0614 14:33:15.955117   14191 cluster_process.go:633] Attempting to reserve port: 16014
I0614 14:33:15.955132   14191 cluster_process.go:641] Port 16014 is available, reserving..
I0614 14:33:15.955139   14191 cluster_process.go:633] Attempting to reserve port: 16015
I0614 14:33:15.955152   14191 cluster_process.go:641] Port 16015 is available, reserving..
I0614 14:33:15.955182   14191 mysqlctl_process.go:124] Starting mysqlctl with command: [mysqlctl -log_dir /home/runner/work/vitess/vitess/vtdataroot/vt_805034223/vtroot_16001/tmp_16003 -tablet_uid 2434 -mysql_port 16015 -db-credentials-file /home/runner/work/vitess/vitess/vtdataroot/vt_805034223/vtroot_16001/tmp_16003/db_credentials.json init -init_db_sql_file /home/runner/work/vitess/vitess/vtdataroot/vt_805034223/vtroot_16001/tmp_16003/init_db_with_passwords.sql start]
I0614 14:33:15.957284   14191 cluster_process.go:633] Attempting to reserve port: 16016
I0614 14:33:15.957320   14191 cluster_process.go:641] Port 16016 is available, reserving..
I0614 14:33:15.957331   14191 cluster_process.go:633] Attempting to reserve port: 16017
I0614 14:33:15.957346   14191 cluster_process.go:641] Port 16017 is available, reserving..
I0614 14:33:15.957352   14191 cluster_process.go:633] Attempting to reserve port: 16018
I0614 14:33:15.957366   14191 cluster_process.go:641] Port 16018 is available, reserving..
I0614 14:33:15.957397   14191 mysqlctl_process.go:124] Starting mysqlctl with command: [mysqlctl -log_dir /home/runner/work/vitess/vitess/vtdataroot/vt_805034223/vtroot_16001/tmp_16003 -tablet_uid 2435 -mysql_port 16018 -db-credentials-file /home/runner/work/vitess/vitess/vtdataroot/vt_805034223/vtroot_16001/tmp_16003/db_credentials.json init -init_db_sql_file /home/runner/work/vitess/vitess/vtdataroot/vt_805034223/vtroot_16001/tmp_16003/init_db_with_passwords.sql start]
I0614 14:33:22.314104   14191 vttablet_process.go:128] Running vttablet with command: vttablet -topo_implementation etcd2 -topo_global_server_address localhost:16002 -topo_global_root /vitess/global -log_queries_to_file /home/runner/work/vitess/vitess/vtdataroot/vt_805034223/vtroot_16001/tmp_16003/vt_0000002432_querylog.txt -tablet-path zone1-0000002432 -port 16007 -grpc_port 16008 -init_shard 0 -log_dir /home/runner/work/vitess/vitess/vtdataroot/vt_805034223/vtroot_16001/tmp_16003 -tablet_hostname localhost -init_keyspace ks -init_tablet_type replica -health_check_interval 5s -enable_replication_reporter -backup_storage_implementation file -file_backup_storage_root /home/runner/work/vitess/vitess/vtdataroot/vt_805034223/vtroot_16001/backups -service_map grpc-queryservice,grpc-tabletmanager,grpc-updatestream,grpc-throttler -vtctld_addr http://localhost:16005 -vtctld_addr http://localhost:16005 -vreplication_tablet_type replica -restore_from_backup -enable_semi_sync -vreplication_healthcheck_topology_refresh 1s -vreplication_healthcheck_retry_delay 1s -vreplication_retry_delay 1s -degraded_threshold 5s -lock_tables_timeout 5s -watch_replication_stream -serving_state_grace_period 1s -db-credentials-file /home/runner/work/vitess/vitess/vtdataroot/vt_805034223/vtroot_16001/tmp_16003/db_credentials.json -backup_engine_implementation xtrabackup -xtrabackup_stream_mode=xbstream -xtrabackup_user=vt_dba -xtrabackup_backup_flags --***
I0614 14:33:22.618263   14191 vttablet_process.go:128] Running vttablet with command: vttablet -topo_implementation etcd2 -topo_global_server_address localhost:16002 -topo_global_root /vitess/global -log_queries_to_file /home/runner/work/vitess/vitess/vtdataroot/vt_805034223/vtroot_16001/tmp_16003/vt_0000002433_querylog.txt -tablet-path zone1-0000002433 -port 16010 -grpc_port 16011 -init_shard 0 -log_dir /home/runner/work/vitess/vitess/vtdataroot/vt_805034223/vtroot_16001/tmp_16003 -tablet_hostname localhost -init_keyspace ks -init_tablet_type replica -health_check_interval 5s -enable_replication_reporter -backup_storage_implementation file -file_backup_storage_root /home/runner/work/vitess/vitess/vtdataroot/vt_805034223/vtroot_16001/backups -service_map grpc-queryservice,grpc-tabletmanager,grpc-updatestream,grpc-throttler -vtctld_addr http://localhost:16005 -vtctld_addr http://localhost:16005 -vreplication_tablet_type replica -restore_from_backup -enable_semi_sync -vreplication_healthcheck_topology_refresh 1s -vreplication_healthcheck_retry_delay 1s -vreplication_retry_delay 1s -degraded_threshold 5s -lock_tables_timeout 5s -watch_replication_stream -serving_state_grace_period 1s -db-credentials-file /home/runner/work/vitess/vitess/vtdataroot/vt_805034223/vtroot_16001/tmp_16003/db_credentials.json -backup_engine_implementation xtrabackup -xtrabackup_stream_mode=xbstream -xtrabackup_user=vt_dba -xtrabackup_backup_flags --***
I0614 14:33:23.524902   14191 vtctlclient_process.go:177] Executing vtctlclient with command: vtctlclient -server localhost:16006 InitShardMaster -force -wait_replicas_timeout 31s ks/0 zone1-2432
=== RUN   TestRecovery
I0614 14:33:23.705407   14191 vtctlclient_process.go:177] Executing vtctlclient with command: vtctlclient -server localhost:16006 Backup zone1-0000002433
E0614 14:33:25.539111   14191 vtctlclient_process.go:158] Output:
E0614 14:33:25.537726   17227 main.go:67] E0614 14:33:25.537448 backup.go:163] E0614 14:33:25.537318 backup.go:123] backup is not usable, aborting it: [exit status 1
xtrabackup failed with error. Output=]
Backup Error: rpc error: code = Unknown desc = TabletManager.Backup on zone1-0000002433 error: xtrabackup failed with error. Output=: exit status 1: xtrabackup failed with error. Output=: exit status 1
E0614 14:33:25.538497   17227 main.go:76] remote error: rpc error: code = Unknown desc = TabletManager.Backup on zone1-0000002433 error: xtrabackup failed with error. Output=: exit status 1: xtrabackup failed with error. Output=: exit status 1
    recovery.go:190: 
        	Error Trace:	recovery.go:190
        	Error:      	Received unexpected error:
        	            	exit status 1
        	Test:       	TestRecovery
I0614 14:33:25.539218   14191 vtctlclient_process.go:177] Executing vtctlclient with command: vtctlclient -server localhost:16006 ListBackups ks/0
    recovery.go:193: 
        	Error Trace:	recovery.go:193
        	Error:      	Not equal: 
        	            	expected: 0
        	            	actual  : 1
        	Test:       	TestRecovery
--- FAIL: TestRecovery (13.93s)
FAIL
FAIL	vitess.io/vitess/go/test/endtoend/recovery/xtrabackup	28.376s
FAIL
@ajm188
Copy link
Contributor Author

ajm188 commented Jun 14, 2021

Dupe of #8315 (sorry!)

@ajm188 ajm188 closed this as completed Jun 14, 2021
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
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
1 participant
@ajm188