search

canonical / mysql-k8s-operator

A Charmed Operator for running MySQL on Kubernetes
https://charmhub.io/mysql-k8s
Apache License 2.0
8 stars 15 forks source link

`ERROR: Cannot set replication user of channel 'group_replication_recovery' to 'mysql_innodb_cluster_530989616'.` #359

Open carlcsaposs-canonical opened 7 months ago

carlcsaposs-canonical commented 7 months ago

Steps to reproduce

Not sure how to reproduce consistently Occurred while testing 3 units of mysql-k8s with 3 units of mysql-router-k8s and 1 unit of mysql-test-app and deleting mysql-k8s pods repeatedly

Expected behavior

No error; server recovers

Actual behavior

ERROR: Cannot set replication user of channel 'group_replication_recovery' to 'mysql_innodb_cluster_530989616'.

Versions

Operating system: Ubuntu 22.04

Juju CLI: 3.1.7-genericlinux-amd64

Juju agent: 3.1.7

Charm revision: 113

microk8s: MicroK8s v1.28.3 revision 6091

Log output

Juju debug log: missing-from-cluster-set-debug-log.txt

unit-mysql-k8s-0: 11:09:13 ERROR unit.mysql-k8s/0.juju-log database-peers:0: Failed to add instance mysql-k8s-0.mysql-k8s-endpoints.foo6.svc.cluster.local to cluster cluster-265b6141cc9a90bb9af1eee2b4367b24 on mysql-k8s-0.mysql-k8s-endpoints.foo6.svc.cluster.local
Traceback (most recent call last):
  File "/var/lib/juju/agents/unit-mysql-k8s-0/charm/src/mysql_k8s_helpers.py", line 666, in _run_mysqlsh_script
    stdout, _ = process.wait_output()
  File "/var/lib/juju/agents/unit-mysql-k8s-0/charm/venv/ops/pebble.py", line 1441, in wait_output
    raise ExecError[AnyStr](self._command, exit_code, out_value, err_value)
ops.pebble.ExecError: non-zero exit code 1 executing ['/usr/bin/mysqlsh', '--no-wizard', '--python', '--verbose=1', '-f', '/tmp/script.py', ';', 'rm', '/tmp/script.py'], stdout='* Waiting for server restart... \\ \r* Waiting for server restart... | \r* Waiting for server restart... / \r* Waiting for server restart... - \r* Waiting for server restart... \\ \r* Waiting for server restart... | \r* Waiting for server restart... / \r* Waiting for server restart... - \r* Waiting for server restart... \\ \r* Waiting for server restart... | \r* Waiting for server restart... ready \n', stderr='Cannot set LC_ALL to locale en_US.UTF-8: No such file or directory\nverbose: 2024-01-18T11:08:23Z: Loading startup files...\nverbose: 2024-01-18T11:08:23Z: Loading plugins...\nverbose: 2024-01-18T11:08:23Z: Connecting to MySQL at: clusteradmin@mysql-k8s-2.mysql-k8s-endpoints.foo6.svc.cluster.local\nverbose: 2024-01-18T11:08:23Z: Shell.connect: tid=177: CONNECTED: mysql-k8s-2.mysql-k8s-endpoints.foo6.svc.cluster.local\nverbose: 2024-01-18T11:08:23Z: Connecting to MySQL at: mysql://clusteradmin@mysql-k8s-2.mysql-k8s-endpoints.foo6.svc.cluster.local:3306?connect-timeout=5000\nverbose: 2024-01-18T11:08:23Z: Dba.get_cluster: tid=178: CONNECTED: mysql-k8s-2.mysql-k8s-endpoints.foo6.svc.cluster.local:3306\nverbose: 2024-01-18T11:08:23Z: Connecting to MySQL at: mysql://clusteradmin@mysql-k8s-2.mysql-k8s-endpoints.foo6.svc.cluster.local:3306?connect-timeout=5000\nverbose: 2024-01-18T11:08:23Z: Dba.get_cluster: tid=179: CONNECTED: mysql-k8s-2.mysql-k8s-endpoints.foo6.svc.cluster.local:3306\nverbose: 2024-01-18T11:08:23Z: Group ' [truncated]

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/var/lib/juju/agents/unit-mysql-k8s-0/charm/lib/charms/mysql/v0/mysql.py", line 1326, in add_instance_to_cluster
    self._run_mysqlsh_script("\n".join(connect_commands + add_instance_command))
  File "/var/lib/juju/agents/unit-mysql-k8s-0/charm/src/mysql_k8s_helpers.py", line 669, in _run_mysqlsh_script
    raise MySQLClientError(e.stderr)
