search

jnidzwetzki / mysql-ha-cloud

This container image provides a highly available and replicated MySQL installation in Kubernetes or Docker Swarm. Consul, ProxySQL, and XtraBackup are used for leader election, load distribution, and backups.
Apache License 2.0
38 stars 16 forks source link

rpc error making call: invalid session #2

Closed 2peter3 closed 3 years ago

2peter3 commented 3 years ago

Hi, after restart the docker swarm, im getting an error message. Could you give me a hint, how to fix this

 Renaming database file /var/lib/proxysql/proxysql.db
 2021-03-21 04:04:36 [INFO] Using OpenSSL version: OpenSSL 1.1.1d  10 Sep 2019
 2021-03-21 04:04:36 [INFO] No SSL keys/certificates found in datadir (/var/lib/proxysql). Generating new keys/certificates.
 2021-03-21 04:04:37,010 INFO root Starting MySQL
 Logging to '/var/lib/mysql/ce864ecd723d.err'.
 2021-03-21T04:04:37.194010Z mysqld_safe Starting mysqld daemon with databases from /var/lib/mysql
 2021-03-21 04:04:39,053 INFO root Performing initial ProxySQL setup
     2021-03-21T04:04:39.419Z [ERROR] agent.client: RPC failed to server: method=KVS.Apply server=10.0.8.10:8300 error="rpc error making call: rpc error making call: invalid session "5125b25b-7477-ba31-0885-b227fcad7698""
     2021-03-21T04:04:39.420Z [ERROR] agent.http: Request error: method=PUT url=/v1/kv/mcm/instances/10.0.8.159?acquire=5125b25b-7477-ba31-0885-b227fcad7698 from=127.0.0.1:55222 error="rpc error making call: rpc error making call: invalid session "5125b25b-7477-ba31-0885-b227fcad7698""
 Traceback (most recent call last):
   File "./mysql_cluster_manager.py", line 46, in <module>
     Actions.join_or_bootstrap()
   File "/cluster/mcm/actions.py", line 86, in join_or_bootstrap
     server_id=server_id)
   File "/cluster/mcm/consul.py", line 250, in register_node
     put_result = self.client.kv.put(path, json_string, acquire=self.node_health_session)
   File "/usr/local/lib/python3.7/dist-packages/consul/base.py", line 3069, in put
     params=params, headers=headers, data=value)
   File "/usr/local/lib/python3.7/dist-packages/consul/std.py", line 39, in put
     timeout=self.timeout)))
   File "/usr/local/lib/python3.7/dist-packages/consul/base.py", line 249, in cb
     CB._status(response, allow_404=allow_404)
   File "/usr/local/lib/python3.7/dist-packages/consul/base.py", line 212, in _status
     raise ConsulException("%d %s" % (response.code, response.body))
 consul.base.ConsulException: 500 rpc error making call: rpc error making call: invalid session "5125b25b-7477-ba31-0885-b227fcad7698"

Thanks

jnidzwetzki commented 3 years ago

Hi @2peter3 ,

Thanks for the bug report. It seems that the Consul cluster is not ready. Can you give me some hints how to reproduce this problem?

Best Regards Jan

2peter3 commented 3 years ago

HI @jnidzwetzki , Thanks for the fast response.

I have a cluster consisting of a master, two database servers and 4 workers. In my Docker volume "backup-volume" i have a backup of the last status of the MySQL cluster.

root@m:/data/minio/mysqlbackup# ls -ltr
insgesamt 2340612
-rw-r--r-- 1 root root 345965003 Mär 21 03:46 mysql_backup_1616294704.9394488.tgz

I have tried to get the Consul and MySQL running only on the Database Nodes, Minio should be running on the Master Node.

version: "3.8"

networks:
  backend:

volumes:
  backup-volume:

services:
  consul:
    image: consul:1.9
    networks:
       backend:
          aliases:
             - consul_cluster
    environment:
      - CONSUL_BIND_INTERFACE=eth0
    command: agent -ui -data-dir /consul/data -server -client 0.0.0.0 -retry-join consul_cluster -bootstrap-expect=5
    deploy:
      replicas: 5
      endpoint_mode: dnsrr
      placement:
        max_replicas_per_node: 3
        constraints:
          - node.role!=manager
          - node.labels.type==db
      update_config:
        parallelism: 1
        delay: 60s
      restart_policy:
        condition: on-failure

  mysql:
    image: jnidzwetzki/mysql-ha-cloud:latest
    networks:
       backend:
    environment:
      - CONSUL_BIND_INTERFACE=eth1
      - CONSUL_BOOTSTRAP_SERVER=consul_cluster
      - MINIO_ACCESS_KEY=minio
      - MINIO_SECRET_KEY=minio123
      - MINIO_URL=http://minio:9000
      - MCM_BIND_INTERFACE=eth1
      - MYSQL_ROOT_PASSWORD=verysecret123
      - MYSQL_BACKUP_USER=backup_user
      - MYSQL_BACKUP_PASSWORD=backup_secret
      - MYSQL_REPLICATION_USER=replication_user
      - MYSQL_REPLICATION_PASSWORD=replication_secret
      - MYSQL_APPLICATION_USER=mysql_user
      - MYSQL_APPLICATION_PASSWORD=mysql_secret
    deploy:
      replicas: 5
      placement:
        max_replicas_per_node: 3
        constraints:
          - node.role!=manager
          - node.labels.type==db
      update_config:
        parallelism: 1
        delay: 60s
      restart_policy:
        condition: on-failure
    ports:
      - 6032:6032
      - 3306:6033

  minio:
    image: minio/minio:RELEASE.2020-10-18T21-54-12Z
    networks:
       backend:
          aliases:
             - minio_endpoint
    volumes:
       - backup-volume:/data
    ports:
       - 9000:9000
    deploy:
      placement:
        constraints:
          - node.role==manager
          - node.labels.type==chef
    environment:
       - MINIO_ACCESS_KEY=minio
       - MINIO_SECRET_KEY=minio123
    command: server /data

