[MDEV-15453] IST failed during upgrade of version and SST failed too from 10.2.12 to 10.2.13 - Jira

Details

Type: Bug
Status: Closed (View Workflow)
Priority: Major
Resolution: Cannot Reproduce
Affects Version/s: 10.2.13
Fix Version/s: N/A
Component/s: Galera, Galera SST
Labels:
- galera
Environment:
one master , one galera cluster on slave with 10.2.12 under Debian 9.3. We try to upgrade the galera cluster 10.2.12 to 10.2.13

Description

Hello I tried to upgrade one galera cluster behind on master.

they way : upgrade node by node and reconnect to the cluster.
(SST method : Xtrabackup)

1) upgraded the node 3 who is slave (no problem, no event on cluster)
2) we let replication, we disconect the node 2 we upgrade MariaDB from 10.2.12 to 10.2.13
(maybe one or 2 minutes)
impossible to rejoin the cluster IST failed, so SST and SST failed.
3) stop the slave on slave 1, remove node 3 from cluster, upgrade to 10.2.13 reconnect to cluster, everthing fine.

2018-03-02 10:47:43 140596706543808 [Note] WSREP: GCache history reset: 6b51589d-0b5f-11e8-94e6-82aa9d3be300:0 -> 6b51589d-0b5f-11e8-94e6-82aa9d3be300:467319538

2018-03-02 10:47:43 140596706543808 [Note] WSREP: Assign initial position for certification: 467319538, protocol version: -1

2018-03-02 10:47:43 140596706543808 [Note] WSREP: wsrep_sst_grab()

2018-03-02 10:47:43 140596706543808 [Note] WSREP: Start replication

2018-03-02 10:47:43 140596706543808 [Note] WSREP: Setting initial position to 6b51589d-0b5f-11e8-94e6-82aa9d3be300:467319538

2018-03-02 10:47:43 140596706543808 [Note] WSREP: protonet asio version 0

2018-03-02 10:47:43 140596706543808 [Note] WSREP: Using CRC-32C for message checksums.

2018-03-02 10:47:43 140596706543808 [Note] WSREP: backend: asio

2018-03-02 10:47:43 140596706543808 [Note] WSREP: gcomm thread scheduling priority set to other:0