charms.mysql.v0.mysql.MySQLClientError: Cannot set LC_ALL to locale en_US.UTF-8: No such file or directory
verbose: 2024-01-18T11:08:23Z: Loading startup files...
verbose: 2024-01-18T11:08:23Z: Loading plugins...
verbose: 2024-01-18T11:08:23Z: Connecting to MySQL at: clusteradmin@mysql-k8s-2.mysql-k8s-endpoints.foo6.svc.cluster.local
verbose: 2024-01-18T11:08:23Z: Shell.connect: tid=177: CONNECTED: mysql-k8s-2.mysql-k8s-endpoints.foo6.svc.cluster.local
verbose: 2024-01-18T11:08:23Z: Connecting to MySQL at: mysql://clusteradmin@mysql-k8s-2.mysql-k8s-endpoints.foo6.svc.cluster.local:3306?connect-timeout=5000
verbose: 2024-01-18T11:08:23Z: Dba.get_cluster: tid=178: CONNECTED: mysql-k8s-2.mysql-k8s-endpoints.foo6.svc.cluster.local:3306
verbose: 2024-01-18T11:08:23Z: Connecting to MySQL at: mysql://clusteradmin@mysql-k8s-2.mysql-k8s-endpoints.foo6.svc.cluster.local:3306?connect-timeout=5000
verbose: 2024-01-18T11:08:23Z: Dba.get_cluster: tid=179: CONNECTED: mysql-k8s-2.mysql-k8s-endpoints.foo6.svc.cluster.local:3306
verbose: 2024-01-18T11:08:23Z: Group Replication 'group_name' value: d3a27e02-b5f1-11ee-be1f-0e739010502b
verbose: 2024-01-18T11:08:23Z: Metadata 'group_name' value: d3a27e02-b5f1-11ee-be1f-0e739010502b
verbose: 2024-01-18T11:08:23Z: Connecting to MySQL at: mysql://clusteradmin@mysql-k8s-2.mysql-k8s-endpoints.foo6.svc.cluster.local:3306?connect-timeout=5000
verbose: 2024-01-18T11:08:23Z: Dba.get_cluster: tid=180: CONNECTED: mysql-k8s-2.mysql-k8s-endpoints.foo6.svc.cluster.local:3306
verbose: 2024-01-18T11:08:23Z: Connecting to MySQL at: mysql://clusteradmin@mysql-k8s-2.mysql-k8s-endpoints.foo6.svc.cluster.local:3306?connect-timeout=5000
verbose: 2024-01-18T11:08:23Z: Dba.get_cluster: tid=181: CONNECTED: mysql-k8s-2.mysql-k8s-endpoints.foo6.svc.cluster.local:3306
verbose: 2024-01-18T11:08:23Z: Connecting to MySQL at: mysql://clusteradmin@mysql-k8s-2.mysql-k8s-endpoints.foo6.svc.cluster.local:3306?connect-timeout=5000
verbose: 2024-01-18T11:08:23Z: Cluster.add_instance: tid=182: CONNECTED: mysql-k8s-2.mysql-k8s-endpoints.foo6.svc.cluster.local:3306
verbose: 2024-01-18T11:08:23Z: Connecting to MySQL at: mysql://clusteradmin@mysql-k8s-2.mysql-k8s-endpoints.foo6.svc.cluster.local:3306?connect-timeout=5000
verbose: 2024-01-18T11:08:23Z: Cluster.add_instance: tid=183: CONNECTED: mysql-k8s-2.mysql-k8s-endpoints.foo6.svc.cluster.local:3306
verbose: 2024-01-18T11:08:23Z: Connecting to MySQL at: mysql://clusteradmin@mysql-k8s-2.mysql-k8s-endpoints.foo6.svc.cluster.local:3306?connect-timeout=5000
verbose: 2024-01-18T11:08:23Z: Cluster.add_instance: tid=184: CONNECTED: mysql-k8s-2.mysql-k8s-endpoints.foo6.svc.cluster.local:3306
verbose: 2024-01-18T11:08:23Z: Connecting to MySQL at: mysql://clusteradmin@mysql-k8s-2.mysql-k8s-endpoints.foo6.svc.cluster.local:3306?connect-timeout=5000
verbose: 2024-01-18T11:08:24Z: Cluster.add_instance: tid=185: CONNECTED: mysql-k8s-2.mysql-k8s-endpoints.foo6.svc.cluster.local:3306
verbose: 2024-01-18T11:08:24Z: Connecting to MySQL at: mysql://clusteradmin@mysql-k8s-2.mysql-k8s-endpoints.foo6.svc.cluster.local:3306?connect-timeout=5000
verbose: 2024-01-18T11:08:24Z: Cluster.add_instance: tid=187: CONNECTED: mysql-k8s-2.mysql-k8s-endpoints.foo6.svc.cluster.local:3306
verbose: 2024-01-18T11:08:24Z: Connecting to MySQL at: mysql://clusteradmin@mysql-k8s-2.mysql-k8s-endpoints.foo6.svc.cluster.local:3306?connect-timeout=5000
verbose: 2024-01-18T11:08:24Z: Cluster.add_instance: tid=188: CONNECTED: mysql-k8s-2.mysql-k8s-endpoints.foo6.svc.cluster.local:3306
verbose: 2024-01-18T11:08:24Z: Connecting to MySQL at: mysql://clusteradmin@mysql-k8s-0.mysql-k8s-endpoints.foo6.svc.cluster.local?connect-timeout=5000
verbose: 2024-01-18T11:08:24Z: Cluster.add_instance: tid=42: CONNECTED: mysql-k8s-0.mysql-k8s-endpoints.foo6.svc.cluster.local

NOTE: The target instance 'mysql-k8s-0.mysql-k8s-endpoints.foo6.svc.cluster.local:3306' has not been pre-provisioned (GTID set is empty). The Shell is unable to decide whether incremental state recovery can correctly provision it.