In Consul im getting errors like:

 ==> Found address '10.0.24.9' for interface 'eth0', setting bind option...
 ==> Starting Consul agent...
            Version: '1.9.4'
            Node ID: 'cf6dc633-4392-2952-faf5-6cef226d374a'
          Node name: '99b7d8294177'
         Datacenter: 'dc1' (Segment: '<all>')
             Server: true (Bootstrap: false)
        Client Addr: [0.0.0.0] (HTTP: 8500, HTTPS: -1, gRPC: -1, DNS: 8600)
       Cluster Addr: 10.0.24.9 (LAN: 8301, WAN: 8302)
            Encrypt: Gossip: false, TLS-Outgoing: false, TLS-Incoming: false, Auto-Encrypt-TLS: false

 ==> Log data will now stream in as it occurs:

     2021-03-21T12:44:27.472Z [WARN]  agent: bootstrap_expect > 0: expecting 5 servers
     2021-03-21T12:44:27.481Z [WARN]  agent.auto_config: bootstrap_expect > 0: expecting 5 servers
     2021-03-21T12:44:27.489Z [INFO]  agent.server.raft: initial configuration: index=0 servers=[]
     2021-03-21T12:44:27.490Z [INFO]  agent.server.raft: entering follower state: follower="Node at 10.0.24.9:8300 [Follower]" leader=
     2021-03-21T12:44:27.491Z [INFO]  agent.server.serf.wan: serf: EventMemberJoin: 99b7d8294177.dc1 10.0.24.9
     2021-03-21T12:44:27.492Z [INFO]  agent.server.serf.lan: serf: EventMemberJoin: 99b7d8294177 10.0.24.9
     2021-03-21T12:44:27.492Z [INFO]  agent.router: Initializing LAN area manager
     2021-03-21T12:44:27.492Z [INFO]  agent.server: Adding LAN server: server="99b7d8294177 (Addr: tcp/10.0.24.9:8300) (DC: dc1)"
     2021-03-21T12:44:27.492Z [INFO]  agent.server: Handled event for server in area: event=member-join server=99b7d8294177.dc1 area=wan
     2021-03-21T12:44:27.492Z [INFO]  agent: Started DNS server: address=0.0.0.0:8600 network=tcp
     2021-03-21T12:44:27.493Z [INFO]  agent: Started DNS server: address=0.0.0.0:8600 network=udp
     2021-03-21T12:44:27.494Z [INFO]  agent: Starting server: address=[::]:8500 network=tcp protocol=http
     2021-03-21T12:44:27.494Z [WARN]  agent: DEPRECATED Backwards compatibility with pre-1.9 metrics enabled. These metrics will be removed in a future version of Consul. Set `telemetry { disable_compat_1.9 = true }` to disable them.
     2021-03-21T12:44:27.494Z [INFO]  agent: Retry join is supported for the following discovery methods: cluster=LAN discovery_methods="aliyun aws azure digitalocean gce k8s linode mdns os packet scaleway softlayer tencentcloud triton vsphere"
     2021-03-21T12:44:27.494Z [INFO]  agent: Joining cluster...: cluster=LAN
     2021-03-21T12:44:27.494Z [INFO]  agent: (LAN) joining: lan_addresses=[consul_cluster]
     2021-03-21T12:44:27.494Z [INFO]  agent: started state syncer
 ==> Consul agent running!
     2021-03-21T12:44:27.497Z [INFO]  agent.server.serf.lan: serf: EventMemberJoin: 0c3afdfcca00 10.0.24.8
     2021-03-21T12:44:27.497Z [INFO]  agent.server.serf.lan: serf: EventMemberJoin: 03acc773ab03 10.0.24.5
     2021-03-21T12:44:27.497Z [INFO]  agent.server: Adding LAN server: server="0c3afdfcca00 (Addr: tcp/10.0.24.8:8300) (DC: dc1)"
     2021-03-21T12:44:27.498Z [INFO]  agent.server: Adding LAN server: server="03acc773ab03 (Addr: tcp/10.0.24.5:8300) (DC: dc1)"
     2021-03-21T12:44:27.499Z [INFO]  agent.server.serf.wan: serf: EventMemberJoin: 0c3afdfcca00.dc1 10.0.24.8
     2021-03-21T12:44:27.499Z [INFO]  agent.server.serf.wan: serf: EventMemberJoin: 03acc773ab03.dc1 10.0.24.5
     2021-03-21T12:44:27.500Z [INFO]  agent.server: Handled event for server in area: event=member-join server=0c3afdfcca00.dc1 area=wan
     2021-03-21T12:44:27.500Z [INFO]  agent.server: Handled event for server in area: event=member-join server=03acc773ab03.dc1 area=wan
     2021-03-21T12:44:27.503Z [INFO]  agent: (LAN) joined: number_of_nodes=3
     2021-03-21T12:44:27.503Z [INFO]  agent: Join cluster completed. Synced with initial agents: cluster=LAN num_agents=3
     2021-03-21T12:44:27.657Z [INFO]  agent.server.serf.lan: serf: EventMemberJoin: 3a085917046c 10.0.24.6
     2021-03-21T12:44:27.657Z [INFO]  agent.server: Adding LAN server: server="3a085917046c (Addr: tcp/10.0.24.6:8300) (DC: dc1)"
     2021-03-21T12:44:27.658Z [INFO]  agent.server.serf.wan: serf: EventMemberJoin: 3a085917046c.dc1 10.0.24.6
     2021-03-21T12:44:27.659Z [INFO]  agent.server: Handled event for server in area: event=member-join server=3a085917046c.dc1 area=wan
     2021-03-21T12:44:27.701Z [INFO]  agent.server.serf.lan: serf: EventMemberJoin: 5376c710e215 10.0.24.7
     2021-03-21T12:44:27.702Z [INFO]  agent.server: Adding LAN server: server="5376c710e215 (Addr: tcp/10.0.24.7:8300) (DC: dc1)"
     2021-03-21T12:44:27.709Z [INFO]  agent.server: Found expected number of peers, attempting bootstrap: peers=10.0.24.5:8300,10.0.24.6:8300,10.0.24.7:8300,10.0.24.9:8300,10.0.24.8:8300
     2021-03-21T12:44:27.713Z [INFO]  agent.server.serf.wan: serf: EventMemberJoin: 5376c710e215.dc1 10.0.24.7
     2021-03-21T12:44:27.714Z [INFO]  agent.server: Handled event for server in area: event=member-join server=5376c710e215.dc1 area=wan
     2021-03-21T12:44:29.409Z [INFO]  agent.server.serf.lan: serf: EventMemberJoin: 893fc2531f5f 10.0.24.16
     2021-03-21T12:44:29.465Z [INFO]  agent.server.serf.lan: serf: EventMemberJoin: 53654dedd95f 10.0.24.14
     2021-03-21T12:44:29.673Z [INFO]  agent.server.serf.lan: serf: EventMemberJoin: fb0ce29d2848 10.0.24.15
     2021-03-21T12:44:29.942Z [INFO]  agent.server.serf.lan: serf: EventMemberJoin: 01f481d08969 10.0.24.17
     2021-03-21T12:44:29.943Z [INFO]  agent.server.serf.lan: serf: EventMemberJoin: 0ceb7abc8c3b 10.0.24.13
     2021-03-21T12:44:33.656Z [INFO]  agent: Synced node info
     2021-03-21T12:44:33.729Z [INFO]  agent.server: New leader elected: payload=0c3afdfcca00
     2021-03-21T12:45:29.492Z [INFO]  agent.server.memberlist.lan: memberlist: Suspect 53654dedd95f has failed, no acks received
     2021-03-21T12:45:32.698Z [INFO]  agent.server.memberlist.lan: memberlist: Marking 893fc2531f5f as failed, suspect timeout reached (2 peer confirmations)
     2021-03-21T12:45:32.698Z [INFO]  agent.server.serf.lan: serf: EventMemberFailed: 893fc2531f5f 10.0.24.16
     2021-03-21T12:45:33.492Z [INFO]  agent.server.memberlist.lan: memberlist: Suspect 893fc2531f5f has failed, no acks received
     2021-03-21T12:45:33.493Z [INFO]  agent.server.memberlist.lan: memberlist: Marking 53654dedd95f as failed, suspect timeout reached (2 peer confirmations)
     2021-03-21T12:45:33.493Z [INFO]  agent.server.serf.lan: serf: EventMemberFailed: 53654dedd95f 10.0.24.14
     2021-03-21T12:45:35.109Z [INFO]  agent.server.serf.lan: serf: EventMemberJoin: 92438ca3489d 10.0.24.18
     2021-03-21T12:45:35.186Z [INFO]  agent.server.serf.lan: serf: EventMemberJoin: 0dd939cd5232 10.0.24.19
     2021-03-21T12:45:36.492Z [INFO]  agent.server.memberlist.lan: memberlist: Suspect 01f481d08969 has failed, no acks received
     2021-03-21T12:45:40.492Z [INFO]  agent.server.memberlist.lan: memberlist: Suspect 0ceb7abc8c3b has failed, no acks received
     2021-03-21T12:45:40.493Z [INFO]  agent.server.memberlist.lan: memberlist: Marking 0ceb7abc8c3b as failed, suspect timeout reached (2 peer confirmations)
     2021-03-21T12:45:40.493Z [INFO]  agent.server.serf.lan: serf: EventMemberFailed: 0ceb7abc8c3b 10.0.24.13
     2021-03-21T12:45:41.807Z [INFO]  agent.server.serf.lan: serf: EventMemberJoin: d8517fd3624d 10.0.24.20
     2021-03-21T12:45:42.880Z [INFO]  agent.server.serf.lan: serf: EventMemberJoin: 3bdba541eb3c 10.0.24.21
     2021-03-21T12:45:43.149Z [INFO]  agent.server.serf.lan: serf: EventMemberJoin: 2d50749046de 10.0.24.22
     2021-03-21T12:45:44.213Z [INFO]  agent.server.memberlist.lan: memberlist: Marking fb0ce29d2848 as failed, suspect timeout reached (2 peer confirmations)
     2021-03-21T12:45:44.213Z [INFO]  agent.server.serf.lan: serf: EventMemberFailed: fb0ce29d2848 10.0.24.15
     2021-03-21T12:45:44.275Z [INFO]  agent.server.serf.lan: serf: EventMemberFailed: 01f481d08969 10.0.24.17
     2021-03-21T12:45:47.109Z [ERROR] agent.server.memberlist.lan: memberlist: Push/Pull with fb0ce29d2848 failed: dial tcp 10.0.24.15:8301: i/o timeout
     2021-03-21T12:45:57.492Z [INFO]  agent.server.serf.lan: serf: attempting reconnect to 53654dedd95f 10.0.24.14:8301
     2021-03-21T12:46:30.542Z [INFO]  agent.server.serf.lan: serf: attempting reconnect to 0ceb7abc8c3b 10.0.24.13:8301
     2021-03-21T12:46:45.470Z [ERROR] agent.server.raft: failed to flush response: error="write tcp 10.0.24.9:8300->10.0.24.8:46885: write: broken pipe"
     2021-03-21T12:46:52.247Z [INFO]  agent.server.serf.lan: serf: EventMemberJoin: 2e5ac016b1b4 10.0.24.23
     2021-03-21T12:46:52.492Z [INFO]  agent.server.memberlist.lan: memberlist: Suspect 0dd939cd5232 has failed, no acks received
     2021-03-21T12:46:52.984Z [INFO]  agent.server.serf.lan: serf: EventMemberFailed: 0dd939cd5232 10.0.24.19
     2021-03-21T12:46:56.492Z [INFO]  agent.server.memberlist.lan: memberlist: Suspect 92438ca3489d has failed, no acks received
     2021-03-21T12:46:59.658Z [INFO]  agent.server.memberlist.lan: memberlist: Marking 92438ca3489d as failed, suspect timeout reached (2 peer confirmations)
     2021-03-21T12:46:59.658Z [INFO]  agent.server.serf.lan: serf: EventMemberFailed: 92438ca3489d 10.0.24.18
     2021-03-21T12:46:59.913Z [INFO]  agent.server.serf.lan: serf: EventMemberJoin: 2bddc6ed5c81 10.0.24.24
     2021-03-21T12:47:08.492Z [INFO]  agent.server.memberlist.lan: memberlist: Suspect 3bdba541eb3c has failed, no acks received
     2021-03-21T12:47:12.492Z [INFO]  agent.server.memberlist.lan: memberlist: Suspect 3bdba541eb3c has failed, no acks received
     2021-03-21T12:47:12.697Z [INFO]  agent.server.serf.lan: serf: EventMemberFailed: 3bdba541eb3c 10.0.24.21
     2021-03-21T12:47:13.099Z [INFO]  agent.server.serf.lan: serf: EventMemberFailed: 2d50749046de 10.0.24.22
     2021-03-21T12:47:14.069Z [INFO]  agent.server.serf.lan: serf: EventMemberJoin: 4161f8d19d33 10.0.24.26
     2021-03-21T12:47:14.080Z [INFO]  agent.server.serf.lan: serf: EventMemberJoin: 958e5345d8f0 10.0.24.25
     2021-03-21T12:47:21.492Z [INFO]  agent.server.memberlist.lan: memberlist: Suspect d8517fd3624d has failed, no acks received
     2021-03-21T12:47:21.898Z [INFO]  agent.server.serf.lan: serf: EventMemberFailed: d8517fd3624d 10.0.24.20
     2021-03-21T12:47:22.812Z [INFO]  agent.server.serf.lan: serf: EventMemberJoin: 45217fd056e3 10.0.24.27
     2021-03-21T12:47:40.543Z [INFO]  agent.server.serf.lan: serf: attempting reconnect to 2d50749046de 10.0.24.22:8301
     2021-03-21T12:47:59.549Z [ERROR] agent.server.raft: failed to flush response: error="write tcp 10.0.24.9:8300->10.0.24.8:59327: write: broken pipe"
     2021-03-21T12:48:13.492Z [INFO]  agent.server.memberlist.lan: memberlist: Suspect 4161f8d19d33 has failed, no acks received
     2021-03-21T12:48:14.698Z [INFO]  agent.server.memberlist.lan: memberlist: Marking 2e5ac016b1b4 as failed, suspect timeout reached (2 peer confirmations)
     2021-03-21T12:48:14.698Z [INFO]  agent.server.serf.lan: serf: EventMemberFailed: 2e5ac016b1b4 10.0.24.23
     2021-03-21T12:48:15.198Z [INFO]  agent.server.serf.lan: serf: EventMemberFailed: 958e5345d8f0 10.0.24.25
     2021-03-21T12:48:15.650Z [INFO]  agent.server.serf.lan: serf: EventMemberFailed: 2bddc6ed5c81 10.0.24.24
     2021-03-21T12:48:15.758Z [INFO]  agent.server.serf.lan: serf: EventMemberJoin: 3cda2fcecd76 10.0.24.28
     2021-03-21T12:48:16.438Z [INFO]  agent.server.serf.lan: serf: EventMemberJoin: 033c7332f2c4 10.0.24.29
     2021-03-21T12:48:17.492Z [INFO]  agent.server.memberlist.lan: memberlist: Marking 4161f8d19d33 as failed, suspect timeout reached (2 peer confirmations)
     2021-03-21T12:48:17.492Z [INFO]  agent.server.serf.lan: serf: EventMemberFailed: 4161f8d19d33 10.0.24.26
     2021-03-21T12:48:17.492Z [INFO]  agent.server.memberlist.lan: memberlist: Suspect 958e5345d8f0 has failed, no acks received
     2021-03-21T12:48:17.603Z [INFO]  agent.server.serf.lan: serf: EventMemberJoin: d9026ce7be36 10.0.24.30
     2021-03-21T12:48:18.874Z [INFO]  agent.server.serf.lan: serf: EventMemberJoin: eccaede0bc7d 10.0.24.31
     2021-03-21T12:48:20.544Z [INFO]  agent.server.serf.lan: serf: attempting reconnect to 0ceb7abc8c3b 10.0.24.13:8301
     2021-03-21T12:48:24.492Z [INFO]  agent.server.memberlist.lan: memberlist: Suspect 45217fd056e3 has failed, no acks received
     2021-03-21T12:48:25.883Z [INFO]  agent.server.serf.lan: serf: EventMemberFailed: 45217fd056e3 10.0.24.27
     2021-03-21T12:48:28.544Z [INFO]  agent.server.serf.lan: serf: EventMemberJoin: e6b52fa55bea 10.0.24.32
     2021-03-21T12:48:53.614Z [INFO]  agent.server.serf.lan: serf: attempting reconnect to 0ceb7abc8c3b 10.0.24.13:8301
     2021-03-21T12:49:08.988Z [ERROR] agent.server.raft: failed to flush response: error="write tcp 10.0.24.9:8300->10.0.24.8:57397: write: broken pipe"
     2021-03-21T12:49:20.492Z [INFO]  agent.server.memberlist.lan: memberlist: Suspect 033c7332f2c4 has failed, no acks received
     2021-03-21T12:49:23.739Z [INFO]  agent.server.memberlist.lan: memberlist: Marking 033c7332f2c4 as failed, suspect timeout reached (2 peer confirmations)
     2021-03-21T12:49:23.739Z [INFO]  agent.server.serf.lan: serf: EventMemberFailed: 033c7332f2c4 10.0.24.29
     2021-03-21T12:49:24.046Z [INFO]  agent.server.serf.lan: serf: EventMemberJoin: 7554fe7a1f06 10.0.24.33
     2021-03-21T12:49:26.670Z [INFO]  agent.server.serf.lan: serf: attempting reconnect to 893fc2531f5f 10.0.24.16:8301
     2021-03-21T12:49:36.492Z [INFO]  agent.server.memberlist.lan: memberlist: Suspect 7554fe7a1f06 has failed, no acks received
     2021-03-21T12:49:37.897Z [INFO]  agent.server.serf.lan: serf: EventMemberFailed: 7554fe7a1f06 10.0.24.33
     2021-03-21T12:49:38.055Z [INFO]  agent.server.serf.lan: serf: EventMemberJoin: 118ee3ad4900 10.0.24.34
     2021-03-21T12:49:39.494Z [INFO]  agent.server.serf.lan: serf: EventMemberFailed: eccaede0bc7d 10.0.24.31
     2021-03-21T12:49:40.133Z [INFO]  agent.server.serf.lan: serf: EventMemberJoin: 8d9f34de685f 10.0.24.35
     2021-03-21T12:49:40.492Z [INFO]  agent.server.memberlist.lan: memberlist: Suspect d9026ce7be36 has failed, no acks received