2018-03-02 10:47:43 140596706543808 [Warning] WSREP: access file(/RDC/mysql/data//gvwstate.dat) failed(No such file or directory)

2018-03-02 10:47:43 140596706543808 [Note] WSREP: restore pc from disk failed

2018-03-02 10:47:43 140596706543808 [Note] WSREP: GMCast version 0

2018-03-02 10:47:43 140596706543808 [Note] WSREP: (c144d827, 'tcp://0.0.0.0:4567') listening at tcp://0.0.0.0:4567

2018-03-02 10:47:43 140596706543808 [Note] WSREP: (c144d827, 'tcp://0.0.0.0:4567') multicast: , ttl: 1

2018-03-02 10:47:43 140596706543808 [Note] WSREP: EVS version 0

2018-03-02 10:47:43 140596706543808 [Note] WSREP: gcomm: connecting to group 'rdc-cluster-1', peer '10.241.5.221:,10.241.5.222:,10.241.5.220:'

2018-03-02 10:47:43 140596706543808 [Note] WSREP: (c144d827, 'tcp://0.0.0.0:4567') connection established to c144d827 tcp://10.241.5.221:4567

2018-03-02 10:47:43 140596706543808 [Warning] WSREP: (c144d827, 'tcp://0.0.0.0:4567') address 'tcp://10.241.5.221:4567' points to own listening address, blacklisting

2018-03-02 10:47:43 140596706543808 [Note] WSREP: (c144d827, 'tcp://0.0.0.0:4567') connection established to 40c1e704 tcp://10.241.5.220:4567

2018-03-02 10:47:43 140596706543808 [Note] WSREP: (c144d827, 'tcp://0.0.0.0:4567') turning message relay requesting on, nonlive peers:

2018-03-02 10:47:43 140596706543808 [Note] WSREP: (c144d827, 'tcp://0.0.0.0:4567') connection established to 0a0faad9 tcp://10.241.5.222:4567

2018-03-02 10:47:44 140596706543808 [Note] WSREP: declaring 0a0faad9 at tcp://10.241.5.222:4567 stable

2018-03-02 10:47:44 140596706543808 [Note] WSREP: declaring 40c1e704 at tcp://10.241.5.220:4567 stable

2018-03-02 10:47:44 140596706543808 [Note] WSREP: Node 0a0faad9 state prim

2018-03-02 10:47:44 140596706543808 [Note] WSREP: view(view_id(PRIM,0a0faad9,23) memb {

        0a0faad9,0

        40c1e704,0

        c144d827,0

} joined {

} left {

} partitioned {

})

2018-03-02 10:47:44 140596706543808 [Note] WSREP: save pc into disk

2018-03-02 10:47:44 140596706543808 [Note] WSREP: gcomm: connected

2018-03-02 10:47:44 140596706543808 [Note] WSREP: Changing maximum packet size to 64500, resulting msg size: 32636

2018-03-02 10:47:44 140596706543808 [Note] WSREP: Shifting CLOSED -> OPEN (TO: 0)

2018-03-02 10:47:44 140596706543808 [Note] WSREP: Opened channel 'rdc-cluster-1'

2018-03-02 10:47:44 140596507354880 [Note] WSREP: New COMPONENT: primary = yes, bootstrap = no, my_idx = 2, memb_num = 3

2018-03-02 10:47:44 140596706543808 [Note] WSREP: Waiting for SST to complete.

2018-03-02 10:47:44 140596507354880 [Note] WSREP: STATE EXCHANGE: Waiting for state UUID.

2018-03-02 10:47:44 140596507354880 [Note] WSREP: STATE EXCHANGE: sent state msg: c191bd3a-1dfe-11e8-b54c-4f0a6cf28162

2018-03-02 10:47:44 140596507354880 [Note] WSREP: STATE EXCHANGE: got state msg: c191bd3a-1dfe-11e8-b54c-4f0a6cf28162 from 0 (hb01-galera-cl01-03)

2018-03-02 10:47:44 140596507354880 [Note] WSREP: STATE EXCHANGE: got state msg: c191bd3a-1dfe-11e8-b54c-4f0a6cf28162 from 1 (hb01-galera-cl01-01)

2018-03-02 10:47:44 140596507354880 [Note] WSREP: STATE EXCHANGE: got state msg: c191bd3a-1dfe-11e8-b54c-4f0a6cf28162 from 2 (hb01-galera-cl01-02)

2018-03-02 10:47:44 140596507354880 [Note] WSREP: Quorum results:

        version    = 4,

        component  = PRIMARY,

        conf_id    = 22,

        members    = 2/3 (joined/total),

        act_id     = 467382351,

        last_appl. = -1,

        protocols  = 0/7/3 (gcs/repl/appl),

        group UUID = 6b51589d-0b5f-11e8-94e6-82aa9d3be300

2018-03-02 10:47:44 140596507354880 [Note] WSREP: Flow-control interval: [28, 28]

2018-03-02 10:47:44 140596507354880 [Note] WSREP: Trying to continue unpaused monitor

2018-03-02 10:47:44 140596507354880 [Note] WSREP: Shifting OPEN -> PRIMARY (TO: 467382351)

2018-03-02 10:47:44 140596498659072 [Note] WSREP: State transfer required:

        Group state: 6b51589d-0b5f-11e8-94e6-82aa9d3be300:467382351

        Local state: 6b51589d-0b5f-11e8-94e6-82aa9d3be300:467319538

2018-03-02 10:47:44 140596498659072 [Note] WSREP: New cluster view: global state: 6b51589d-0b5f-11e8-94e6-82aa9d3be300:467382351, view# 23: Primary, number of nodes: 3, my index: 2, protocol version 3

2018-03-02 10:47:44 140596498659072 [Warning] WSREP: Gap in state sequence. Need state transfer.

2018-03-02 10:47:44 140574950680320 [Note] WSREP: Running: 'wsrep_sst_xtrabackup-v2 --role 'joiner' --address '10.241.5.221' --datadir '/RDC/mysql/data/'   --parent '21401' --binlog '/RDC/mysql/binlog/mariadb-bin' '

WSREP_SST: [INFO] Logging all stderr of SST/Innobackupex to syslog (20180302 10:47:44.863)

2018-03-02 10:47:46 140596515747584 [Note] WSREP: (c144d827, 'tcp://0.0.0.0:4567') connection to peer c144d827 with addr tcp://10.241.5.221:4567 timed out, no messages seen in PT3S

2018-03-02 10:47:47 140596515747584 [Note] WSREP: (c144d827, 'tcp://0.0.0.0:4567') turning message relay requesting off

2018-03-02 10:49:13 140574950680320 [ERROR] WSREP: Failed to read 'ready <addr>' from: wsrep_sst_xtrabackup-v2 --role 'joiner' --address '10.241.5.221' --datadir '/RDC/mysql/data/'   --parent '21401' --binlog '/RDC/mysql/binlog/mariadb-bin'

        Read: '(null)'

2018-03-02 10:49:13 140574950680320 [ERROR] WSREP: Process was aborted.

2018-03-02 10:49:13 140574950680320 [ERROR] WSREP: Process completed with error: wsrep_sst_xtrabackup-v2 --role 'joiner' --address '10.241.5.221' --datadir '/RDC/mysql/data/'   --parent '21401' --binlog '/RDC/mysql/binlog/mariadb-bin' : 2 (No such file or directory)

2018-03-02 10:49:13 140596498659072 [ERROR] WSREP: Failed to prepare for 'xtrabackup-v2' SST. Unrecoverable.

2018-03-02 10:49:13 140596498659072 [ERROR] Aborting

Error in my_thread_global_end(): 1 threads didn't exit

2018-03-02 11:06:51 139691983460544 [Note] WSREP: Read nil XID from storage engines, skipping position init

2018-03-02 11:06:51 139691983460544 [Note] WSREP: wsrep_load(): loading provider library '/usr/lib/galera/libgalera_smm.so'

2018-03-02 11:06:51 139691983460544 [Note] WSREP: wsrep_load(): Galera 25.3.23(r3789) by Codership Oy <info@codership.com> loaded successfully.

2018-03-02 11:06:51 139691983460544 [Note] WSREP: CRC-32C: using hardware acceleration.

2018-03-02 11:06:51 139691983460544 [Note] WSREP: Found saved state: 6b51589d-0b5f-11e8-94e6-82aa9d3be300:-1, safe_to_bootstrap: 0

2018-03-02 11:06:51 139691983460544 [Note] WSREP: Passing config to GCS: base_dir = /RDC/mysql/data/; base_host = 10.241.5.221; base_port = 4567; cert.log_conflicts = no; debug = no; evs.auto_evict = 0; evs.delay_margin = PT1S; evs.delayed_keep_period = PT30S; evs.inactive_check_period = PT0.5S; evs.inactive_timeout = PT15S; evs.join_retrans_period = PT1S; evs.max_install_timeouts = 3; evs.send_window = 4; evs.stats_report_period = PT1M; evs.suspect_timeout = PT5S; evs.user_send_window = 2; evs.view_forget_timeout = PT24H; gcache.dir = /RDC/mysql/data/; gcache.keep_pages_size = 0; gcache.mem_size = 0; gcache.name = /RDC/mysql/data//galera.cache; gcache.page_size = 128M; gcache.recover = no; gcache.size = 20G; gcomm.thread_prio = ; gcs.fc_debug = 0; gcs.fc_factor = 1.0; gcs.fc_limit = 16; gcs.fc_master_slave = no; gcs.max_packet_size = 64500; gcs.max_throttle = 0.25; gcs.recv_q_hard_limit = 9223372036854775807; gcs.recv_q_soft_limit = 0.25; gcs.sync_donor = no; gmcast.segment = 0; gmcast.version = 0; pc.announce_timeout = PT3S; pc.checksum = false; pc

2018-03-02 11:06:51 139691983460544 [Note] WSREP: GCache history reset: 6b51589d-0b5f-11e8-94e6-82aa9d3be300:0 -> 6b51589d-0b5f-11e8-94e6-82aa9d3be300:467319538

2018-03-02 11:06:51 139691983460544 [Note] WSREP: Assign initial position for certification: 467319538, protocol version: -1

2018-03-02 11:06:51 139691983460544 [Note] WSREP: wsrep_sst_grab()

2018-03-02 11:06:51 139691983460544 [Note] WSREP: Start replication

2018-03-02 11:06:51 139691983460544 [Note] WSREP: Setting initial position to 6b51589d-0b5f-11e8-94e6-82aa9d3be300:467319538

2018-03-02 11:06:51 139691983460544 [Note] WSREP: protonet asio version 0

2018-03-02 11:06:51 139691983460544 [Note] WSREP: Using CRC-32C for message checksums.

2018-03-02 11:06:51 139691983460544 [Note] WSREP: backend: asio

2018-03-02 11:06:51 139691983460544 [Note] WSREP: gcomm thread scheduling priority set to other:0

2018-03-02 11:06:51 139691983460544 [Warning] WSREP: access file(/RDC/mysql/data//gvwstate.dat) failed(No such file or directory)

2018-03-02 11:06:51 139691983460544 [Note] WSREP: restore pc from disk failed

2018-03-02 11:06:51 139691983460544 [Note] WSREP: GMCast version 0

2018-03-02 11:06:51 139691983460544 [Note] WSREP: (6d87b0f9, 'tcp://0.0.0.0:4567') listening at tcp://0.0.0.0:4567

2018-03-02 11:06:51 139691983460544 [Note] WSREP: (6d87b0f9, 'tcp://0.0.0.0:4567') multicast: , ttl: 1

2018-03-02 11:06:51 139691983460544 [Note] WSREP: EVS version 0

2018-03-02 11:06:51 139691983460544 [Note] WSREP: gcomm: connecting to group 'rdc-cluster-1', peer '10.241.5.221:,10.241.5.222:,10.241.5.220:'

2018-03-02 11:06:51 139691983460544 [Note] WSREP: (6d87b0f9, 'tcp://0.0.0.0:4567') connection established to 6d87b0f9 tcp://10.241.5.221:4567

2018-03-02 11:06:51 139691983460544 [Warning] WSREP: (6d87b0f9, 'tcp://0.0.0.0:4567') address 'tcp://10.241.5.221:4567' points to own listening address, blacklisting

2018-03-02 11:06:51 139691983460544 [Note] WSREP: (6d87b0f9, 'tcp://0.0.0.0:4567') connection established to 40c1e704 tcp://10.241.5.220:4567

2018-03-02 11:06:51 139691983460544 [Note] WSREP: (6d87b0f9, 'tcp://0.0.0.0:4567') turning message relay requesting on, nonlive peers:

2018-03-02 11:06:51 139691983460544 [Note] WSREP: (6d87b0f9, 'tcp://0.0.0.0:4567') connection established to 0a0faad9 tcp://10.241.5.222:4567

2018-03-02 11:06:51 139691983460544 [Note] WSREP: declaring 0a0faad9 at tcp://10.241.5.222:4567 stable

2018-03-02 11:06:51 139691983460544 [Note] WSREP: declaring 40c1e704 at tcp://10.241.5.220:4567 stable

2018-03-02 11:06:51 139691983460544 [Note] WSREP: Node 0a0faad9 state prim

2018-03-02 11:06:51 139691983460544 [Note] WSREP: view(view_id(PRIM,0a0faad9,25) memb {

        0a0faad9,0

        40c1e704,0

        6d87b0f9,0

} joined {

} left {

} partitioned {

})

2018-03-02 11:06:51 139691983460544 [Note] WSREP: save pc into disk

2018-03-02 11:06:52 139691983460544 [Note] WSREP: gcomm: connected

2018-03-02 11:06:52 139691983460544 [Note] WSREP: Changing maximum packet size to 64500, resulting msg size: 32636

2018-03-02 11:06:52 139691983460544 [Note] WSREP: Shifting CLOSED -> OPEN (TO: 0)

2018-03-02 11:06:52 139691983460544 [Note] WSREP: Opened channel 'rdc-cluster-1'

2018-03-02 11:06:52 139670239299328 [Note] WSREP: New COMPONENT: primary = yes, bootstrap = no, my_idx = 2, memb_num = 3

2018-03-02 11:06:52 139670239299328 [Note] WSREP: STATE EXCHANGE: Waiting for state UUID.

2018-03-02 11:06:52 139691983460544 [Note] WSREP: Waiting for SST to complete.

2018-03-02 11:06:52 139670239299328 [Note] WSREP: STATE EXCHANGE: sent state msg: 6d8f82e8-1e01-11e8-b761-8af7ed4b3c00

2018-03-02 11:06:52 139670239299328 [Note] WSREP: STATE EXCHANGE: got state msg: 6d8f82e8-1e01-11e8-b761-8af7ed4b3c00 from 0 (hb01-galera-cl01-03)

2018-03-02 11:06:52 139670239299328 [Note] WSREP: STATE EXCHANGE: got state msg: 6d8f82e8-1e01-11e8-b761-8af7ed4b3c00 from 1 (hb01-galera-cl01-01)

2018-03-02 11:06:52 139670239299328 [Note] WSREP: STATE EXCHANGE: got state msg: 6d8f82e8-1e01-11e8-b761-8af7ed4b3c00 from 2 (hb01-galera-cl01-02)

2018-03-02 11:06:52 139670239299328 [Note] WSREP: Quorum results:

        version    = 4,

        component  = PRIMARY,

        conf_id    = 24,

        members    = 2/3 (joined/total),

        act_id     = 467641595,

        last_appl. = -1,

        protocols  = 0/7/3 (gcs/repl/appl),

        group UUID = 6b51589d-0b5f-11e8-94e6-82aa9d3be300

2018-03-02 11:06:52 139670239299328 [Note] WSREP: Flow-control interval: [28, 28]

2018-03-02 11:06:52 139670239299328 [Note] WSREP: Trying to continue unpaused monitor

2018-03-02 11:06:52 139670239299328 [Note] WSREP: Shifting OPEN -> PRIMARY (TO: 467641595)

2018-03-02 11:06:52 139691800753920 [Note] WSREP: State transfer required:

        Group state: 6b51589d-0b5f-11e8-94e6-82aa9d3be300:467641595

        Local state: 6b51589d-0b5f-11e8-94e6-82aa9d3be300:467319538

2018-03-02 11:06:52 139691800753920 [Note] WSREP: New cluster view: global state: 6b51589d-0b5f-11e8-94e6-82aa9d3be300:467641595, view# 25: Primary, number of nodes: 3, my index: 2, protocol version 3

2018-03-02 11:06:52 139691800753920 [Warning] WSREP: Gap in state sequence. Need state transfer.

2018-03-02 11:06:52 139670230906624 [Note] WSREP: Running: 'wsrep_sst_xtrabackup-v2 --role 'joiner' --address '10.241.5.221' --datadir '/RDC/mysql/data/'   --parent '24625' --binlog '/RDC/mysql/binlog/mariadb-bin' '

WSREP_SST: [INFO] Logging all stderr of SST/Innobackupex to syslog (20180302 11:06:52.380)

2018-03-02 11:06:54 139670247692032 [Note] WSREP: (6d87b0f9, 'tcp://0.0.0.0:4567') connection to peer 6d87b0f9 with addr tcp://10.241.5.221:4567 timed out, no messages seen in PT3S

2018-03-02 11:06:55 139670247692032 [Note] WSREP: (6d87b0f9, 'tcp://0.0.0.0:4567') turning message relay requesting off

2018-03-02 11:08:21 139670230906624 [ERROR] WSREP: Failed to read 'ready <addr>' from: wsrep_sst_xtrabackup-v2 --role 'joiner' --address '10.241.5.221' --datadir '/RDC/mysql/data/'   --parent '24625' --binlog '/RDC/mysql/binlog/mariadb-bin'

        Read: '(null)'

2018-03-02 11:08:21 139670230906624 [ERROR] WSREP: Process was aborted.

2018-03-02 11:08:21 139670230906624 [ERROR] WSREP: Process completed with error: wsrep_sst_xtrabackup-v2 --role 'joiner' --address '10.241.5.221' --datadir '/RDC/mysql/data/'   --parent '24625' --binlog '/RDC/mysql/binlog/mariadb-bin' : 2 (No such file or directory)

2018-03-02 11:08:21 139691800753920 [ERROR] WSREP: Failed to prepare for 'xtrabackup-v2' SST. Unrecoverable.

2018-03-02 11:08:21 139691800753920 [ERROR] Aborting

Error in my_thread_global_end(): 1 threads didn't exit

2018-03-02 11:15:16 140552530852032 [Note] WSREP: Read nil XID from storage engines, skipping position init

2018-03-02 11:15:16 140552530852032 [Note] WSREP: wsrep_load(): loading provider library '/usr/lib/galera/libgalera_smm.so'

2018-03-02 11:15:16 140552530852032 [Note] WSREP: wsrep_load(): Galera 25.3.23(r3789) by Codership Oy <info@codership.com> loaded successfully.

2018-03-02 11:15:16 140552530852032 [Note] WSREP: CRC-32C: using hardware acceleration.

2018-03-02 11:15:16 140552530852032 [Warning] WSREP: Could not open state file for reading: '/RDC/mysql/data//grastate.dat'

2018-03-02 11:15:16 140552530852032 [Note] WSREP: Found saved state: 00000000-0000-0000-0000-000000000000:-1, safe_to_bootstrap: 1

2018-03-02 11:15:16 140552530852032 [Note] WSREP: Passing config to GCS: base_dir = /RDC/mysql/data/; base_host = 10.241.5.221; base_port = 4567; cert.log_conflicts = no; debug = no; evs.auto_evict = 0; evs.delay_margin = PT1S; evs.delayed_keep_period = PT30S; evs.inactive_check_period = PT0.5S; evs.inactive_timeout = PT15S; evs.join_retrans_period = PT1S; evs.max_install_timeouts = 3; evs.send_window = 4; evs.stats_report_period = PT1M; evs.suspect_timeout = PT5S; evs.user_send_window = 2; evs.view_forget_timeout = PT24H; gcache.dir = /RDC/mysql/data/; gcache.keep_pages_size = 0; gcache.mem_size = 0; gcache.name = /RDC/mysql/data//galera.cache; gcache.page_size = 128M; gcache.recover = no; gcache.size = 20G; gcomm.thread_prio = ; gcs.fc_debug = 0; gcs.fc_factor = 1.0; gcs.fc_limit = 16; gcs.fc_master_slave = no; gcs.max_packet_size = 64500; gcs.max_throttle = 0.25; gcs.recv_q_hard_limit = 9223372036854775807; gcs.recv_q_soft_limit = 0.25; gcs.sync_donor = no; gmcast.segment = 0; gmcast.version = 0; pc.announce_timeout = PT3S; pc.checksum = false; pc

2018-03-02 11:15:16 140552530852032 [Note] WSREP: GCache history reset: 00000000-0000-0000-0000-000000000000:0 -> 00000000-0000-0000-0000-000000000000:-1

2018-03-02 11:15:16 140552530852032 [Note] WSREP: Assign initial position for certification: -1, protocol version: -1

2018-03-02 11:15:16 140552530852032 [Note] WSREP: wsrep_sst_grab()

2018-03-02 11:15:16 140552530852032 [Note] WSREP: Start replication

2018-03-02 11:15:16 140552530852032 [Note] WSREP: Setting initial position to 00000000-0000-0000-0000-000000000000:-1

2018-03-02 11:15:16 140552530852032 [Note] WSREP: protonet asio version 0

2018-03-02 11:15:16 140552530852032 [Note] WSREP: Using CRC-32C for message checksums.

2018-03-02 11:15:16 140552530852032 [Note] WSREP: backend: asio

2018-03-02 11:15:16 140552530852032 [Note] WSREP: gcomm thread scheduling priority set to other:0

2018-03-02 11:15:16 140552530852032 [Warning] WSREP: access file(/RDC/mysql/data//gvwstate.dat) failed(No such file or directory)

2018-03-02 11:15:16 140552530852032 [Note] WSREP: restore pc from disk failed

2018-03-02 11:15:16 140552530852032 [Note] WSREP: GMCast version 0

2018-03-02 11:15:16 140552530852032 [Note] WSREP: (9a6e409c, 'tcp://0.0.0.0:4567') listening at tcp://0.0.0.0:4567

2018-03-02 11:15:16 140552530852032 [Note] WSREP: (9a6e409c, 'tcp://0.0.0.0:4567') multicast: , ttl: 1

2018-03-02 11:15:16 140552530852032 [Note] WSREP: EVS version 0

2018-03-02 11:15:16 140552530852032 [Note] WSREP: gcomm: connecting to group 'rdc-cluster-1', peer '10.241.5.221:,10.241.5.222:,10.241.5.220:'

2018-03-02 11:15:16 140552530852032 [Note] WSREP: (9a6e409c, 'tcp://0.0.0.0:4567') connection established to 9a6e409c tcp://10.241.5.221:4567

2018-03-02 11:15:16 140552530852032 [Warning] WSREP: (9a6e409c, 'tcp://0.0.0.0:4567') address 'tcp://10.241.5.221:4567' points to own listening address, blacklisting

2018-03-02 11:15:16 140552530852032 [Note] WSREP: (9a6e409c, 'tcp://0.0.0.0:4567') connection established to 40c1e704 tcp://10.241.5.220:4567

2018-03-02 11:15:16 140552530852032 [Note] WSREP: (9a6e409c, 'tcp://0.0.0.0:4567') turning message relay requesting on, nonlive peers:

2018-03-02 11:15:16 140552530852032 [Note] WSREP: (9a6e409c, 'tcp://0.0.0.0:4567') connection established to 0a0faad9 tcp://10.241.5.222:4567

2018-03-02 11:15:16 140552530852032 [Note] WSREP: declaring 0a0faad9 at tcp://10.241.5.222:4567 stable

2018-03-02 11:15:16 140552530852032 [Note] WSREP: declaring 40c1e704 at tcp://10.241.5.220:4567 stable

2018-03-02 11:15:16 140552530852032 [Note] WSREP: Node 0a0faad9 state prim

2018-03-02 11:15:16 140552530852032 [Note] WSREP: view(view_id(PRIM,0a0faad9,27) memb {

        0a0faad9,0

        40c1e704,0

        9a6e409c,0

} joined {

} left {

} partitioned {

})

2018-03-02 11:15:16 140552530852032 [Note] WSREP: save pc into disk

2018-03-02 11:15:16 140552530852032 [Note] WSREP: gcomm: connected

2018-03-02 11:15:16 140552530852032 [Note] WSREP: Changing maximum packet size to 64500, resulting msg size: 32636

2018-03-02 11:15:16 140552530852032 [Note] WSREP: Shifting CLOSED -> OPEN (TO: 0)

2018-03-02 11:15:16 140552530852032 [Note] WSREP: Opened channel 'rdc-cluster-1'

2018-03-02 11:15:16 140530784655104 [Note] WSREP: New COMPONENT: primary = yes, bootstrap = no, my_idx = 2, memb_num = 3

2018-03-02 11:15:16 140552530852032 [Note] WSREP: Waiting for SST to complete.

2018-03-02 11:15:16 140530784655104 [Note] WSREP: STATE EXCHANGE: Waiting for state UUID.

2018-03-02 11:15:16 140530784655104 [Note] WSREP: STATE EXCHANGE: sent state msg: 9a6ee7ea-1e02-11e8-9075-071fb0408cc9

2018-03-02 11:15:16 140530784655104 [Note] WSREP: STATE EXCHANGE: got state msg: 9a6ee7ea-1e02-11e8-9075-071fb0408cc9 from 0 (hb01-galera-cl01-03)

2018-03-02 11:15:16 140530784655104 [Note] WSREP: STATE EXCHANGE: got state msg: 9a6ee7ea-1e02-11e8-9075-071fb0408cc9 from 1 (hb01-galera-cl01-01)

2018-03-02 11:15:16 140530784655104 [Note] WSREP: STATE EXCHANGE: got state msg: 9a6ee7ea-1e02-11e8-9075-071fb0408cc9 from 2 (hb01-galera-cl01-02)

2018-03-02 11:15:16 140530784655104 [Note] WSREP: Quorum results:

        version    = 4,

        component  = PRIMARY,

        conf_id    = 26,

        members    = 2/3 (joined/total),

        act_id     = 467915709,

        last_appl. = -1,

        protocols  = 0/7/3 (gcs/repl/appl),

        group UUID = 6b51589d-0b5f-11e8-94e6-82aa9d3be300

2018-03-02 11:15:16 140530784655104 [Note] WSREP: Flow-control interval: [28, 28]

2018-03-02 11:15:16 140530784655104 [Note] WSREP: Trying to continue unpaused monitor

2018-03-02 11:15:16 140530784655104 [Note] WSREP: Shifting OPEN -> PRIMARY (TO: 467915709)

2018-03-02 11:15:16 140552339752704 [Note] WSREP: State transfer required:

        Group state: 6b51589d-0b5f-11e8-94e6-82aa9d3be300:467915709

        Local state: 00000000-0000-0000-0000-000000000000:-1

2018-03-02 11:15:16 140552339752704 [Note] WSREP: New cluster view: global state: 6b51589d-0b5f-11e8-94e6-82aa9d3be300:467915709, view# 27: Primary, number of nodes: 3, my index: 2, protocol version 3

2018-03-02 11:15:16 140552339752704 [Warning] WSREP: Gap in state sequence. Need state transfer.

2018-03-02 11:15:16 140530776262400 [Note] WSREP: Running: 'wsrep_sst_xtrabackup-v2 --role 'joiner' --address '10.241.5.221' --datadir '/RDC/mysql/data/'   --parent '26402' --binlog '/RDC/mysql/binlog/mariadb-bin' '

WSREP_SST: [INFO] Logging all stderr of SST/Innobackupex to syslog (20180302 11:15:17.186)

2018-03-02 11:15:19 140530793047808 [Note] WSREP: (9a6e409c, 'tcp://0.0.0.0:4567') connection to peer 9a6e409c with addr tcp://10.241.5.221:4567 timed out, no messages seen in PT3S

2018-03-02 11:15:19 140530793047808 [Note] WSREP: (9a6e409c, 'tcp://0.0.0.0:4567') turning message relay requesting off

2018-03-02 11:16:46 140530776262400 [ERROR] WSREP: Failed to read 'ready <addr>' from: wsrep_sst_xtrabackup-v2 --role 'joiner' --address '10.241.5.221' --datadir '/RDC/mysql/data/'   --parent '26402' --binlog '/RDC/mysql/binlog/mariadb-bin'

        Read: '(null)'

2018-03-02 11:16:46 140530776262400 [ERROR] WSREP: Process was aborted.

2018-03-02 11:16:46 140530776262400 [ERROR] WSREP: Process completed with error: wsrep_sst_xtrabackup-v2 --role 'joiner' --address '10.241.5.221' --datadir '/RDC/mysql/data/'   --parent '26402' --binlog '/RDC/mysql/binlog/mariadb-bin' : 2 (No such file or directory)

2018-03-02 11:16:46 140552339752704 [ERROR] WSREP: Failed to prepare for 'xtrabackup-v2' SST. Unrecoverable.

2018-03-02 11:16:46 140552339752704 [ERROR] Aborting

Error in my_thread_global_end(): 1 threads didn't exit

2018-03-02 11:45:51 140065529612480 [Note] WSREP: Read nil XID from storage engines, skipping position init

2018-03-02 11:45:51 140065529612480 [Note] WSREP: wsrep_load(): loading provider library 'none'

2018-03-02 11:45:51 140065529612480 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins

2018-03-02 11:45:51 140065529612480 [Note] InnoDB: Uses event mutexes

2018-03-02 11:45:51 140065529612480 [Note] InnoDB: Compressed tables use zlib 1.2.8

2018-03-02 11:45:51 140065529612480 [Note] InnoDB: Using Linux native AIO

2018-03-02 11:45:51 140065529612480 [Note] InnoDB: Number of pools: 1

2018-03-02 11:45:51 140065529612480 [Note] InnoDB: Using SSE2 crc32 instructions

2018-03-02 11:45:51 140065529612480 [Note] InnoDB: Initializing buffer pool, total size = 378G, instances = 8, chunk size = 128M

2018-03-02 11:46:02 140065529612480 [Note] InnoDB: Completed initialization of buffer pool

2018-03-02 11:46:02 139632422274816 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().

2018-03-02 11:46:02 140065529612480 [Note] InnoDB: Highest supported file format is Barracuda.

2018-03-02 11:46:04 140065529612480 [Note] InnoDB: 128 out of 128 rollback segments are active.

2018-03-02 11:46:04 140065529612480 [Note] InnoDB: Creating shared tablespace for temporary tables

2018-03-02 11:46:04 140065529612480 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...

2018-03-02 11:46:04 140065529612480 [Note] InnoDB: File './ibtmp1' size is now 12 MB.

2018-03-02 11:46:04 140065529612480 [Note] InnoDB: Waiting for purge to start

2018-03-02 11:46:04 140065529612480 [Note] InnoDB: 5.7.21 started; log sequence number 1619267

2018-03-02 11:46:04 139641726428928 [Note] InnoDB: Loading buffer pool(s) from /RDC/mysql/data/ib_buffer_pool

2018-03-02 11:46:04 139641726428928 [Note] InnoDB: Buffer pool(s) load completed at 180302 11:46:04

2018-03-02 11:46:04 140065529612480 [Note] Plugin 'FEEDBACK' is disabled.

2018-03-02 11:46:48 140111382202560 [Note] WSREP: Read nil XID from storage engines, skipping position init

2018-03-02 11:46:48 140111382202560 [Note] WSREP: wsrep_load(): loading provider library '/usr/lib/galera/libgalera_smm.so'

2018-03-02 11:46:48 140111382202560 [Note] WSREP: wsrep_load(): Galera 25.3.23(r3789) by Codership Oy <info@codership.com> loaded successfully.

2018-03-02 11:46:48 140111382202560 [Note] WSREP: CRC-32C: using hardware acceleration.

2018-03-02 11:46:48 140111382202560 [Note] WSREP: Found saved state: 00000000-0000-0000-0000-000000000000:-1, safe_to_bootstrap: 1

2018-03-02 11:46:48 140111382202560 [Note] WSREP: Passing config to GCS: base_dir = /RDC/mysql/data/; base_host = 10.241.5.221; base_port = 4567; cert.log_conflicts = no; debug = no; evs.auto_evict = 0; evs.delay_margin = PT1S; evs.delayed_keep_period = PT30S; evs.inactive_check_period = PT0.5S; evs.inactive_timeout = PT15S; evs.join_retrans_period = PT1S; evs.max_install_timeouts = 3; evs.send_window = 4; evs.stats_report_period = PT1M; evs.suspect_timeout = PT5S; evs.user_send_window = 2; evs.view_forget_timeout = PT24H; gcache.dir = /RDC/mysql/data/; gcache.keep_pages_size = 0; gcache.mem_size = 0; gcache.name = /RDC/mysql/data//galera.cache; gcache.page_size = 128M; gcache.recover = no; gcache.size = 20G; gcomm.thread_prio = ; gcs.fc_debug = 0; gcs.fc_factor = 1.0; gcs.fc_limit = 16; gcs.fc_master_slave = no; gcs.max_packet_size = 64500; gcs.max_throttle = 0.25; gcs.recv_q_hard_limit = 9223372036854775807; gcs.recv_q_soft_limit = 0.25; gcs.sync_donor = no; gmcast.segment = 0; gmcast.version = 0; pc.announce_timeout = PT3S; pc.checksum = false; pc

2018-03-02 11:46:48 140111382202560 [Note] WSREP: GCache history reset: 00000000-0000-0000-0000-000000000000:0 -> 00000000-0000-0000-0000-000000000000:-1

2018-03-02 11:46:48 140111382202560 [Note] WSREP: Assign initial position for certification: -1, protocol version: -1

2018-03-02 11:46:48 140111382202560 [Note] WSREP: wsrep_sst_grab()

2018-03-02 11:46:48 140111382202560 [Note] WSREP: Start replication

2018-03-02 11:46:48 140111382202560 [Note] WSREP: Setting initial position to 00000000-0000-0000-0000-000000000000:-1

2018-03-02 11:46:48 140111382202560 [Note] WSREP: protonet asio version 0

2018-03-02 11:46:48 140111382202560 [Note] WSREP: Using CRC-32C for message checksums.

2018-03-02 11:46:48 140111382202560 [Note] WSREP: backend: asio

2018-03-02 11:46:48 140111382202560 [Note] WSREP: gcomm thread scheduling priority set to other:0

2018-03-02 11:46:48 140111382202560 [Warning] WSREP: access file(/RDC/mysql/data//gvwstate.dat) failed(No such file or directory)

2018-03-02 11:46:48 140111382202560 [Note] WSREP: restore pc from disk failed

2018-03-02 11:46:48 140111382202560 [Note] WSREP: GMCast version 0

2018-03-02 11:46:48 140111382202560 [Note] WSREP: (025fa3ee, 'tcp://0.0.0.0:4567') listening at tcp://0.0.0.0:4567

2018-03-02 11:46:48 140111382202560 [Note] WSREP: (025fa3ee, 'tcp://0.0.0.0:4567') multicast: , ttl: 1

2018-03-02 11:46:48 140111382202560 [Note] WSREP: EVS version 0

2018-03-02 11:46:48 140111382202560 [Note] WSREP: gcomm: connecting to group 'rdc-cluster-1', peer '10.241.5.221:,10.241.5.222:,10.241.5.220:'

2018-03-02 11:46:48 140111382202560 [Note] WSREP: (025fa3ee, 'tcp://0.0.0.0:4567') connection established to 025fa3ee tcp://10.241.5.221:4567

2018-03-02 11:46:48 140111382202560 [Warning] WSREP: (025fa3ee, 'tcp://0.0.0.0:4567') address 'tcp://10.241.5.221:4567' points to own listening address, blacklisting

2018-03-02 11:46:48 140111382202560 [Note] WSREP: (025fa3ee, 'tcp://0.0.0.0:4567') connection established to 8fa6765f tcp://10.241.5.220:4567

2018-03-02 11:46:48 140111382202560 [Note] WSREP: (025fa3ee, 'tcp://0.0.0.0:4567') turning message relay requesting on, nonlive peers:

2018-03-02 11:46:48 140111382202560 [Note] WSREP: (025fa3ee, 'tcp://0.0.0.0:4567') connection established to 0a0faad9 tcp://10.241.5.222:4567

2018-03-02 11:46:48 140111382202560 [Note] WSREP: declaring 0a0faad9 at tcp://10.241.5.222:4567 stable

2018-03-02 11:46:48 140111382202560 [Note] WSREP: declaring 8fa6765f at tcp://10.241.5.220:4567 stable

2018-03-02 11:46:48 140111382202560 [Note] WSREP: Node 0a0faad9 state prim

2018-03-02 11:46:48 140111382202560 [Note] WSREP: view(view_id(PRIM,025fa3ee,31) memb {

        025fa3ee,0

        0a0faad9,0

        8fa6765f,0

} joined {

} left {

} partitioned {

})

2018-03-02 11:46:48 140111382202560 [Note] WSREP: save pc into disk

2018-03-02 11:46:49 140111382202560 [Note] WSREP: gcomm: connected

2018-03-02 11:46:49 140111382202560 [Note] WSREP: Changing maximum packet size to 64500, resulting msg size: 32636

2018-03-02 11:46:49 140111382202560 [Note] WSREP: Shifting CLOSED -> OPEN (TO: 0)

2018-03-02 11:46:49 140111382202560 [Note] WSREP: Opened channel 'rdc-cluster-1'

2018-03-02 11:46:49 140089639511808 [Note] WSREP: New COMPONENT: primary = yes, bootstrap = no, my_idx = 0, memb_num = 3

2018-03-02 11:46:49 140111382202560 [Note] WSREP: Waiting for SST to complete.

2018-03-02 11:46:49 140089639511808 [Note] WSREP: STATE_EXCHANGE: sent state UUID: 02ac5985-1e07-11e8-9509-d60e7fa9376f

2018-03-02 11:46:49 140089639511808 [Note] WSREP: STATE EXCHANGE: sent state msg: 02ac5985-1e07-11e8-9509-d60e7fa9376f

2018-03-02 11:46:49 140089639511808 [Note] WSREP: STATE EXCHANGE: got state msg: 02ac5985-1e07-11e8-9509-d60e7fa9376f from 0 (hb01-galera-cl01-02)

2018-03-02 11:46:49 140089639511808 [Note] WSREP: STATE EXCHANGE: got state msg: 02ac5985-1e07-11e8-9509-d60e7fa9376f from 1 (hb01-galera-cl01-03)

2018-03-02 11:46:49 140089639511808 [Note] WSREP: STATE EXCHANGE: got state msg: 02ac5985-1e07-11e8-9509-d60e7fa9376f from 2 (hb01-galera-cl01-01)

2018-03-02 11:46:49 140089639511808 [Note] WSREP: Quorum results:

        version    = 4,

        component  = PRIMARY,

        conf_id    = 30,

        members    = 2/3 (joined/total),

        act_id     = 469231120,

        last_appl. = -1,

        protocols  = 0/8/3 (gcs/repl/appl),

        group UUID = 6b51589d-0b5f-11e8-94e6-82aa9d3be300

2018-03-02 11:46:49 140089639511808 [Note] WSREP: Flow-control interval: [28, 28]

2018-03-02 11:46:49 140089639511808 [Note] WSREP: Trying to continue unpaused monitor

2018-03-02 11:46:49 140089639511808 [Note] WSREP: Shifting OPEN -> PRIMARY (TO: 469231120)

2018-03-02 11:46:49 140111229683456 [Note] WSREP: State transfer required:

        Group state: 6b51589d-0b5f-11e8-94e6-82aa9d3be300:469231120

        Local state: 00000000-0000-0000-0000-000000000000:-1

2018-03-02 11:46:49 140111229683456 [Note] WSREP: New cluster view: global state: 6b51589d-0b5f-11e8-94e6-82aa9d3be300:469231120, view# 31: Primary, number of nodes: 3, my index: 0, protocol version 3

2018-03-02 11:46:49 140111229683456 [Warning] WSREP: Gap in state sequence. Need state transfer.

2018-03-02 11:46:49 140089631119104 [Note] WSREP: Running: 'wsrep_sst_xtrabackup-v2 --role 'joiner' --address '10.241.5.221' --datadir '/RDC/mysql/data/'   --parent '31376' --binlog '/RDC/mysql/binlog/mariadb-bin' '

WSREP_SST: [INFO] Logging all stderr of SST/Innobackupex to syslog (20180302 11:46:49.566)

2018-03-02 11:46:52 140089647904512 [Note] WSREP: (025fa3ee, 'tcp://0.0.0.0:4567') connection to peer 025fa3ee with addr tcp://10.241.5.221:4567 timed out, no messages seen in PT3S

2018-03-02 11:46:52 140089647904512 [Note] WSREP: (025fa3ee, 'tcp://0.0.0.0:4567') turning message relay requesting off

2018-03-02 11:48:18 140089631119104 [ERROR] WSREP: Failed to read 'ready <addr>' from: wsrep_sst_xtrabackup-v2 --role 'joiner' --address '10.241.5.221' --datadir '/RDC/mysql/data/'   --parent '31376' --binlog '/RDC/mysql/binlog/mariadb-bin'

        Read: '(null)'

2018-03-02 11:48:18 140089631119104 [ERROR] WSREP: Process was aborted.

2018-03-02 11:48:18 140089631119104 [ERROR] WSREP: Process completed with error: wsrep_sst_xtrabackup-v2 --role 'joiner' --address '10.241.5.221' --datadir '/RDC/mysql/data/'   --parent '31376' --binlog '/RDC/mysql/binlog/mariadb-bin' : 2 (No such file or directory)

2018-03-02 11:48:18 140111229683456 [ERROR] WSREP: Failed to prepare for 'xtrabackup-v2' SST. Unrecoverable.

2018-03-02 11:48:18 140111229683456 [ERROR] Aborting

Error in my_thread_global_end(): 1 threads didn't exit

on init (12.2.12) I load node 3 with slave, then node 1 & 2 with SST and it's worked perfectly

Attachments

Issue Links

relates to

MDEV-12289 Keep 128 persistent rollback segments for compatibility and performance

Closed

MDEV-15466 SST not working after upgrade from 10.2.11

Closed

Activity

Transition	Time In Source Status	Execution Times

Jan Lindström (Inactive) made transition - 2018-07-25 06:17

Open

In Progress

144d 16h 39m

Jan Lindström (Inactive) made transition - 2018-07-26 12:36

In Progress

Stalled

1d 6h 18m

Jan Lindström (Inactive) made transition - 2018-09-13 11:05

Stalled

Closed

48d 22h 28m

People

Assignee:: Jan Lindström (Inactive)

Reporter:: Aurélien LEQUOY

Votes:: 0 Vote for this issue

Watchers:: 6 Start watching this issue

Dates

Created:: 2018-03-02 13:38

Updated:: 2018-09-13 11:05

Resolved:: 2018-09-13 11:05

Git Integration

Error rendering 'com.xiplink.jira.git.jira_git_plugin:git-issue-webpanel'. Please contact your Jira administrators.

MariaDB Server