Clone based recovery selected through the recoveryMethod option

verbose: 2024-01-18T11:08:24Z: Connecting to MySQL at: mysql://clusteradmin@mysql-k8s-1.mysql-k8s-endpoints.foo6.svc.cluster.local:3306?connect-timeout=5000
verbose: 2024-01-18T11:08:24Z: Cluster.add_instance: tid=42: CONNECTED: mysql-k8s-1.mysql-k8s-endpoints.foo6.svc.cluster.local:3306
Validating instance configuration at mysql-k8s-0.mysql-k8s-endpoints.foo6.svc.cluster.local:3306...
verbose: 2024-01-18T11:08:24Z: Connecting to MySQL at: mysql://clusteradmin@mysql-k8s-0.mysql-k8s-endpoints.foo6.svc.cluster.local:3306?connect-timeout=5000
verbose: 2024-01-18T11:08:24Z: Cluster.add_instance: tid=43: CONNECTED: mysql-k8s-0.mysql-k8s-endpoints.foo6.svc.cluster.local:3306
verbose: 2024-01-18T11:08:24Z: Validating account clusteradmin@%...
verbose: 2024-01-18T11:08:24Z: clusteradmin user has 1 accounts with wildcard or netmask and 0 without

This instance reports its own address as mysql-k8s-0.mysql-k8s-endpoints.foo6.svc.cluster.local:3306
verbose: 2024-01-18T11:08:24Z: Validating InnoDB page size of instance 'mysql-k8s-0.mysql-k8s-endpoints.foo6.svc.cluster.local:3306'.
verbose: 2024-01-18T11:08:24Z: Checking if performance_schema is enabled on instance 'mysql-k8s-0.mysql-k8s-endpoints.foo6.svc.cluster.local:3306'.
verbose: 2024-01-18T11:08:24Z: Validating configuration of mysql-k8s-0.mysql-k8s-endpoints.foo6.svc.cluster.local:3306 (mycnf = )

Instance configuration is suitable.
verbose: 2024-01-18T11:08:24Z: Validating if 'lower_case_table_names' variable has the same value on target instance 'mysql-k8s-0.mysql-k8s-endpoints.foo6.svc.cluster.local:3306' as it does on the cluster.
verbose: 2024-01-18T11:08:24Z: Connecting to MySQL at: mysql://clusteradmin@mysql-k8s-1.mysql-k8s-endpoints.foo6.svc.cluster.local:3306?connect-timeout=5000
verbose: 2024-01-18T11:08:24Z: Cluster.add_instance: tid=43: CONNECTED: mysql-k8s-1.mysql-k8s-endpoints.foo6.svc.cluster.local:3306
verbose: 2024-01-18T11:08:24Z: Validating if 'default_table_encryption' variable has the same value on target instance 'mysql-k8s-0.mysql-k8s-endpoints.foo6.svc.cluster.local:3306' as it does on the cluster.
verbose: 2024-01-18T11:08:24Z: SSL mode used to configure the instance: 'REQUIRED'
verbose: 2024-01-18T11:08:24Z: Connecting to MySQL at: mysql://clusteradmin@mysql-k8s-2.mysql-k8s-endpoints.foo6.svc.cluster.local:3306?connect-timeout=5000
verbose: 2024-01-18T11:08:24Z: Cluster.add_instance: tid=190: CONNECTED: mysql-k8s-2.mysql-k8s-endpoints.foo6.svc.cluster.local:3306
verbose: 2024-01-18T11:08:24Z: Connecting to MySQL at: mysql://clusteradmin@mysql-k8s-1.mysql-k8s-endpoints.foo6.svc.cluster.local:3306?connect-timeout=5000
verbose: 2024-01-18T11:08:24Z: Cluster.add_instance: tid=44: CONNECTED: mysql-k8s-1.mysql-k8s-endpoints.foo6.svc.cluster.local:3306
NOTE: Group Replication will communicate with other members using 'mysql-k8s-0.mysql-k8s-endpoints.foo6.svc.cluster.local:3306'. Use the localAddress option to override.

