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

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

Open
carlcsaposs-canonical opened this issue Jan 19, 2024 · 1 comment
Open

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

carlcsaposs-canonical opened this issue Jan 19, 2024 · 1 comment
Labels
bug Something isn't working

Comments

@carlcsaposs-canonical
Copy link
Contributor

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
@carlcsaposs-canonical carlcsaposs-canonical added the bug Something isn't working label Jan 19, 2024
@github-actions GitHub Actions
Copy link
Contributor

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

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
bug Something isn't working
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
1 participant
@carlcsaposs-canonical