In the same time im the MySQL Service is in a infinity loop with the same error message everytime.

 2021-03-21 12:51:09,697 INFO root Starting Consul Agent
 2021-03-21 12:51:09,700 INFO root Setup MinIO agent
 Added `backup` successfully.
 ==> Starting Consul agent...
            Version: '1.8.4'
            Node ID: '457812dc-1915-ed7e-7612-c02b7c1dcb7b'
          Node name: 'b67786a52a2f'
         Datacenter: 'dc1' (Segment: '')
             Server: false (Bootstrap: false)
        Client Addr: [127.0.0.1] (HTTP: 8500, HTTPS: -1, gRPC: -1, DNS: 8600)
       Cluster Addr: 10.0.24.43 (LAN: 8301, WAN: 8302)
            Encrypt: Gossip: false, TLS-Outgoing: false, TLS-Incoming: false, Auto-Encrypt-TLS: false

 ==> Log data will now stream in as it occurs:

     2021-03-21T12:51:09.811Z [INFO]  agent.client.serf.lan: serf: EventMemberJoin: b67786a52a2f 10.0.24.43
     2021-03-21T12:51:09.811Z [INFO]  agent.router: Initializing LAN area manager
     2021-03-21T12:51:09.812Z [INFO]  agent: Started DNS server: address=127.0.0.1:8600 network=udp
     2021-03-21T12:51:09.812Z [INFO]  agent: Started DNS server: address=127.0.0.1:8600 network=tcp
     2021-03-21T12:51:09.813Z [INFO]  agent: Started HTTP server: address=127.0.0.1:8500 network=tcp
 ==> Joining cluster...
     2021-03-21T12:51:09.815Z [INFO]  agent: (LAN) joining: lan_addresses=[consul_cluster]
     2021-03-21T12:51:09.818Z [INFO]  agent.client.serf.lan: serf: EventMemberJoin: 5376c710e215 10.0.24.7
     2021-03-21T12:51:09.819Z [INFO]  agent.client.serf.lan: serf: EventMemberJoin: 1db09ce9a3e1 10.0.24.39
     2021-03-21T12:51:09.819Z [INFO]  agent.client.serf.lan: serf: EventMemberJoin: 0c3afdfcca00 10.0.24.8
     2021-03-21T12:51:09.819Z [INFO]  agent.client: adding server: server="5376c710e215 (Addr: tcp/10.0.24.7:8300) (DC: dc1)"
     2021-03-21T12:51:09.820Z [INFO]  agent.client: adding server: server="0c3afdfcca00 (Addr: tcp/10.0.24.8:8300) (DC: dc1)"
     2021-03-21T12:51:09.819Z [INFO]  agent.client.serf.lan: serf: EventMemberJoin: 86dfa4ec9d47 10.0.24.41
     2021-03-21T12:51:09.820Z [INFO]  agent.client.serf.lan: serf: EventMemberJoin: 3a085917046c 10.0.24.6
     2021-03-21T12:51:09.820Z [INFO]  agent.client.serf.lan: serf: EventMemberJoin: 03acc773ab03 10.0.24.5
     2021-03-21T12:51:09.820Z [INFO]  agent.client.serf.lan: serf: EventMemberJoin: 99b7d8294177 10.0.24.9
     2021-03-21T12:51:09.821Z [INFO]  agent.client.serf.lan: serf: EventMemberJoin: 0c4b995cd64c 10.0.24.42
     2021-03-21T12:51:09.821Z [INFO]  agent.client.serf.lan: serf: EventMemberJoin: 538c85ac51ca 10.0.24.40
     2021-03-21T12:51:09.822Z [INFO]  agent.client: adding server: server="3a085917046c (Addr: tcp/10.0.24.6:8300) (DC: dc1)"
     2021-03-21T12:51:09.822Z [INFO]  agent.client: adding server: server="03acc773ab03 (Addr: tcp/10.0.24.5:8300) (DC: dc1)"
     2021-03-21T12:51:09.822Z [INFO]  agent.client: adding server: server="99b7d8294177 (Addr: tcp/10.0.24.9:8300) (DC: dc1)"
     2021-03-21T12:51:09.873Z [INFO]  agent: (LAN) joined: number_of_nodes=5
     2021-03-21T12:51:09.874Z [INFO]  agent: Join completed. Initial agents synced with: agent_count=5
     2021-03-21T12:51:09.874Z [INFO]  agent: started state syncer
 ==> Consul agent running!
 Bucket created successfully `backup/mysqlbackup`.
     2021-03-21T12:51:09.947Z [INFO]  agent: Synced node info
 Lifecycle configuration rule with ID `expire_rule` modified  to backup/mysqlbackup.
 2021-03-21 12:51:09,982 INFO root Setup MinIO agent
 Added `backup` successfully.
 Bucket created successfully `backup/mysqlbackup`.
 Lifecycle configuration rule with ID `expire_rule` modified  to backup/mysqlbackup.
 2021-03-21 12:51:11,364 INFO root Register Consul connection
 2021-03-21 12:51:11,425 INFO root Init local node (leader=False, backup=True)
 2021-03-21 12:51:11,425 INFO root Restore MySQL Backup
 2021-03-21 12:51:11,426 INFO root Setup MinIO agent
 Added `backup` successfully.
 Bucket created successfully `backup/mysqlbackup`.
 Lifecycle configuration rule with ID `expire_rule` modified  to backup/mysqlbackup.
 `backup/mysqlbackup/mysql_backup_1616294704.9394488.tgz` -> `/tmp/mysql_restore_1616331071.425939/mysql_backup_1616294704.9394488.tgz`
     2021-03-21T12:51:13.279Z [INFO]  agent: Newer Consul version available: new_version=1.9.3 current_version=1.8.4
 Total: 0 B, Transferred: 329.94 MiB, Speed: 36.64 MiB/s
 xtrabackup: recognized server arguments: --datadir=/var/lib/mysql
 xtrabackup: recognized client arguments: --copy-back=1 --target-dir=/tmp/mysql_restore_1616331071.425939/mysql
 /usr/bin/xtrabackup version 8.0.14 based on MySQL server 8.0.21 Linux (x86_64) (revision id: 113f3d7)
 210321 12:51:35 [01] Copying undo_001 to /var/lib/mysql/undo_001
 210321 12:51:35 [01]        ...done
 210321 12:51:44 [01] Copying undo_002 to /var/lib/mysql/undo_002
 210321 12:51:45 [01]        ...done
 210321 12:51:46 [01] Copying ib_logfile0 to /var/lib/mysql/ib_logfile0
 210321 12:51:46 [01]        ...done
 210321 12:51:47 [01] Copying ib_logfile1 to /var/lib/mysql/ib_logfile1
 210321 12:51:47 [01]        ...done
 210321 12:51:48 [01] Copying ibdata1 to /var/lib/mysql/ibdata1
 210321 12:51:48 [01]        ...done
 210321 12:51:48 [01] Copying binlog.000019 to /var/lib/mysql/binlog.000019
 210321 12:51:48 [01]        ...done
 210321 12:51:48 [01] Copying binlog.index to /var/lib/mysql/binlog.index
 210321 12:51:48 [01]        ...done
 210321 12:51:48 [01] Copying ./performance_schema/events_statement_127.sdi to /var/lib/mysql/performance_schema/events_statement_127.sdi
 210321 12:51:48 [01]        ...done
 210321 12:51:48 [01] Copying ./performance_schema/replication_appl_162.sdi to /var/lib/mysql/performance_schema/replication_appl_162.sdi
 210321 12:51:48 [01]        ...done
 210321 12:51:48 [01] Copying ./performance_schema/threads_107.sdi to /var/lib/mysql/performance_schema/threads_107.sdi
 210321 12:51:48 [01]        ...done
 210321 12:51:48 [01] Copying ./performance_schema/setup_actors_99.sdi to /var/lib/mysql/performance_schema/setup_actors_99.sdi
 210321 12:51:48 [01]        ...done
 210321 12:51:48 [01] Copying ./performance_schema/events_statement_124.sdi to /var/lib/mysql/performance_schema/events_statement_124.sdi
 210321 12:51:48 [01]        ...done
 210321 12:51:48 [01] Copying ./performance_schema/global_variables_179.sdi to /var/lib/mysql/performance_schema/global_variables_179.sdi
 210321 12:51:48 [01]        ...done
 210321 12:51:48 [01] Copying ./performance_schema/events_waits_sum_86.sdi to /var/lib/mysql/performance_schema/events_waits_sum_86.sdi
 210321 12:51:48 [01]        ...done
 210321 12:51:48 [01] Copying ./performance_schema/events_waits_sum_87.sdi to /var/lib/mysql/performance_schema/events_waits_sum_87.sdi
 210321 12:51:48 [01]        ...done
 210321 12:51:48 [01] Copying ./performance_schema/socket_instances_144.sdi to /var/lib/mysql/performance_schema/socket_instances_144.sdi
 210321 12:51:48 [01]        ...done
 210321 12:51:48 [01] Copying ./performance_schema/status_by_accoun_172.sdi to /var/lib/mysql/performance_schema/status_by_accoun_172.sdi
 210321 12:51:48 [01]        ...done
 210321 12:51:48 [01] Copying ./performance_schema/events_waits_sum_88.sdi to /var/lib/mysql/performance_schema/events_waits_sum_88.sdi
 210321 12:51:48 [01]        ...done
 210321 12:51:48 [01] Copying ./performance_schema/user_variables_b_171.sdi to /var/lib/mysql/performance_schema/user_variables_b_171.sdi
 210321 12:51:48 [01]        ...done
 210321 12:51:48 [01] Copying ./performance_schema/status_by_host_173.sdi to /var/lib/mysql/performance_schema/status_by_host_173.sdi
 210321 12:51:48 [01]        ...done
 210321 12:51:48 [01] Copying ./performance_schema/events_transacti_134.sdi to /var/lib/mysql/performance_schema/events_transacti_134.sdi
 210321 12:51:48 [01]        ...done
 210321 12:51:48 [01] Copying ./performance_schema/session_variable_180.sdi to /var/lib/mysql/performance_schema/session_variable_180.sdi
 210321 12:51:48 [01]        ...done
 210321 12:51:48 [01] Copying ./performance_schema/socket_summary_b_145.sdi to /var/lib/mysql/performance_schema/socket_summary_b_145.sdi
 210321 12:51:48 [01]        ...done
 210321 12:51:48 [01] Copying ./performance_schema/replication_appl_168.sdi to /var/lib/mysql/performance_schema/replication_appl_168.sdi
 210321 12:51:48 [01]        ...done
 210321 12:51:48 [01] Copying ./performance_schema/users_141.sdi to /var/lib/mysql/performance_schema/users_141.sdi
 210321 12:51:48 [01]        ...done
 210321 12:51:48 [01] Copying ./performance_schema/events_stages_su_114.sdi to /var/lib/mysql/performance_schema/events_stages_su_114.sdi
 210321 12:51:48 [01]        ...done
 210321 12:51:48 [01] Copying ./performance_schema/events_errors_su_136.sdi to /var/lib/mysql/performance_schema/events_errors_su_136.sdi
 210321 12:51:48 [01]        ...done
 210321 12:51:48 [01] Copying ./performance_schema/events_waits_his_83.sdi to /var/lib/mysql/performance_schema/events_waits_his_83.sdi
 210321 12:51:48 [01]        ...done
 210321 12:51:48 [01] Copying ./performance_schema/file_instances_91.sdi to /var/lib/mysql/performance_schema/file_instances_91.sdi
 210321 12:51:48 [01]        ...done
 210321 12:51:48 [01] Copying ./performance_schema/setup_threads_103.sdi to /var/lib/mysql/performance_schema/setup_threads_103.sdi
 210321 12:51:48 [01]        ...done
 210321 12:51:48 [01] Copying ./performance_schema/tls_channel_stat_185.sdi to /var/lib/mysql/performance_schema/tls_channel_stat_185.sdi
 210321 12:51:48 [01]        ...done
 210321 12:51:48 [01] Copying ./performance_schema/events_transacti_129.sdi to /var/lib/mysql/performance_schema/events_transacti_129.sdi
 210321 12:51:48 [01]        ...done
 210321 12:51:48 [01] Copying ./performance_schema/prepared_stateme_170.sdi to /var/lib/mysql/performance_schema/prepared_stateme_170.sdi
 210321 12:51:48 [01]        ...done
 210321 12:51:48 [01] Copying ./performance_schema/events_transacti_130.sdi to /var/lib/mysql/performance_schema/events_transacti_130.sdi
 210321 12:51:48 [01]        ...done
 210321 12:51:48 [01] Copying ./performance_schema/events_transacti_132.sdi to /var/lib/mysql/performance_schema/events_transacti_132.sdi
 210321 12:51:48 [01]        ...done
 210321 12:51:48 [01] Copying ./performance_schema/events_errors_su_139.sdi to /var/lib/mysql/performance_schema/events_errors_su_139.sdi
 210321 12:51:48 [01]        ...done
 210321 12:51:48 [01] Copying ./performance_schema/file_summary_by__92.sdi to /var/lib/mysql/performance_schema/file_summary_by__92.sdi
 210321 12:51:48 [01]        ...done
 210321 12:51:48 [01] Copying ./performance_schema/events_errors_su_137.sdi to /var/lib/mysql/performance_schema/events_errors_su_137.sdi
 210321 12:51:48 [01]        ...done
 210321 12:51:48 [01] Copying ./performance_schema/session_account__148.sdi to /var/lib/mysql/performance_schema/session_account__148.sdi
 210321 12:51:48 [01]        ...done
 210321 12:51:48 [01] Copying ./performance_schema/metadata_locks_156.sdi to /var/lib/mysql/performance_schema/metadata_locks_156.sdi
 210321 12:51:48 [01]        ...done
 210321 12:51:48 [01] Copying ./performance_schema/events_stages_cu_108.sdi to /var/lib/mysql/performance_schema/events_stages_cu_108.sdi
 210321 12:51:48 [01]        ...done
 210321 12:51:48 [01] Copying ./performance_schema/replication_grou_166.sdi to /var/lib/mysql/performance_schema/replication_grou_166.sdi
 210321 12:51:48 [01]        ...done
 210321 12:51:48 [01] Copying ./performance_schema/setup_objects_102.sdi to /var/lib/mysql/performance_schema/setup_objects_102.sdi
 210321 12:51:48 [01]        ...done
 210321 12:51:48 [01] Copying ./performance_schema/objects_summary__96.sdi to /var/lib/mysql/performance_schema/objects_summary__96.sdi
 210321 12:51:48 [01]        ...done
 210321 12:51:48 [01] Copying ./performance_schema/events_stages_su_111.sdi to /var/lib/mysql/performance_schema/events_stages_su_111.sdi
 210321 12:51:48 [01]        ...done
 210321 12:51:48 [01] Copying ./performance_schema/events_waits_sum_90.sdi to /var/lib/mysql/performance_schema/events_waits_sum_90.sdi
 210321 12:51:48 [01]        ...done
 210321 12:51:48 [01] Copying ./performance_schema/table_io_waits_s_104.sdi to /var/lib/mysql/performance_schema/table_io_waits_s_104.sdi
 210321 12:51:48 [01]        ...done
 210321 12:51:48 [01] Copying ./performance_schema/events_transacti_128.sdi to /var/lib/mysql/performance_schema/events_transacti_128.sdi
 210321 12:51:48 [01]        ...done
 210321 12:51:48 [01] Copying ./performance_schema/replication_appl_164.sdi to /var/lib/mysql/performance_schema/replication_appl_164.sdi
 210321 12:51:48 [01]        ...done
 210321 12:51:48 [01] Copying ./performance_schema/events_waits_sum_89.sdi to /var/lib/mysql/performance_schema/events_waits_sum_89.sdi
 210321 12:51:48 [01]        ...done
 210321 12:51:48 [01] Copying ./performance_schema/memory_summary_b_153.sdi to /var/lib/mysql/performance_schema/memory_summary_b_153.sdi
 210321 12:51:48 [01]        ...done
 210321 12:51:48 [01] Copying ./performance_schema/events_stages_su_115.sdi to /var/lib/mysql/performance_schema/events_stages_su_115.sdi
 210321 12:51:48 [01]        ...done
 210321 12:51:48 [01] Copying ./performance_schema/accounts_142.sdi to /var/lib/mysql/performance_schema/accounts_142.sdi
 210321 12:51:48 [01]        ...done
 210321 12:51:48 [01] Copying ./performance_schema/file_summary_by__93.sdi to /var/lib/mysql/performance_schema/file_summary_by__93.sdi
 210321 12:51:48 [01]        ...done
 210321 12:51:48 [01] Copying ./performance_schema/table_handles_155.sdi to /var/lib/mysql/performance_schema/table_handles_155.sdi
 210321 12:51:48 [01]        ...done
 210321 12:51:48 [01] Copying ./performance_schema/events_stages_su_112.sdi to /var/lib/mysql/performance_schema/events_stages_su_112.sdi
 210321 12:51:48 [01]        ...done
 210321 12:51:48 [01] Copying ./performance_schema/setup_instrument_101.sdi to /var/lib/mysql/performance_schema/setup_instrument_101.sdi
 210321 12:51:48 [01]        ...done
 210321 12:51:48 [01] Copying ./performance_schema/socket_summary_b_146.sdi to /var/lib/mysql/performance_schema/socket_summary_b_146.sdi
 210321 12:51:48 [01]        ...done
 210321 12:51:48 [01] Copying ./performance_schema/user_defined_fun_183.sdi to /var/lib/mysql/performance_schema/user_defined_fun_183.sdi
 210321 12:51:48 [01]        ...done
 210321 12:51:48 [01] Copying ./performance_schema/memory_summary_b_152.sdi to /var/lib/mysql/performance_schema/memory_summary_b_152.sdi
 210321 12:51:48 [01]        ...done
 210321 12:51:48 [01] Copying ./performance_schema/events_stages_hi_109.sdi to /var/lib/mysql/performance_schema/events_stages_hi_109.sdi
 210321 12:51:48 [01]        ...done
 210321 12:51:48 [01] Copying ./performance_schema/replication_appl_165.sdi to /var/lib/mysql/performance_schema/replication_appl_165.sdi
 210321 12:51:48 [01]        ...done
 210321 12:51:48 [01] Copying ./performance_schema/cond_instances_81.sdi to /var/lib/mysql/performance_schema/cond_instances_81.sdi
 210321 12:51:48 [01]        ...done
 210321 12:51:48 [01] Copying ./performance_schema/table_io_waits_s_105.sdi to /var/lib/mysql/performance_schema/table_io_waits_s_105.sdi
 210321 12:51:48 [01]        ...done
 210321 12:51:48 [01] Copying ./performance_schema/log_status_169.sdi to /var/lib/mysql/performance_schema/log_status_169.sdi
 210321 12:51:48 [01]        ...done
 210321 12:51:48 [01] Copying ./performance_schema/events_waits_cur_82.sdi to /var/lib/mysql/performance_schema/events_waits_cur_82.sdi
 210321 12:51:48 [01]        ...done
 210321 12:51:48 [01] Copying ./performance_schema/events_stages_hi_110.sdi to /var/lib/mysql/performance_schema/events_stages_hi_110.sdi
 210321 12:51:48 [01]        ...done
 210321 12:51:48 [01] Copying ./performance_schema/replication_appl_163.sdi to /var/lib/mysql/performance_schema/replication_appl_163.sdi
 210321 12:51:48 [01]        ...done
 210321 12:51:48 [01] Copying ./performance_schema/persisted_variab_182.sdi to /var/lib/mysql/performance_schema/persisted_variab_182.sdi
 210321 12:51:48 [01]        ...done
 210321 12:51:48 [01] Copying ./performance_schema/status_by_thread_174.sdi to /var/lib/mysql/performance_schema/status_by_thread_174.sdi
 210321 12:51:48 [01]        ...done
 210321 12:51:48 [01] Copying ./performance_schema/events_statement_125.sdi to /var/lib/mysql/performance_schema/events_statement_125.sdi
 210321 12:51:48 [01]        ...done
 210321 12:51:48 [01] Copying ./performance_schema/events_statement_119.sdi to /var/lib/mysql/performance_schema/events_statement_119.sdi
 210321 12:51:48 [01]        ...done
 210321 12:51:48 [01] Copying ./performance_schema/events_statement_121.sdi to /var/lib/mysql/performance_schema/events_statement_121.sdi
 210321 12:51:48 [01]        ...done
 210321 12:51:48 [01] Copying ./performance_schema/events_transacti_135.sdi to /var/lib/mysql/performance_schema/events_transacti_135.sdi
 210321 12:51:48 [01]        ...done
 210321 12:51:48 [01] Copying ./performance_schema/replication_conn_159.sdi to /var/lib/mysql/performance_schema/replication_conn_159.sdi
 210321 12:51:48 [01]        ...done
 210321 12:51:48 [01] Copying ./performance_schema/data_lock_waits_158.sdi to /var/lib/mysql/performance_schema/data_lock_waits_158.sdi
 210321 12:51:48 [01]        ...done
 210321 12:51:48 [01] Copying ./performance_schema/events_statement_118.sdi to /var/lib/mysql/performance_schema/events_statement_118.sdi
 210321 12:51:48 [01]        ...done
 210321 12:51:48 [01] Copying ./performance_schema/performance_time_97.sdi to /var/lib/mysql/performance_schema/performance_time_97.sdi
 210321 12:51:48 [01]        ...done
 210321 12:51:48 [01] Copying ./performance_schema/events_errors_su_138.sdi to /var/lib/mysql/performance_schema/events_errors_su_138.sdi
 210321 12:51:48 [01]        ...done
 210321 12:51:48 [01] Copying ./performance_schema/events_statement_120.sdi to /var/lib/mysql/performance_schema/events_statement_120.sdi
 210321 12:51:48 [01]        ...done
 210321 12:51:48 [01] Copying ./performance_schema/events_statement_116.sdi to /var/lib/mysql/performance_schema/events_statement_116.sdi
 210321 12:51:48 [01]        ...done
 210321 12:51:48 [01] Copying ./performance_schema/global_status_176.sdi to /var/lib/mysql/performance_schema/global_status_176.sdi
 210321 12:51:48 [01]        ...done
 210321 12:51:48 [01] Copying ./performance_schema/hosts_143.sdi to /var/lib/mysql/performance_schema/hosts_143.sdi
 210321 12:51:48 [01]        ...done
 210321 12:51:48 [01] Copying ./performance_schema/events_errors_su_140.sdi to /var/lib/mysql/performance_schema/events_errors_su_140.sdi
 210321 12:51:48 [01]        ...done
 210321 12:51:48 [01] Copying ./performance_schema/events_statement_122.sdi to /var/lib/mysql/performance_schema/events_statement_122.sdi
 210321 12:51:48 [01]        ...done
 210321 12:51:48 [01] Copying ./performance_schema/events_transacti_131.sdi to /var/lib/mysql/performance_schema/events_transacti_131.sdi
 210321 12:51:48 [01]        ...done
 210321 12:51:49 [01] Copying ./performance_schema/replication_grou_160.sdi to /var/lib/mysql/performance_schema/replication_grou_160.sdi
 210321 12:51:49 [01]        ...done
 210321 12:51:49 [01] Copying ./performance_schema/memory_summary_g_150.sdi to /var/lib/mysql/performance_schema/memory_summary_g_150.sdi
 210321 12:51:49 [01]        ...done
 210321 12:51:49 [01] Copying ./performance_schema/events_waits_his_84.sdi to /var/lib/mysql/performance_schema/events_waits_his_84.sdi
 210321 12:51:49 [01]        ...done
 210321 12:51:49 [01] Copying ./performance_schema/mutex_instances_95.sdi to /var/lib/mysql/performance_schema/mutex_instances_95.sdi
 210321 12:51:49 [01]        ...done
 210321 12:51:49 [01] Copying ./performance_schema/memory_summary_b_154.sdi to /var/lib/mysql/performance_schema/memory_summary_b_154.sdi
 210321 12:51:49 [01]        ...done
 210321 12:51:49 [01] Copying ./performance_schema/status_by_user_175.sdi to /var/lib/mysql/performance_schema/status_by_user_175.sdi
 210321 12:51:49 [01]        ...done
 210321 12:51:49 [01] Copying ./performance_schema/variables_info_181.sdi to /var/lib/mysql/performance_schema/variables_info_181.sdi
 210321 12:51:49 [01]        ...done
 210321 12:51:49 [01] Copying ./performance_schema/replication_conn_161.sdi to /var/lib/mysql/performance_schema/replication_conn_161.sdi
 210321 12:51:49 [01]        ...done
 210321 12:51:49 [01] Copying ./performance_schema/keyring_keys_149.sdi to /var/lib/mysql/performance_schema/keyring_keys_149.sdi
 210321 12:51:49 [01]        ...done
 210321 12:51:49 [01] Copying ./performance_schema/memory_summary_b_151.sdi to /var/lib/mysql/performance_schema/memory_summary_b_151.sdi
 210321 12:51:49 [01]        ...done
 210321 12:51:49 [01] Copying ./performance_schema/rwlock_instances_98.sdi to /var/lib/mysql/performance_schema/rwlock_instances_98.sdi
 210321 12:51:49 [01]        ...done
 210321 12:51:49 [01] Copying ./performance_schema/events_transacti_133.sdi to /var/lib/mysql/performance_schema/events_transacti_133.sdi
 210321 12:51:49 [01]        ...done
 210321 12:51:49 [01] Copying ./performance_schema/host_cache_94.sdi to /var/lib/mysql/performance_schema/host_cache_94.sdi
 210321 12:51:49 [01]        ...done
 210321 12:51:49 [01] Copying ./performance_schema/session_status_177.sdi to /var/lib/mysql/performance_schema/session_status_177.sdi
 210321 12:51:49 [01]        ...done
 210321 12:51:49 [01] Copying ./performance_schema/events_waits_sum_85.sdi to /var/lib/mysql/performance_schema/events_waits_sum_85.sdi
 210321 12:51:49 [01]        ...done
 210321 12:51:49 [01] Copying ./performance_schema/events_stages_su_113.sdi to /var/lib/mysql/performance_schema/events_stages_su_113.sdi
 210321 12:51:49 [01]        ...done
 210321 12:51:49 [01] Copying ./performance_schema/events_statement_117.sdi to /var/lib/mysql/performance_schema/events_statement_117.sdi
 210321 12:51:49 [01]        ...done
 210321 12:51:49 [01] Copying ./performance_schema/data_locks_157.sdi to /var/lib/mysql/performance_schema/data_locks_157.sdi
 210321 12:51:49 [01]        ...done
 210321 12:51:49 [01] Copying ./performance_schema/events_statement_126.sdi to /var/lib/mysql/performance_schema/events_statement_126.sdi
 210321 12:51:49 [01]        ...done
 210321 12:51:49 [01] Copying ./performance_schema/binary_log_trans_184.sdi to /var/lib/mysql/performance_schema/binary_log_trans_184.sdi
 210321 12:51:49 [01]        ...done
 210321 12:51:49 [01] Copying ./performance_schema/session_connect__147.sdi to /var/lib/mysql/performance_schema/session_connect__147.sdi
 210321 12:51:49 [01]        ...done
 210321 12:51:49 [01] Copying ./performance_schema/events_statement_123.sdi to /var/lib/mysql/performance_schema/events_statement_123.sdi
 210321 12:51:49 [01]        ...done
 210321 12:51:49 [01] Copying ./performance_schema/replication_appl_167.sdi to /var/lib/mysql/performance_schema/replication_appl_167.sdi
 210321 12:51:49 [01]        ...done
 210321 12:51:49 [01] Copying ./performance_schema/table_lock_waits_106.sdi to /var/lib/mysql/performance_schema/table_lock_waits_106.sdi
 210321 12:51:49 [01]        ...done
 210321 12:51:49 [01] Copying ./performance_schema/setup_consumers_100.sdi to /var/lib/mysql/performance_schema/setup_consumers_100.sdi
 210321 12:51:49 [01]        ...done
 210321 12:51:49 [01] Copying ./performance_schema/variables_by_thr_178.sdi to /var/lib/mysql/performance_schema/variables_by_thr_178.sdi
 210321 12:51:49 [01]        ...done
 210321 12:51:49 [01] Copying ./xtrabackup_master_key_id to /var/lib/mysql/xtrabackup_master_key_id
 210321 12:51:49 [01]        ...done
 210321 12:51:49 [01] Copying ./sys/sys_config.ibd to /var/lib/mysql/sys/sys_config.ibd
 210321 12:51:49 [01]        ...done
 210321 12:51:49 [01] Copying ./ibtmp1 to /var/lib/mysql/ibtmp1
 210321 12:51:49 [01]        ...done
 210321 12:51:49 [01] Copying ./testbla/db.opt to /var/lib/mysql/testbla/db.opt
 210321 12:51:49 [01]        ...done
 210321 12:51:49 [01] Creating directory ./#innodb_temp
 210321 12:51:49 [01] ...done.
 210321 12:51:49 [01] Copying ./mysql.ibd to /var/lib/mysql/mysql.ibd
 210321 12:51:49 [01]        ...done
 210321 12:51:49 [01] Copying ./ib_buffer_pool to /var/lib/mysql/ib_buffer_pool
 210321 12:51:49 [01]        ...done
 210321 12:51:49 [01] Copying ./mysql/slow_log.CSV to /var/lib/mysql/mysql/slow_log.CSV
 210321 12:51:49 [01]        ...done
 210321 12:51:49 [01] Copying ./mysql/slow_log.CSM to /var/lib/mysql/mysql/slow_log.CSM
 210321 12:51:49 [01]        ...done
 210321 12:51:49 [01] Copying ./mysql/general_log.CSV to /var/lib/mysql/mysql/general_log.CSV
 210321 12:51:49 [01]        ...done
 210321 12:51:49 [01] Copying ./mysql/general_log.CSM to /var/lib/mysql/mysql/general_log.CSM
 210321 12:51:49 [01]        ...done
 210321 12:51:49 [01] Copying ./mysql/slow_log_208.sdi to /var/lib/mysql/mysql/slow_log_208.sdi
 210321 12:51:49 [01]        ...done
 210321 12:51:49 [01] Copying ./mysql/general_log_207.sdi to /var/lib/mysql/mysql/general_log_207.sdi
 210321 12:51:49 [01]        ...done
 210321 12:51:49 [01] Copying ./adonis/tests.ibd to /var/lib/mysql/adonis/tests.ibd
 210321 12:51:52 [01]        ...done
 210321 12:52:02 [01] Copying ./adonis/adonis_schema.ibd to /var/lib/mysql/adonis/adonis_schema.ibd
 210321 12:52:02 [01]        ...done
 210321 12:52:02 [01] Copying ./adonis/tokens.ibd to /var/lib/mysql/adonis/tokens.ibd
 210321 12:52:02 [01]        ...done
 210321 12:52:02 [01] Copying ./adonis/users.ibd to /var/lib/mysql/adonis/users.ibd
 210321 12:52:02 [01]        ...done
 210321 12:52:02 [01] Copying ./xtrabackup_info to /var/lib/mysql/xtrabackup_info
 210321 12:52:02 [01]        ...done
 210321 12:52:02 completed OK!
 2021-03-21 12:52:02 [INFO] Using config file /etc/proxysql.cnf
 Renaming database file /var/lib/proxysql/proxysql.db
 2021-03-21 12:52:02 [INFO] Using OpenSSL version: OpenSSL 1.1.1d  10 Sep 2019
 2021-03-21 12:52:02 [INFO] No SSL keys/certificates found in datadir (/var/lib/proxysql). Generating new keys/certificates.
 2021-03-21 12:52:03,085 INFO root Starting MySQL
 Logging to '/var/lib/mysql/b67786a52a2f.err'.
 2021-03-21T12:52:12.141646Z mysqld_safe Starting mysqld daemon with databases from /var/lib/mysql
     2021-03-21T12:52:14.812Z [INFO]  agent.client.memberlist.lan: memberlist: Suspect 86dfa4ec9d47 has failed, no acks received
 2021-03-21 12:52:14,975 INFO root Performing initial ProxySQL setup
     2021-03-21T12:52:15.289Z [ERROR] agent.client: RPC failed to server: method=KVS.Apply server=10.0.24.7:8300 error="rpc error making call: rpc error making call: invalid session "3ff03485-8cf2-ccad-af6c-7db4d63447d8""
     2021-03-21T12:52:15.289Z [ERROR] agent.http: Request error: method=PUT url=/v1/kv/mcm/instances/10.0.24.43?acquire=3ff03485-8cf2-ccad-af6c-7db4d63447d8 from=127.0.0.1:48390 error="rpc error making call: rpc error making call: invalid session "3ff03485-8cf2-ccad-af6c-7db4d63447d8""
 Traceback (most recent call last):
   File "./mysql_cluster_manager.py", line 46, in <module>
     Actions.join_or_bootstrap()
   File "/cluster/mcm/actions.py", line 86, in join_or_bootstrap
     server_id=server_id)
   File "/cluster/mcm/consul.py", line 250, in register_node
     put_result = self.client.kv.put(path, json_string, acquire=self.node_health_session)
   File "/usr/local/lib/python3.7/dist-packages/consul/base.py", line 3069, in put
     params=params, headers=headers, data=value)
   File "/usr/local/lib/python3.7/dist-packages/consul/std.py", line 39, in put
     timeout=self.timeout)))
   File "/usr/local/lib/python3.7/dist-packages/consul/base.py", line 249, in cb
     CB._status(response, allow_404=allow_404)
   File "/usr/local/lib/python3.7/dist-packages/consul/base.py", line 212, in _status
     raise ConsulException("%d %s" % (response.code, response.body))
 consul.base.ConsulException: 500 rpc error making call: rpc error making call: invalid session "3ff03485-8cf2-ccad-af6c-7db4d63447d8"