verbose: 2024-01-18T11:08:24Z: Connecting to MySQL at: mysql://clusteradmin@mysql-k8s-1.mysql-k8s-endpoints.foo6.svc.cluster.local:3306?connect-timeout=5000
verbose: 2024-01-18T11:08:24Z: Cluster.add_instance: tid=45: CONNECTED: mysql-k8s-1.mysql-k8s-endpoints.foo6.svc.cluster.local:3306
* Checking connectivity and SSL configuration...
verbose: 2024-01-18T11:08:24Z: Checking connection from mysql-k8s-0.mysql-k8s-endpoints.foo6.svc.cluster.local:3306 to mysqlsh-lo.test@mysql-k8s-0.mysql-k8s-endpoints.foo6.svc.cluster.local:3306 (localAddress) ssl_mode=REQUIRED auth_type=PASSWORD cert_issuer= cert_subject=
verbose: 2024-01-18T11:08:24Z: Setting up async source for channel 'mysqlsh.test' of mysql-k8s-0.mysql-k8s-endpoints.foo6.svc.cluster.local:3306 to mysql-k8s-0.mysql-k8s-endpoints.foo6.svc.cluster.local:3306 (user 'mysqlsh-lo.test')
verbose: 2024-01-18T11:08:24Z: Connection check mysql-k8s-0.mysql-k8s-endpoints.foo6.svc.cluster.local:3306 -> mysql-k8s-0.mysql-k8s-endpoints.foo6.svc.cluster.local:3306 io_state=OFF io_error=Fatal error: The replica I/O thread stops because source and replica have equal MySQL server ids; these ids must be different for replication to work (or the --replicate-same-server-id option must be used on replica but this does not always make sense; please check the manual before using it). (13117) at 2024-01-18 11:08:24.364453
verbose: 2024-01-18T11:08:24Z: Checking connection from mysql-k8s-0.mysql-k8s-endpoints.foo6.svc.cluster.local:3306 to mysqlsh.test@mysql-k8s-2.mysql-k8s-endpoints.foo6.svc.cluster.local:3306 (report_host) ssl_mode=REQUIRED auth_type=PASSWORD cert_issuer= cert_subject=
verbose: 2024-01-18T11:08:24Z: Setting up async source for channel 'mysqlsh.test' of mysql-k8s-0.mysql-k8s-endpoints.foo6.svc.cluster.local:3306 to mysql-k8s-2.mysql-k8s-endpoints.foo6.svc.cluster.local:3306 (user 'mysqlsh.test')
verbose: 2024-01-18T11:08:24Z: Connection check mysql-k8s-0.mysql-k8s-endpoints.foo6.svc.cluster.local:3306 -> mysql-k8s-2.mysql-k8s-endpoints.foo6.svc.cluster.local:3306 io_state=OFF io_error=Source command COM_REGISTER_REPLICA failed: Access denied for user 'mysqlsh.test'@'%' (using password: YES) (Errno: 1045) (13120) at 2024-01-18 11:08:24.622708
verbose: 2024-01-18T11:08:24Z: Checking connection from mysql-k8s-2.mysql-k8s-endpoints.foo6.svc.cluster.local:3306 to mysqlsh.test@mysql-k8s-0.mysql-k8s-endpoints.foo6.svc.cluster.local:3306 (report_host) ssl_mode=REQUIRED auth_type=PASSWORD cert_issuer= cert_subject=
verbose: 2024-01-18T11:08:24Z: Setting up async source for channel 'mysqlsh.test' of mysql-k8s-2.mysql-k8s-endpoints.foo6.svc.cluster.local:3306 to mysql-k8s-0.mysql-k8s-endpoints.foo6.svc.cluster.local:3306 (user 'mysqlsh.test')
verbose: 2024-01-18T11:08:25Z: Connection check mysql-k8s-2.mysql-k8s-endpoints.foo6.svc.cluster.local:3306 -> mysql-k8s-0.mysql-k8s-endpoints.foo6.svc.cluster.local:3306 io_state=OFF io_error=Source command COM_REGISTER_REPLICA failed: Access denied for user 'mysqlsh.test'@'%' (using password: YES) (Errno: 1045) (13120) at 2024-01-18 11:08:24.879617
A new instance will be added to the InnoDB Cluster. Depending on the amount of
data on the cluster this might take from a few seconds to several hours.

verbose: 2024-01-18T11:08:25Z: Using Group Replication local address: mysql-k8s-0.mysql-k8s-endpoints.foo6.svc.cluster.local:3306
verbose: 2024-01-18T11:08:25Z: Using Group Replication group seeds: mysql-k8s-1.mysql-k8s-endpoints.foo6.svc.cluster.local:3306,mysql-k8s-2.mysql-k8s-endpoints.foo6.svc.cluster.local:3306
verbose: 2024-01-18T11:08:25Z: Using Group Replication failover consistency: EVENTUAL
verbose: 2024-01-18T11:08:25Z: Using Group Replication expel timeout: 5
Adding instance to the cluster...

