Uploaded image for project: 'Percona XtraDB Cluster'
  1. Percona XtraDB Cluster
  2. PXC-3982

Getting error from Slave SQL thread when it is started before the PXC 8.0 node is ready to accept connections while joining the PXC cluster


    • Bug
    • Status: Done
    • Medium
    • Resolution: Fixed
    • 8.0.27-18 (Q4 2021)
    • 8.0.29-21 (Q2 2022)
    • None
    • Yes
    • Yes


      If a PXC node is also an asynchronous slave, the SQL thread may fail at startup if the node is not yet ready to join the cluster. To set this up, create a PXC cluster and make one node an asynchronous slave to a master. Then, on another PXC node and master node, let it receive writes from different databases:




      while [ 1 ];
        mysql d1 < data.sql;
        sleep 0.1;


      Another PXC node:


      while [ 1 ];
        mysql d2 < data.sql;
        sleep 0.1;



      Then, try to restart the PXC 8.0 node that is also asynchronous slave repeatedly until you get this error:

      2022-07-12T02:41:24.920734Z 9 [ERROR] [MY-010584] [Repl] Slave SQL for channel '': Error 'WSREP has not yet prepared node for application use' on query. Default database: 'employees'. Query: 'BEGIN', Error_code: MY-001047 2022-07-12T02:41:24.920850Z 9 [Warning] [MY-010584] [Repl] Slave: WSREP has not yet prepared node for application use Error_code: MY-001047 2022-07-12T02:41:24.920883Z 9 [ERROR] [MY-010586] [Repl] Error running query, slave SQL thread aborted. Fix the problem, and restart the slave SQL thread with "SLAVE START". We stopped at log 'mysql-bin.000004' position 23890123 2022-07-12T02:41:24.923467Z 2 [Note] [MY-000000] [Galera] Recording CC from sst: 296 2022-07-12T02:41:24.923566Z 2 [Note] [MY-000000] [Galera] Lowest cert index boundary for CC from sst: 296 2022-07-12T02:41:24.923630Z 2 [Note] [MY-000000] [Galera] Min available from gcache for CC from sst: 68 2022-07-12T02:41:24.923892Z 0 [Note] [MY-000000] [Galera] 2.0 (test-work): State transfer from 0.0 (test-work) complete. 2022-07-12T02:41:24.923929Z 0 [Note] [MY-000000] [Galera] SST leaving flow control 2022-07-12T02:41:24.923957Z 0 [Note] [MY-000000] [Galera] Shifting JOINER -> JOINED (TO: 296) 2022-07-12T02:41:24.924299Z 0 [Note] [MY-000000] [Galera] Member 2.0 (test-work) synced with group. 2022-07-12T02:41:24.924323Z 0 [Note] [MY-000000] [Galera] Shifting JOINED -> SYNCED (TO: 296) 2022-07-12T02:41:24.924381Z 2 [Note] [MY-000000] [Galera] Server test-work synced with group 2022-07-12T02:41:24.924434Z 2 [Note] [MY-000000] [WSREP] Server status change joined -> synced 2022-07-12T02:41:24.924508Z 2 [Note] [MY-000000] [WSREP] Synchronized with group, ready for connections 2022-07-12T02:41:24.924559Z 2 [Note] [MY-000000] [WSREP] wsrep_notify_cmd is not defined, skipping notification.

      As stated above that you need to test repeatedly because I cannot consistently get the Slave SQL thread to start before the the node is ready.

      On the other hand, in PXC 5.7 it seems that Slave SQL thread is started after the node is ready to receive connections:

      2022-07-12T03:15:31.139508Z 3 [Note] Slave I/O thread for channel '': connected to master '[email protected]:20541',replication started in log 'mysql-bin.000002' at position 464635733 2022-07-12T03:15:31.152385Z 0 [Note] Event Scheduler: Loaded 0 events 2022-07-12T03:15:31.158387Z 0 [Note] WSREP: Signalling provider to continue on SST completion. 2022-07-12T03:15:31.158445Z 0 [Note] WSREP: Initialized wsrep sidno 3 2022-07-12T03:15:31.158493Z 0 [Note] WSREP: SST received: f16aa510-018c-11ed-a03b-97efe1fe04a0:2039 2022-07-12T03:15:31.158725Z 0 [Note] /home/test/opt/percona-xtradb-cluster/5.7.38/bin/mysqld: ready for connections. Version: '5.7.38-41-59-log' socket: '/tmp/mysql_sandbox27541.sock' port: 27541 Percona XtraDB Cluster binary (GPL) 5.7.38-rel41-59, Revision 37a6216, wsrep_31.59 2022-07-12T03:15:31.170359Z 1 [Note] WSREP: Receiving IST: 973 writesets, seqnos 2039-3012 2022-07-12T03:15:31.170632Z 0 [Note] WSREP: Receiving IST... 0.0% ( 0/973 events) complete. 2022-07-12T03:15:41.252819Z 0 [Note] WSREP: Receiving IST... 97.0% (944/973 events) complete. 2022-07-12T03:15:46.326208Z 0 [Note] WSREP: Receiving IST...100.0% (973/973 events) complete. 2022-07-12T03:15:46.326555Z 1 [Note] WSREP: IST received: f16aa510-018c-11ed-a03b-97efe1fe04a0:3012 2022-07-12T03:15:46.327181Z 0 [Note] WSREP: 2.0 (test-work): State transfer from 1.0 (test-work) complete. 2022-07-12T03:15:46.327201Z 0 [Note] WSREP: SST leaving flow control 2022-07-12T03:15:46.327211Z 0 [Note] WSREP: Shifting JOINER -> JOINED (TO: 3062) 2022-07-12T03:15:46.327509Z 0 [Note] WSREP: Member 2.0 (test-work) synced with group. 2022-07-12T03:15:46.327527Z 0 [Note] WSREP: Shifting JOINED -> SYNCED (TO: 3062) 2022-07-12T03:15:53.841359Z 1 [Note] WSREP: Synchronized with group, ready for connections 2022-07-12T03:15:53.841402Z 1 [Note] WSREP: Setting wsrep_ready to true 2022-07-12T03:15:53.841417Z 1 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification. 2022-07-12T03:15:53.841426Z 4 [Note] Slave SQL thread for channel '' initialized, starting replication in log 'mysql-bin.000002' at position 464635733, relay log './mysql-relay.000009' position: 4





            kamil.holubicki Kamil Holubicki
            jaime.sicam@percona.com Jaime Sicam
            0 Vote for this issue
            2 Start watching this issue



              Smart Checklist