If you have any hint, how to fix this it would be awesome.

Thanks for your time :)

jnidzwetzki commented 3 years ago

Hi @2peter3 ,

It seems that your Consul installation has lost the quorum. This can occur when more than n/2 consul nodes are unreachable.

I see that you run 5 consul nodes, and you have set max_replicas_per_node: 3. Therefore, when one node contains 3 out of 5 consul services, and this node goes down, Consul will lose the quorum.

To recover from this situation, you can do the following:

To avoid such problems in the future, reduce max_replicas_per_node to 1.

Best Regards Jan

2peter3 commented 3 years ago

Hey @jnidzwetzki ,

It looks like I found the problem. For a freshly created cluster, the backups are quite small. After the database has been filled with some data 5-6 million entries and the stack has been killed. If you start the cluster again, it loads the backup from the minio server in my case about 300mb. Then the restore is carried out via xtrabackup, which takes longer than 15 seconds. The session expires during this time, as the Actions.join_main_event_loop (consul_process, mysql_process) function is only started after a successful restore. As a small workaround, I have changed the TTL from 15 to 60 and everything looks great.

https://github.com/jnidzwetzki/mysql-ha-cloud/blob/86c0a55b484b2631d82ca8a5dca4044fd17f8696/mysql_cluster_manager/src/mcm/consul.py#L69

I don't know much about python, maybe the session refresh can be started as a background process at the beginning to get around the problem permanently

best regards 2peter3

jnidzwetzki commented 3 years ago

Hi @2peter3 ,

Thank you very much for the information. I was able to reproduce the issue and I made some changes to the code. The sessions are now automatically refreshed during long-running tasks such as backup creation and restore. Could you try if the latest development version fixes this problem in your installation?

Best Regards Jan

2peter3 commented 3 years ago

Hi @jnidzwetzki ,

I just tested the last version. The error has now been corrected. Thank you for your time and the quick response. Great repository :)

Best Regards 2peter3

jnidzwetzki commented 3 years ago

I am glad that I could help :)