verbose: 2024-01-18T11:08:25Z: Validating if 'group_replication_gtid_assignment_block_size' variable has the same value on target instance 'mysql-k8s-0.mysql-k8s-endpoints.foo6.svc.cluster.local:3306' as it does on the cluster.
verbose: 2024-01-18T11:08:25Z: Installing the clone plugin on instance 'mysql-k8s-0.mysql-k8s-endpoints.foo6.svc.cluster.local:3306'.
verbose: 2024-01-18T11:08:25Z: Connecting to MySQL at: mysql://clusteradmin@mysql-k8s-2.mysql-k8s-endpoints.foo6.svc.cluster.local:3306?connect-timeout=5000
verbose: 2024-01-18T11:08:25Z: Cluster.add_instance: tid=201: CONNECTED: mysql-k8s-2.mysql-k8s-endpoints.foo6.svc.cluster.local:3306
verbose: 2024-01-18T11:08:25Z: Installing the clone plugin on instance 'mysql-k8s-2.mysql-k8s-endpoints.foo6.svc.cluster.local:3306'.
verbose: 2024-01-18T11:08:25Z: Connecting to MySQL at: mysql://clusteradmin@mysql-k8s-1.mysql-k8s-endpoints.foo6.svc.cluster.local:3306?connect-timeout=5000
verbose: 2024-01-18T11:08:25Z: Cluster.add_instance: tid=46: CONNECTED: mysql-k8s-1.mysql-k8s-endpoints.foo6.svc.cluster.local:3306
verbose: 2024-01-18T11:08:25Z: Installing the clone plugin on instance 'mysql-k8s-1.mysql-k8s-endpoints.foo6.svc.cluster.local:3306'.
verbose: 2024-01-18T11:08:25Z: Creating recovery account 'mysql_innodb_cluster_530989616'@'%' for instance 'mysql-k8s-0.mysql-k8s-endpoints.foo6.svc.cluster.local:3306'
verbose: 2024-01-18T11:08:25Z: Connecting to MySQL at: mysql://clusteradmin@mysql-k8s-1.mysql-k8s-endpoints.foo6.svc.cluster.local:3306?connect-timeout=5000
verbose: 2024-01-18T11:08:25Z: Cluster.add_instance: tid=48: CONNECTED: mysql-k8s-1.mysql-k8s-endpoints.foo6.svc.cluster.local:3306
verbose: 2024-01-18T11:08:25Z: Joining 'mysql-k8s-0.mysql-k8s-endpoints.foo6.svc.cluster.local:3306' to cluster using account 'clusteradmin' to peer 'mysql-k8s-2.mysql-k8s-endpoints.foo6.svc.cluster.local:3306'.
verbose: 2024-01-18T11:08:25Z: Creating recovery account 'mysql_innodb_cluster_530989616'@'%' for instance 'mysql-k8s-0.mysql-k8s-endpoints.foo6.svc.cluster.local:3306'
verbose: 2024-01-18T11:08:25Z: Connecting to MySQL at: mysql://clusteradmin@mysql-k8s-1.mysql-k8s-endpoints.foo6.svc.cluster.local:3306?connect-timeout=5000
verbose: 2024-01-18T11:08:25Z: Cluster.add_instance: tid=49: CONNECTED: mysql-k8s-1.mysql-k8s-endpoints.foo6.svc.cluster.local:3306
verbose: 2024-01-18T11:08:25Z: Connecting to MySQL at: mysql://clusteradmin@mysql-k8s-2.mysql-k8s-endpoints.foo6.svc.cluster.local:3306?connect-timeout=5000
verbose: 2024-01-18T11:08:25Z: Cluster.add_instance: tid=207: CONNECTED: mysql-k8s-2.mysql-k8s-endpoints.foo6.svc.cluster.local:3306
verbose: 2024-01-18T11:08:25Z: Connecting to MySQL at: mysql://clusteradmin@mysql-k8s-1.mysql-k8s-endpoints.foo6.svc.cluster.local:3306?connect-timeout=5000
verbose: 2024-01-18T11:08:25Z: Cluster.add_instance: tid=50: CONNECTED: mysql-k8s-1.mysql-k8s-endpoints.foo6.svc.cluster.local:3306
Monitoring recovery process of the new cluster member. Press ^C to stop monitoring and let it continue in background.
verbose: 2024-01-18T11:08:27Z: Waiting for GR recovery to start for mysql-k8s-0.mysql-k8s-endpoints.foo6.svc.cluster.local:3306...
verbose: 2024-01-18T11:08:27Z: Connecting to MySQL at: mysql://clusteradmin@mysql-k8s-0.mysql-k8s-endpoints.foo6.svc.cluster.local:3306?connect-timeout=5000
verbose: 2024-01-18T11:08:27Z: Cluster.add_instance: tid=69: CONNECTED: mysql-k8s-0.mysql-k8s-endpoints.foo6.svc.cluster.local:3306
verbose: 2024-01-18T11:08:27Z: mysql-k8s-0.mysql-k8s-endpoints.foo6.svc.cluster.local:3306 has started
verbose: 2024-01-18T11:08:27Z: Connecting to MySQL at: mysql://clusteradmin@mysql-k8s-0.mysql-k8s-endpoints.foo6.svc.cluster.local:3306?connect-timeout=5000
verbose: 2024-01-18T11:08:27Z: Cluster.add_instance: tid=72: CONNECTED: mysql-k8s-0.mysql-k8s-endpoints.foo6.svc.cluster.local:3306
Clone based state recovery is now in progress.

NOTE: A server restart is expected to happen as part of the clone process. If the
server does not support the RESTART command or does not come back after a
while, you may need to manually start it back.

* Waiting for clone to finish...
NOTE: mysql-k8s-0.mysql-k8s-endpoints.foo6.svc.cluster.local:3306 is being cloned from mysql-k8s-1.mysql-k8s-endpoints.foo6.svc.cluster.local:3306
** Stage DROP DATA: Completed
** Stage FILE COPY: Completed
** Stage PAGE COPY: Completed
** Stage REDO COPY: Completed
verbose: 2024-01-18T11:08:31Z: Cluster.add_instance: tid=72: MySQL Error 1053 (08S01): Server shutdown in progress, SQL: SELECT *, end_time-begin_time as elapsed FROM performance_schema.clone_status WHERE begin_time >= '2024-01-18 11:08:25.197' ORDER BY id DESC LIMIT 1

NOTE: mysql-k8s-0.mysql-k8s-endpoints.foo6.svc.cluster.local:3306 is shutting down...

verbose: 2024-01-18T11:08:31Z: Connecting to MySQL at: mysql://clusteradmin@mysql-k8s-0.mysql-k8s-endpoints.foo6.svc.cluster.local:3306?connect-timeout=5000
verbose: 2024-01-18T11:08:32Z: Connecting to MySQL at: mysql://clusteradmin@mysql-k8s-0.mysql-k8s-endpoints.foo6.svc.cluster.local:3306?connect-timeout=5000
verbose: 2024-01-18T11:08:33Z: Connecting to MySQL at: mysql://clusteradmin@mysql-k8s-0.mysql-k8s-endpoints.foo6.svc.cluster.local:3306?connect-timeout=5000
verbose: 2024-01-18T11:08:34Z: Connecting to MySQL at: mysql://clusteradmin@mysql-k8s-0.mysql-k8s-endpoints.foo6.svc.cluster.local:3306?connect-timeout=5000
verbose: 2024-01-18T11:08:35Z: Connecting to MySQL at: mysql://clusteradmin@mysql-k8s-0.mysql-k8s-endpoints.foo6.svc.cluster.local:3306?connect-timeout=5000
verbose: 2024-01-18T11:08:36Z: Connecting to MySQL at: mysql://clusteradmin@mysql-k8s-0.mysql-k8s-endpoints.foo6.svc.cluster.local:3306?connect-timeout=5000
verbose: 2024-01-18T11:08:37Z: Connecting to MySQL at: mysql://clusteradmin@mysql-k8s-0.mysql-k8s-endpoints.foo6.svc.cluster.local:3306?connect-timeout=5000
verbose: 2024-01-18T11:08:38Z: Connecting to MySQL at: mysql://clusteradmin@mysql-k8s-0.mysql-k8s-endpoints.foo6.svc.cluster.local:3306?connect-timeout=5000
verbose: 2024-01-18T11:08:39Z: Connecting to MySQL at: mysql://clusteradmin@mysql-k8s-0.mysql-k8s-endpoints.foo6.svc.cluster.local:3306?connect-timeout=5000
verbose: 2024-01-18T11:08:40Z: Connecting to MySQL at: mysql://clusteradmin@mysql-k8s-0.mysql-k8s-endpoints.foo6.svc.cluster.local:3306?connect-timeout=5000
verbose: 2024-01-18T11:08:41Z: Connecting to MySQL at: mysql://clusteradmin@mysql-k8s-0.mysql-k8s-endpoints.foo6.svc.cluster.local:3306?connect-timeout=5000
verbose: 2024-01-18T11:08:41Z: Cluster.add_instance: tid=24: CONNECTED: mysql-k8s-0.mysql-k8s-endpoints.foo6.svc.cluster.local:3306
verbose: 2024-01-18T11:08:41Z: mysql-k8s-0.mysql-k8s-endpoints.foo6.svc.cluster.local:3306 has started
* mysql-k8s-0.mysql-k8s-endpoints.foo6.svc.cluster.local:3306 has restarted, waiting for clone to finish...
** Stage FILE SYNC: Completed
** Stage RESTART: Completed
* Clone process has finished: 74.34 MB transferred in about 1 second (~74.34 MB/s)

verbose: 2024-01-18T11:08:41Z: Member mysql-k8s-0.mysql-k8s-endpoints.foo6.svc.cluster.local:3306 is in state OFFLINE, when recovery was expected (clone_state=Completed@2024-01-18 11:08:27.184).
verbose: 2024-01-18T11:08:42Z: Member mysql-k8s-0.mysql-k8s-endpoints.foo6.svc.cluster.local:3306 is in state OFFLINE, when recovery was expected (clone_state=Completed@2024-01-18 11:08:27.184).
verbose: 2024-01-18T11:08:43Z: Member mysql-k8s-0.mysql-k8s-endpoints.foo6.svc.cluster.local:3306 is in state OFFLINE, when recovery was expected (clone_state=Completed@2024-01-18 11:08:27.184).
verbose: 2024-01-18T11:08:44Z: Member mysql-k8s-0.mysql-k8s-endpoints.foo6.svc.cluster.local:3306 is in state OFFLINE, when recovery was expected (clone_state=Completed@2024-01-18 11:08:27.184).
verbose: 2024-01-18T11:08:45Z: Member mysql-k8s-0.mysql-k8s-endpoints.foo6.svc.cluster.local:3306 is in state OFFLINE, when recovery was expected (clone_state=Completed@2024-01-18 11:08:27.184).
verbose: 2024-01-18T11:08:46Z: Member mysql-k8s-0.mysql-k8s-endpoints.foo6.svc.cluster.local:3306 is in state OFFLINE, when recovery was expected (clone_state=Completed@2024-01-18 11:08:27.184).
verbose: 2024-01-18T11:08:47Z: Member mysql-k8s-0.mysql-k8s-endpoints.foo6.svc.cluster.local:3306 is in state OFFLINE, when recovery was expected (clone_state=Completed@2024-01-18 11:08:27.184).
verbose: 2024-01-18T11:08:48Z: Member mysql-k8s-0.mysql-k8s-endpoints.foo6.svc.cluster.local:3306 is in state OFFLINE, when recovery was expected (clone_state=Completed@2024-01-18 11:08:27.184).
verbose: 2024-01-18T11:08:49Z: Member mysql-k8s-0.mysql-k8s-endpoints.foo6.svc.cluster.local:3306 is in state OFFLINE, when recovery was expected (clone_state=Completed@2024-01-18 11:08:27.184).
verbose: 2024-01-18T11:08:50Z: Member mysql-k8s-0.mysql-k8s-endpoints.foo6.svc.cluster.local:3306 is in state OFFLINE, when recovery was expected (clone_state=Completed@2024-01-18 11:08:27.184).
verbose: 2024-01-18T11:08:51Z: Member mysql-k8s-0.mysql-k8s-endpoints.foo6.svc.cluster.local:3306 is in state OFFLINE, when recovery was expected (clone_state=Completed@2024-01-18 11:08:27.184).
verbose: 2024-01-18T11:08:52Z: Member mysql-k8s-0.mysql-k8s-endpoints.foo6.svc.cluster.local:3306 is in state OFFLINE, when recovery was expected (clone_state=Completed@2024-01-18 11:08:27.184).
verbose: 2024-01-18T11:08:53Z: Member mysql-k8s-0.mysql-k8s-endpoints.foo6.svc.cluster.local:3306 is in state OFFLINE, when recovery was expected (clone_state=Completed@2024-01-18 11:08:27.184).
verbose: 2024-01-18T11:08:54Z: Member mysql-k8s-0.mysql-k8s-endpoints.foo6.svc.cluster.local:3306 is in state OFFLINE, when recovery was expected (clone_state=Completed@2024-01-18 11:08:27.184).
verbose: 2024-01-18T11:08:55Z: Member mysql-k8s-0.mysql-k8s-endpoints.foo6.svc.cluster.local:3306 is in state OFFLINE, when recovery was expected (clone_state=Completed@2024-01-18 11:08:27.184).
verbose: 2024-01-18T11:08:56Z: Member mysql-k8s-0.mysql-k8s-endpoints.foo6.svc.cluster.local:3306 is in state OFFLINE, when recovery was expected (clone_state=Completed@2024-01-18 11:08:27.184).
verbose: 2024-01-18T11:08:57Z: Member mysql-k8s-0.mysql-k8s-endpoints.foo6.svc.cluster.local:3306 is in state OFFLINE, when recovery was expected (clone_state=Completed@2024-01-18 11:08:27.184).
verbose: 2024-01-18T11:08:58Z: Member mysql-k8s-0.mysql-k8s-endpoints.foo6.svc.cluster.local:3306 is in state OFFLINE, when recovery was expected (clone_state=Completed@2024-01-18 11:08:27.184).
verbose: 2024-01-18T11:08:59Z: Member mysql-k8s-0.mysql-k8s-endpoints.foo6.svc.cluster.local:3306 is in state OFFLINE, when recovery was expected (clone_state=Completed@2024-01-18 11:08:27.184).
verbose: 2024-01-18T11:09:00Z: Member mysql-k8s-0.mysql-k8s-endpoints.foo6.svc.cluster.local:3306 is in state OFFLINE, when recovery was expected (clone_state=Completed@2024-01-18 11:08:27.184).
verbose: 2024-01-18T11:09:01Z: Member mysql-k8s-0.mysql-k8s-endpoints.foo6.svc.cluster.local:3306 is in state OFFLINE, when recovery was expected (clone_state=Completed@2024-01-18 11:08:27.184).
verbose: 2024-01-18T11:09:02Z: Member mysql-k8s-0.mysql-k8s-endpoints.foo6.svc.cluster.local:3306 is in state OFFLINE, when recovery was expected (clone_state=Completed@2024-01-18 11:08:27.184).
verbose: 2024-01-18T11:09:03Z: Member mysql-k8s-0.mysql-k8s-endpoints.foo6.svc.cluster.local:3306 is in state OFFLINE, when recovery was expected (clone_state=Completed@2024-01-18 11:08:27.184).
verbose: 2024-01-18T11:09:04Z: Member mysql-k8s-0.mysql-k8s-endpoints.foo6.svc.cluster.local:3306 is in state OFFLINE, when recovery was expected (clone_state=Completed@2024-01-18 11:08:27.184).
verbose: 2024-01-18T11:09:05Z: Member mysql-k8s-0.mysql-k8s-endpoints.foo6.svc.cluster.local:3306 is in state OFFLINE, when recovery was expected (clone_state=Completed@2024-01-18 11:08:27.184).
verbose: 2024-01-18T11:09:06Z: Member mysql-k8s-0.mysql-k8s-endpoints.foo6.svc.cluster.local:3306 is in state OFFLINE, when recovery was expected (clone_state=Completed@2024-01-18 11:08:27.184).
verbose: 2024-01-18T11:09:07Z: Member mysql-k8s-0.mysql-k8s-endpoints.foo6.svc.cluster.local:3306 is in state OFFLINE, when recovery was expected (clone_state=Completed@2024-01-18 11:08:27.184).
verbose: 2024-01-18T11:09:08Z: Member mysql-k8s-0.mysql-k8s-endpoints.foo6.svc.cluster.local:3306 is in state OFFLINE, when recovery was expected (clone_state=Completed@2024-01-18 11:08:27.184).
verbose: 2024-01-18T11:09:09Z: Member mysql-k8s-0.mysql-k8s-endpoints.foo6.svc.cluster.local:3306 is in state OFFLINE, when recovery was expected (clone_state=Completed@2024-01-18 11:08:27.184).
verbose: 2024-01-18T11:09:10Z: Member mysql-k8s-0.mysql-k8s-endpoints.foo6.svc.cluster.local:3306 is in state OFFLINE, when recovery was expected (clone_state=Completed@2024-01-18 11:08:27.184).
verbose: 2024-01-18T11:09:11Z: Cluster.add_instance: tid=42: MySQL Error 2013 (HY000): Lost connection to MySQL server during query, SQL: SELECT 1
verbose: 2024-01-18T11:09:11Z: Target connection to mysql-k8s-0.mysql-k8s-endpoints.foo6.svc.cluster.local:3306 lost: MySQL Error 2013 (HY000): Lost connection to MySQL server during query. Reconnecting...
verbose: 2024-01-18T11:09:11Z: Cluster.add_instance: tid=25: CONNECTED: mysql-k8s-0.mysql-k8s-endpoints.foo6.svc.cluster.local:3306
verbose: 2024-01-18T11:09:13Z: Connecting to MySQL at: mysql://clusteradmin@mysql-k8s-2.mysql-k8s-endpoints.foo6.svc.cluster.local:3306?connect-timeout=5000
verbose: 2024-01-18T11:09:13Z: Cluster.add_instance: tid=271: CONNECTED: mysql-k8s-2.mysql-k8s-endpoints.foo6.svc.cluster.local:3306
verbose: 2024-01-18T11:09:13Z: Connecting to MySQL at: mysql://clusteradmin@mysql-k8s-1.mysql-k8s-endpoints.foo6.svc.cluster.local:3306?connect-timeout=5000
verbose: 2024-01-18T11:09:13Z: Cluster.add_instance: tid=83: CONNECTED: mysql-k8s-1.mysql-k8s-endpoints.foo6.svc.cluster.local:3306
verbose: 2024-01-18T11:09:13Z: Cluster.add_instance: tid=25: MySQL Error 3021 (HY000): This operation cannot be performed with a running replica io thread; run STOP REPLICA IO_THREAD FOR CHANNEL 'group_replication_recovery' first., SQL: CHANGE REPLICATION SOURCE TO SOURCE_USER = /*(*/ 'mysql_innodb_cluster_530989616' /*)*/, SOURCE_PASSWORD = **** FOR CHANNEL 'group_replication_recovery'
verbose: 2024-01-18T11:09:13Z: Connecting to MySQL at: mysql://clusteradmin@mysql-k8s-2.mysql-k8s-endpoints.foo6.svc.cluster.local:3306?connect-timeout=5000
verbose: 2024-01-18T11:09:13Z: Cluster.add_instance: tid=276: CONNECTED: mysql-k8s-2.mysql-k8s-endpoints.foo6.svc.cluster.local:3306
verbose: 2024-01-18T11:09:13Z: Resetting recovery account credentials for 'mysql-k8s-2.mysql-k8s-endpoints.foo6.svc.cluster.local:3306' (with password).
verbose: 2024-01-18T11:09:13Z: Connecting to MySQL at: mysql://clusteradmin@mysql-k8s-1.mysql-k8s-endpoints.foo6.svc.cluster.local:3306?connect-timeout=5000
verbose: 2024-01-18T11:09:13Z: Cluster.add_instance: tid=84: CONNECTED: mysql-k8s-1.mysql-k8s-endpoints.foo6.svc.cluster.local:3306
verbose: 2024-01-18T11:09:13Z: Resetting recovery account credentials for 'mysql-k8s-1.mysql-k8s-endpoints.foo6.svc.cluster.local:3306' (with password).
ERROR: Cannot set replication user of channel 'group_replication_recovery' to 'mysql_innodb_cluster_530989616'. Error executing CHANGE SOURCE statement: mysql-k8s-0.mysql-k8s-endpoints.foo6.svc.cluster.local:3306: This operation cannot be performed with a running replica io thread; run STOP REPLICA IO_THREAD FOR CHANNEL 'group_replication_recovery' first.
Traceback (most recent call last):
  File "<string>", line 4, in <module>
RuntimeError: Cluster.add_instance: Cannot set replication user of channel 'group_replication_recovery' to 'mysql_innodb_cluster_530989616'. Error executing CHANGE SOURCE statement: mysql-k8s-0.mysql-k8s-endpoints.foo6.svc.cluster.local:3306: This operation cannot be performed with a running replica io thread; run STOP REPLICA IO_THREAD FOR CHANNEL 'group_replication_recovery' first.

unit-mysql-k8s-0: 11:09:13 DEBUG unit.mysql-k8s/0.juju-log database-peers:0: Releasing lock unit-add on mysql-k8s-2.mysql-k8s-endpoints.foo6.svc.cluster.local for unit mysql-k8s-0

Additional context

github-actions[bot] commented 7 months ago

https://warthogs.atlassian.net/browse/DPE-3335