[MDEV-9599] When using systemd and an SST fails, mysqld on the joiner automatically restarts Created: 2016-02-19  Updated: 2023-04-12  Resolved: 2023-04-11

Status: Closed
Project: MariaDB Server
Component/s: Galera, Galera SST, Scripts & Clients, wsrep
Affects Version/s: 10.1.11
Fix Version/s: N/A

Type: Bug Priority: Major
Reporter: Geoff Montee (Inactive) Assignee: Jan Lindström (Inactive)
Resolution: Won't Fix Votes: 2
Labels: galera, sst, systemd, wsrep


 Description   

When using systemd in MariaDB 10.1 and an SST fails, mysqld on the joiner automatically restarts.

Is this intentional?

Below is an example with wsrep_sst_rsync attempting to do an SST 4 times after automatically restarting.

Feb 19 12:35:08 ip-172-31-19-192 systemd: Starting MariaDB database server...
Feb 19 12:35:09 ip-172-31-19-192 mysqld: 2016-02-19 12:35:09 140565056141440 [Note] /usr/sbin/mysqld (mysqld 10.1.11-MariaDB) starting as process 2383 ...
Feb 19 12:35:09 ip-172-31-19-192 mysqld: 2016-02-19 12:35:09 140565056141440 [Note] WSREP: Read nil XID from storage engines, skipping position init
Feb 19 12:35:09 ip-172-31-19-192 mysqld: 2016-02-19 12:35:09 140565056141440 [Note] WSREP: wsrep_load(): loading provider library '/usr/lib64/galera/libgalera_smm.so'
Feb 19 12:35:09 ip-172-31-19-192 mysqld: 2016-02-19 12:35:09 140565056141440 [Note] WSREP: wsrep_load(): Galera 25.3.12(r3516) by Codership Oy <info@codership.com> loaded successfully.
Feb 19 12:35:09 ip-172-31-19-192 mysqld: 2016-02-19 12:35:09 140565056141440 [Note] WSREP: CRC-32C: using hardware acceleration.
Feb 19 12:35:09 ip-172-31-19-192 mysqld: 2016-02-19 12:35:09 140565056141440 [Warning] WSREP: Could not open state file for reading: '/var/lib/mysql//grastate.dat'
Feb 19 12:35:09 ip-172-31-19-192 mysqld: 2016-02-19 12:35:09 140565056141440 [Note] WSREP: Found saved state: 00000000-0000-0000-0000-000000000000:-1
Feb 19 12:35:09 ip-172-31-19-192 mysqld: 2016-02-19 12:35:09 140565056141440 [Note] WSREP: Passing config to GCS: base_dir = /var/lib/mysql/; base_host = 172.31.19.192; 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 = /var/lib/mysql/; gcache.keep_pages_size = 0; gcache.mem_size = 0; gcache.name = /var/lib/mysql//galera.cache; gcache.page_size = 128M; gcache.size = 128M; 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.ignore_quorum = false; pc.ignore_sb = false
Feb 19 12:35:09 ip-172-31-19-192 mysqld: 2016-02-19 12:35:09 140564825634560 [Note] WSREP: Service thread queue flushed.
Feb 19 12:35:09 ip-172-31-19-192 mysqld: 2016-02-19 12:35:09 140565056141440 [Note] WSREP: Assign initial position for certification: -1, protocol version: -1
Feb 19 12:35:09 ip-172-31-19-192 mysqld: 2016-02-19 12:35:09 140565056141440 [Note] WSREP: wsrep_sst_grab()
Feb 19 12:35:09 ip-172-31-19-192 mysqld: 2016-02-19 12:35:09 140565056141440 [Note] WSREP: Start replication
Feb 19 12:35:09 ip-172-31-19-192 mysqld: 2016-02-19 12:35:09 140565056141440 [Note] WSREP: Setting initial position to 00000000-0000-0000-0000-000000000000:-1
Feb 19 12:35:09 ip-172-31-19-192 mysqld: 2016-02-19 12:35:09 140565056141440 [Note] WSREP: protonet asio version 0
Feb 19 12:35:09 ip-172-31-19-192 mysqld: 2016-02-19 12:35:09 140565056141440 [Note] WSREP: Using CRC-32C for message checksums.
Feb 19 12:35:09 ip-172-31-19-192 mysqld: 2016-02-19 12:35:09 140565056141440 [Note] WSREP: backend: asio
Feb 19 12:35:09 ip-172-31-19-192 mysqld: 2016-02-19 12:35:09 140565056141440 [Warning] WSREP: access file(/var/lib/mysql//gvwstate.dat) failed(No such file or directory)
Feb 19 12:35:09 ip-172-31-19-192 mysqld: 2016-02-19 12:35:09 140565056141440 [Note] WSREP: restore pc from disk failed
Feb 19 12:35:09 ip-172-31-19-192 mysqld: 2016-02-19 12:35:09 140565056141440 [Note] WSREP: GMCast version 0
Feb 19 12:35:09 ip-172-31-19-192 mysqld: 2016-02-19 12:35:09 140565056141440 [Note] WSREP: (1f255a15, 'tcp://0.0.0.0:4567') listening at tcp://0.0.0.0:4567
Feb 19 12:35:09 ip-172-31-19-192 mysqld: 2016-02-19 12:35:09 140565056141440 [Note] WSREP: (1f255a15, 'tcp://0.0.0.0:4567') multicast: , ttl: 1
Feb 19 12:35:09 ip-172-31-19-192 mysqld: 2016-02-19 12:35:09 140565056141440 [Note] WSREP: EVS version 0
Feb 19 12:35:09 ip-172-31-19-192 mysqld: 2016-02-19 12:35:09 140565056141440 [Note] WSREP: gcomm: connecting to group 'my_wsrep_cluster', peer '172.31.22.174:,172.31.19.192:'
Feb 19 12:35:09 ip-172-31-19-192 mysqld: 2016-02-19 12:35:09 140565056141440 [Warning] WSREP: (1f255a15, 'tcp://0.0.0.0:4567') address 'tcp://172.31.19.192:4567' points to own listening address, blacklisting
Feb 19 12:35:09 ip-172-31-19-192 mysqld: 2016-02-19 12:35:09 140565056141440 [Note] WSREP: (1f255a15, 'tcp://0.0.0.0:4567') turning message relay requesting on, nonlive peers:
Feb 19 12:35:09 ip-172-31-19-192 mysqld: 2016-02-19 12:35:09 140565056141440 [Note] WSREP: declaring 474dfc6f at tcp://172.31.22.174:4567 stable
Feb 19 12:35:09 ip-172-31-19-192 mysqld: 2016-02-19 12:35:09 140565056141440 [Note] WSREP: Node 474dfc6f state prim
Feb 19 12:35:09 ip-172-31-19-192 mysqld: 2016-02-19 12:35:09 140565056141440 [Note] WSREP: view(view_id(PRIM,1f255a15,4) memb {
Feb 19 12:35:09 ip-172-31-19-192 mysqld: 1f255a15,0
Feb 19 12:35:09 ip-172-31-19-192 mysqld: 474dfc6f,0
Feb 19 12:35:09 ip-172-31-19-192 mysqld: } joined {
Feb 19 12:35:09 ip-172-31-19-192 mysqld: } left {
Feb 19 12:35:09 ip-172-31-19-192 mysqld: } partitioned {
Feb 19 12:35:09 ip-172-31-19-192 mysqld: })
Feb 19 12:35:09 ip-172-31-19-192 mysqld: 2016-02-19 12:35:09 140565056141440 [Note] WSREP: save pc into disk
Feb 19 12:35:09 ip-172-31-19-192 mysqld: 2016-02-19 12:35:09 140565056141440 [Note] WSREP: gcomm: connected
Feb 19 12:35:09 ip-172-31-19-192 mysqld: 2016-02-19 12:35:09 140565056141440 [Note] WSREP: Changing maximum packet size to 64500, resulting msg size: 32636
Feb 19 12:35:09 ip-172-31-19-192 mysqld: 2016-02-19 12:35:09 140565056141440 [Note] WSREP: Shifting CLOSED -> OPEN (TO: 0)
Feb 19 12:35:09 ip-172-31-19-192 mysqld: 2016-02-19 12:35:09 140565056141440 [Note] WSREP: Opened channel 'my_wsrep_cluster'
Feb 19 12:35:09 ip-172-31-19-192 mysqld: 2016-02-19 12:35:09 140564766910208 [Note] WSREP: New COMPONENT: primary = yes, bootstrap = no, my_idx = 0, memb_num = 2
Feb 19 12:35:09 ip-172-31-19-192 mysqld: 2016-02-19 12:35:09 140564766910208 [Note] WSREP: STATE_EXCHANGE: sent state UUID: 1f721fbf-d72f-11e5-8415-d2f3d6bbba50
Feb 19 12:35:09 ip-172-31-19-192 mysqld: 2016-02-19 12:35:09 140565056141440 [Note] WSREP: Waiting for SST to complete.
Feb 19 12:35:09 ip-172-31-19-192 mysqld: 2016-02-19 12:35:09 140564766910208 [Note] WSREP: STATE EXCHANGE: sent state msg: 1f721fbf-d72f-11e5-8415-d2f3d6bbba50
Feb 19 12:35:09 ip-172-31-19-192 mysqld: 2016-02-19 12:35:09 140564766910208 [Note] WSREP: STATE EXCHANGE: got state msg: 1f721fbf-d72f-11e5-8415-d2f3d6bbba50 from 0 ()
Feb 19 12:35:09 ip-172-31-19-192 mysqld: 2016-02-19 12:35:09 140564766910208 [Note] WSREP: STATE EXCHANGE: got state msg: 1f721fbf-d72f-11e5-8415-d2f3d6bbba50 from 1 ()
Feb 19 12:35:09 ip-172-31-19-192 mysqld: 2016-02-19 12:35:09 140564766910208 [Note] WSREP: Quorum results:
Feb 19 12:35:09 ip-172-31-19-192 mysqld: version    = 3,
Feb 19 12:35:09 ip-172-31-19-192 mysqld: component  = PRIMARY,
Feb 19 12:35:09 ip-172-31-19-192 mysqld: conf_id    = 3,
Feb 19 12:35:09 ip-172-31-19-192 mysqld: members    = 1/2 (joined/total),
Feb 19 12:35:09 ip-172-31-19-192 mysqld: act_id     = 1,
Feb 19 12:35:09 ip-172-31-19-192 mysqld: last_appl. = -1,
Feb 19 12:35:09 ip-172-31-19-192 mysqld: protocols  = 0/7/3 (gcs/repl/appl),
Feb 19 12:35:09 ip-172-31-19-192 mysqld: group UUID = 474f3f92-d723-11e5-8da3-d3e87bd5db9a
Feb 19 12:35:09 ip-172-31-19-192 mysqld: 2016-02-19 12:35:09 140564766910208 [Note] WSREP: Flow-control interval: [23, 23]
Feb 19 12:35:09 ip-172-31-19-192 mysqld: 2016-02-19 12:35:09 140564766910208 [Note] WSREP: Shifting OPEN -> PRIMARY (TO: 1)
Feb 19 12:35:09 ip-172-31-19-192 mysqld: 2016-02-19 12:35:09 140565055826688 [Note] WSREP: State transfer required:
Feb 19 12:35:09 ip-172-31-19-192 mysqld: Group state: 474f3f92-d723-11e5-8da3-d3e87bd5db9a:1
Feb 19 12:35:09 ip-172-31-19-192 mysqld: Local state: 00000000-0000-0000-0000-000000000000:-1
Feb 19 12:35:09 ip-172-31-19-192 mysqld: 2016-02-19 12:35:09 140565055826688 [Note] WSREP: New cluster view: global state: 474f3f92-d723-11e5-8da3-d3e87bd5db9a:1, view# 4: Primary, number of nodes: 2, my index: 0, protocol version 3
Feb 19 12:35:09 ip-172-31-19-192 mysqld: 2016-02-19 12:35:09 140565055826688 [Warning] WSREP: Gap in state sequence. Need state transfer.
Feb 19 12:35:09 ip-172-31-19-192 mysqld: 2016-02-19 12:35:09 140564758517504 [Note] WSREP: Running: 'wsrep_sst_rsync --role 'joiner' --address '172.31.19.192' --datadir '/var/lib/mysql/'   --parent '2383'  '' '
Feb 19 12:35:09 ip-172-31-19-192 rsyncd[2421]: rsyncd version 3.0.9 starting, listening on port 4444
Feb 19 12:35:09 ip-172-31-19-192 mysqld: 2016-02-19 12:35:09 140565055826688 [Note] WSREP: Prepared SST request: rsync|172.31.19.192:4444/rsync_sst
Feb 19 12:35:09 ip-172-31-19-192 mysqld: 2016-02-19 12:35:09 140565055826688 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
Feb 19 12:35:09 ip-172-31-19-192 mysqld: 2016-02-19 12:35:09 140565055826688 [Note] WSREP: REPL Protocols: 7 (3, 2)
Feb 19 12:35:09 ip-172-31-19-192 mysqld: 2016-02-19 12:35:09 140564825634560 [Note] WSREP: Service thread queue flushed.
Feb 19 12:35:09 ip-172-31-19-192 mysqld: 2016-02-19 12:35:09 140565055826688 [Note] WSREP: Assign initial position for certification: 1, protocol version: 3
Feb 19 12:35:09 ip-172-31-19-192 mysqld: 2016-02-19 12:35:09 140564825634560 [Note] WSREP: Service thread queue flushed.
Feb 19 12:35:09 ip-172-31-19-192 mysqld: 2016-02-19 12:35:09 140565055826688 [Warning] WSREP: Failed to prepare for incremental state transfer: Local state UUID (00000000-0000-0000-0000-000000000000) does not match group state UUID (474f3f92-d723-11e5-8da3-d3e87bd5db9a): 1 (Operation not permitted)
Feb 19 12:35:09 ip-172-31-19-192 mysqld: at galera/src/replicator_str.cpp:prepare_for_IST():482. IST will be unavailable.
Feb 19 12:35:09 ip-172-31-19-192 mysqld: 2016-02-19 12:35:09 140564766910208 [Note] WSREP: Member 0.0 () requested state transfer from '*any*'. Selected 1.0 ()(SYNCED) as donor.
Feb 19 12:35:09 ip-172-31-19-192 mysqld: 2016-02-19 12:35:09 140564766910208 [Note] WSREP: Shifting PRIMARY -> JOINER (TO: 1)
Feb 19 12:35:09 ip-172-31-19-192 mysqld: 2016-02-19 12:35:09 140565055826688 [Note] WSREP: Requesting state transfer: success, donor: 1
Feb 19 12:35:10 ip-172-31-19-192 mysqld: 2016-02-19 12:35:10 140564766910208 [Warning] WSREP: 1.0 (): State transfer to 0.0 () failed: -78 (Remote address changed)
Feb 19 12:35:10 ip-172-31-19-192 mysqld: 2016-02-19 12:35:10 140564766910208 [ERROR] WSREP: gcs/src/gcs_group.cpp:gcs_group_handle_join_msg():731: Will never receive state. Need to abort.
Feb 19 12:35:10 ip-172-31-19-192 mysqld: 2016-02-19 12:35:10 140564766910208 [Note] WSREP: gcomm: terminating thread
Feb 19 12:35:10 ip-172-31-19-192 mysqld: 2016-02-19 12:35:10 140564766910208 [Note] WSREP: gcomm: joining thread
Feb 19 12:35:10 ip-172-31-19-192 mysqld: 2016-02-19 12:35:10 140564766910208 [Note] WSREP: gcomm: closing backend
Feb 19 12:35:11 ip-172-31-19-192 mysqld: 2016-02-19 12:35:11 140564766910208 [Note] WSREP: view(view_id(NON_PRIM,1f255a15,4) memb {
Feb 19 12:35:11 ip-172-31-19-192 mysqld: 1f255a15,0
Feb 19 12:35:11 ip-172-31-19-192 mysqld: } joined {
Feb 19 12:35:11 ip-172-31-19-192 mysqld: } left {
Feb 19 12:35:11 ip-172-31-19-192 mysqld: } partitioned {
Feb 19 12:35:11 ip-172-31-19-192 mysqld: 474dfc6f,0
Feb 19 12:35:11 ip-172-31-19-192 mysqld: })
Feb 19 12:35:11 ip-172-31-19-192 mysqld: 2016-02-19 12:35:11 140564766910208 [Note] WSREP: view((empty))
Feb 19 12:35:11 ip-172-31-19-192 mysqld: 2016-02-19 12:35:11 140564766910208 [Note] WSREP: gcomm: closed
Feb 19 12:35:11 ip-172-31-19-192 mysqld: 2016-02-19 12:35:11 140564766910208 [Note] WSREP: /usr/sbin/mysqld: Terminated.
Feb 19 12:35:11 ip-172-31-19-192 systemd: mariadb.service: main process exited, code=killed, status=6/ABRT
Feb 19 12:35:11 ip-172-31-19-192 systemd: Failed to start MariaDB database server.
Feb 19 12:35:11 ip-172-31-19-192 systemd: Unit mariadb.service entered failed state.
Feb 19 12:35:12 ip-172-31-19-192 mysqld: WSREP_SST: [ERROR] Parent mysqld process (PID:2383) terminated unexpectedly. (20160219 12:35:12.696)
Feb 19 12:35:12 ip-172-31-19-192 mysqld: WSREP_SST: [INFO] Joiner cleanup. rsync PID: 2421 (20160219 12:35:12.698)
Feb 19 12:35:13 ip-172-31-19-192 rsyncd[2421]: rsync error: received SIGINT, SIGTERM, or SIGHUP (code 20) at rsync.c(551) [Receiver=3.0.9]
Feb 19 12:35:13 ip-172-31-19-192 mysqld: WSREP_SST: [INFO] Joiner cleanup done. (20160219 12:35:13.202)
Feb 19 12:35:16 ip-172-31-19-192 systemd: mariadb.service holdoff time over, scheduling restart.
Feb 19 12:35:16 ip-172-31-19-192 systemd: Stopping MariaDB database server...
Feb 19 12:35:16 ip-172-31-19-192 systemd: Starting MariaDB database server...
Feb 19 12:35:17 ip-172-31-19-192 mysqld: 2016-02-19 12:35:17 140685195495552 [Note] /usr/sbin/mysqld (mysqld 10.1.11-MariaDB) starting as process 2463 ...
Feb 19 12:35:17 ip-172-31-19-192 mysqld: 2016-02-19 12:35:17 140685195495552 [Note] WSREP: Read nil XID from storage engines, skipping position init
Feb 19 12:35:17 ip-172-31-19-192 mysqld: 2016-02-19 12:35:17 140685195495552 [Note] WSREP: wsrep_load(): loading provider library '/usr/lib64/galera/libgalera_smm.so'
Feb 19 12:35:17 ip-172-31-19-192 mysqld: 2016-02-19 12:35:17 140685195495552 [Note] WSREP: wsrep_load(): Galera 25.3.12(r3516) by Codership Oy <info@codership.com> loaded successfully.
Feb 19 12:35:17 ip-172-31-19-192 mysqld: 2016-02-19 12:35:17 140685195495552 [Note] WSREP: CRC-32C: using hardware acceleration.
Feb 19 12:35:17 ip-172-31-19-192 mysqld: 2016-02-19 12:35:17 140685195495552 [Note] WSREP: Found saved state: 00000000-0000-0000-0000-000000000000:-1
Feb 19 12:35:17 ip-172-31-19-192 mysqld: 2016-02-19 12:35:17 140685195495552 [Note] WSREP: Passing config to GCS: base_dir = /var/lib/mysql/; base_host = 172.31.19.192; 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 = /var/lib/mysql/; gcache.keep_pages_size = 0; gcache.mem_size = 0; gcache.name = /var/lib/mysql//galera.cache; gcache.page_size = 128M; gcache.size = 128M; 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.ignore_quorum = false; pc.ignore_sb = false
Feb 19 12:35:17 ip-172-31-19-192 mysqld: 2016-02-19 12:35:17 140684967278336 [Note] WSREP: Service thread queue flushed.
Feb 19 12:35:17 ip-172-31-19-192 mysqld: 2016-02-19 12:35:17 140685195495552 [Note] WSREP: Assign initial position for certification: -1, protocol version: -1
Feb 19 12:35:17 ip-172-31-19-192 mysqld: 2016-02-19 12:35:17 140685195495552 [Note] WSREP: wsrep_sst_grab()
Feb 19 12:35:17 ip-172-31-19-192 mysqld: 2016-02-19 12:35:17 140685195495552 [Note] WSREP: Start replication
Feb 19 12:35:17 ip-172-31-19-192 mysqld: 2016-02-19 12:35:17 140685195495552 [Note] WSREP: Setting initial position to 00000000-0000-0000-0000-000000000000:-1
Feb 19 12:35:17 ip-172-31-19-192 mysqld: 2016-02-19 12:35:17 140685195495552 [Note] WSREP: protonet asio version 0
Feb 19 12:35:17 ip-172-31-19-192 mysqld: 2016-02-19 12:35:17 140685195495552 [Note] WSREP: Using CRC-32C for message checksums.
Feb 19 12:35:17 ip-172-31-19-192 mysqld: 2016-02-19 12:35:17 140685195495552 [Note] WSREP: backend: asio
Feb 19 12:35:17 ip-172-31-19-192 mysqld: 2016-02-19 12:35:17 140685195495552 [Warning] WSREP: access file(/var/lib/mysql//gvwstate.dat) failed(No such file or directory)
Feb 19 12:35:17 ip-172-31-19-192 mysqld: 2016-02-19 12:35:17 140685195495552 [Note] WSREP: restore pc from disk failed
Feb 19 12:35:17 ip-172-31-19-192 mysqld: 2016-02-19 12:35:17 140685195495552 [Note] WSREP: GMCast version 0
Feb 19 12:35:17 ip-172-31-19-192 mysqld: 2016-02-19 12:35:17 140685195495552 [Note] WSREP: (23e701f3, 'tcp://0.0.0.0:4567') listening at tcp://0.0.0.0:4567
Feb 19 12:35:17 ip-172-31-19-192 mysqld: 2016-02-19 12:35:17 140685195495552 [Note] WSREP: (23e701f3, 'tcp://0.0.0.0:4567') multicast: , ttl: 1
Feb 19 12:35:17 ip-172-31-19-192 mysqld: 2016-02-19 12:35:17 140685195495552 [Note] WSREP: EVS version 0
Feb 19 12:35:17 ip-172-31-19-192 mysqld: 2016-02-19 12:35:17 140685195495552 [Note] WSREP: gcomm: connecting to group 'my_wsrep_cluster', peer '172.31.22.174:,172.31.19.192:'
Feb 19 12:35:17 ip-172-31-19-192 mysqld: 2016-02-19 12:35:17 140685195495552 [Warning] WSREP: (23e701f3, 'tcp://0.0.0.0:4567') address 'tcp://172.31.19.192:4567' points to own listening address, blacklisting
Feb 19 12:35:17 ip-172-31-19-192 mysqld: 2016-02-19 12:35:17 140685195495552 [Note] WSREP: (23e701f3, 'tcp://0.0.0.0:4567') turning message relay requesting on, nonlive peers:
Feb 19 12:35:17 ip-172-31-19-192 mysqld: 2016-02-19 12:35:17 140685195495552 [Note] WSREP: declaring 474dfc6f at tcp://172.31.22.174:4567 stable
Feb 19 12:35:17 ip-172-31-19-192 mysqld: 2016-02-19 12:35:17 140685195495552 [Note] WSREP: Node 474dfc6f state prim
Feb 19 12:35:17 ip-172-31-19-192 mysqld: 2016-02-19 12:35:17 140685195495552 [Note] WSREP: view(view_id(PRIM,23e701f3,6) memb {
Feb 19 12:35:17 ip-172-31-19-192 mysqld: 23e701f3,0
Feb 19 12:35:17 ip-172-31-19-192 mysqld: 474dfc6f,0
Feb 19 12:35:17 ip-172-31-19-192 mysqld: } joined {
Feb 19 12:35:17 ip-172-31-19-192 mysqld: } left {
Feb 19 12:35:17 ip-172-31-19-192 mysqld: } partitioned {
Feb 19 12:35:17 ip-172-31-19-192 mysqld: })
Feb 19 12:35:17 ip-172-31-19-192 mysqld: 2016-02-19 12:35:17 140685195495552 [Note] WSREP: save pc into disk
Feb 19 12:35:18 ip-172-31-19-192 mysqld: 2016-02-19 12:35:18 140685195495552 [Note] WSREP: gcomm: connected
Feb 19 12:35:18 ip-172-31-19-192 mysqld: 2016-02-19 12:35:18 140685195495552 [Note] WSREP: Changing maximum packet size to 64500, resulting msg size: 32636
Feb 19 12:35:18 ip-172-31-19-192 mysqld: 2016-02-19 12:35:18 140685195495552 [Note] WSREP: Shifting CLOSED -> OPEN (TO: 0)
Feb 19 12:35:18 ip-172-31-19-192 mysqld: 2016-02-19 12:35:18 140685195495552 [Note] WSREP: Opened channel 'my_wsrep_cluster'
Feb 19 12:35:18 ip-172-31-19-192 mysqld: 2016-02-19 12:35:18 140684908553984 [Note] WSREP: New COMPONENT: primary = yes, bootstrap = no, my_idx = 0, memb_num = 2
Feb 19 12:35:18 ip-172-31-19-192 mysqld: 2016-02-19 12:35:18 140684908553984 [Note] WSREP: STATE_EXCHANGE: sent state UUID: 248016a6-d72f-11e5-afc0-d3e786fff5e6
Feb 19 12:35:18 ip-172-31-19-192 mysqld: 2016-02-19 12:35:18 140685195495552 [Note] WSREP: Waiting for SST to complete.
Feb 19 12:35:18 ip-172-31-19-192 mysqld: 2016-02-19 12:35:18 140684908553984 [Note] WSREP: STATE EXCHANGE: sent state msg: 248016a6-d72f-11e5-afc0-d3e786fff5e6
Feb 19 12:35:18 ip-172-31-19-192 mysqld: 2016-02-19 12:35:18 140684908553984 [Note] WSREP: STATE EXCHANGE: got state msg: 248016a6-d72f-11e5-afc0-d3e786fff5e6 from 0 ()
Feb 19 12:35:18 ip-172-31-19-192 mysqld: 2016-02-19 12:35:18 140684908553984 [Note] WSREP: STATE EXCHANGE: got state msg: 248016a6-d72f-11e5-afc0-d3e786fff5e6 from 1 ()
Feb 19 12:35:18 ip-172-31-19-192 mysqld: 2016-02-19 12:35:18 140684908553984 [Note] WSREP: Quorum results:
Feb 19 12:35:18 ip-172-31-19-192 mysqld: version    = 3,
Feb 19 12:35:18 ip-172-31-19-192 mysqld: component  = PRIMARY,
Feb 19 12:35:18 ip-172-31-19-192 mysqld: conf_id    = 5,
Feb 19 12:35:18 ip-172-31-19-192 mysqld: members    = 1/2 (joined/total),
Feb 19 12:35:18 ip-172-31-19-192 mysqld: act_id     = 1,
Feb 19 12:35:18 ip-172-31-19-192 mysqld: last_appl. = -1,
Feb 19 12:35:18 ip-172-31-19-192 mysqld: protocols  = 0/7/3 (gcs/repl/appl),
Feb 19 12:35:18 ip-172-31-19-192 mysqld: group UUID = 474f3f92-d723-11e5-8da3-d3e87bd5db9a
Feb 19 12:35:18 ip-172-31-19-192 mysqld: 2016-02-19 12:35:18 140684908553984 [Note] WSREP: Flow-control interval: [23, 23]
Feb 19 12:35:18 ip-172-31-19-192 mysqld: 2016-02-19 12:35:18 140684908553984 [Note] WSREP: Shifting OPEN -> PRIMARY (TO: 1)
Feb 19 12:35:18 ip-172-31-19-192 mysqld: 2016-02-19 12:35:18 140685195180800 [Note] WSREP: State transfer required:
Feb 19 12:35:18 ip-172-31-19-192 mysqld: Group state: 474f3f92-d723-11e5-8da3-d3e87bd5db9a:1
Feb 19 12:35:18 ip-172-31-19-192 mysqld: Local state: 00000000-0000-0000-0000-000000000000:-1
Feb 19 12:35:18 ip-172-31-19-192 mysqld: 2016-02-19 12:35:18 140685195180800 [Note] WSREP: New cluster view: global state: 474f3f92-d723-11e5-8da3-d3e87bd5db9a:1, view# 6: Primary, number of nodes: 2, my index: 0, protocol version 3
Feb 19 12:35:18 ip-172-31-19-192 mysqld: 2016-02-19 12:35:18 140685195180800 [Warning] WSREP: Gap in state sequence. Need state transfer.
Feb 19 12:35:18 ip-172-31-19-192 mysqld: 2016-02-19 12:35:18 140684900161280 [Note] WSREP: Running: 'wsrep_sst_rsync --role 'joiner' --address '172.31.19.192' --datadir '/var/lib/mysql/'   --parent '2463'  '' '
Feb 19 12:35:18 ip-172-31-19-192 rsyncd[2501]: rsyncd version 3.0.9 starting, listening on port 4444
Feb 19 12:35:18 ip-172-31-19-192 mysqld: 2016-02-19 12:35:18 140685195180800 [Note] WSREP: Prepared SST request: rsync|172.31.19.192:4444/rsync_sst
Feb 19 12:35:18 ip-172-31-19-192 mysqld: 2016-02-19 12:35:18 140685195180800 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
Feb 19 12:35:18 ip-172-31-19-192 mysqld: 2016-02-19 12:35:18 140685195180800 [Note] WSREP: REPL Protocols: 7 (3, 2)
Feb 19 12:35:18 ip-172-31-19-192 mysqld: 2016-02-19 12:35:18 140684967278336 [Note] WSREP: Service thread queue flushed.
Feb 19 12:35:18 ip-172-31-19-192 mysqld: 2016-02-19 12:35:18 140685195180800 [Note] WSREP: Assign initial position for certification: 1, protocol version: 3
Feb 19 12:35:18 ip-172-31-19-192 mysqld: 2016-02-19 12:35:18 140684967278336 [Note] WSREP: Service thread queue flushed.
Feb 19 12:35:18 ip-172-31-19-192 mysqld: 2016-02-19 12:35:18 140685195180800 [Warning] WSREP: Failed to prepare for incremental state transfer: Local state UUID (00000000-0000-0000-0000-000000000000) does not match group state UUID (474f3f92-d723-11e5-8da3-d3e87bd5db9a): 1 (Operation not permitted)
Feb 19 12:35:18 ip-172-31-19-192 mysqld: at galera/src/replicator_str.cpp:prepare_for_IST():482. IST will be unavailable.
Feb 19 12:35:18 ip-172-31-19-192 mysqld: 2016-02-19 12:35:18 140684908553984 [Note] WSREP: Member 0.0 () requested state transfer from '*any*'. Selected 1.0 ()(SYNCED) as donor.
Feb 19 12:35:18 ip-172-31-19-192 mysqld: 2016-02-19 12:35:18 140684908553984 [Note] WSREP: Shifting PRIMARY -> JOINER (TO: 1)
Feb 19 12:35:18 ip-172-31-19-192 mysqld: 2016-02-19 12:35:18 140685195180800 [Note] WSREP: Requesting state transfer: success, donor: 1
Feb 19 12:35:19 ip-172-31-19-192 mysqld: 2016-02-19 12:35:19 140684908553984 [Warning] WSREP: 1.0 (): State transfer to 0.0 () failed: -78 (Remote address changed)
Feb 19 12:35:19 ip-172-31-19-192 mysqld: 2016-02-19 12:35:19 140684908553984 [ERROR] WSREP: gcs/src/gcs_group.cpp:gcs_group_handle_join_msg():731: Will never receive state. Need to abort.
Feb 19 12:35:19 ip-172-31-19-192 mysqld: 2016-02-19 12:35:19 140684908553984 [Note] WSREP: gcomm: terminating thread
Feb 19 12:35:19 ip-172-31-19-192 mysqld: 2016-02-19 12:35:19 140684908553984 [Note] WSREP: gcomm: joining thread
Feb 19 12:35:19 ip-172-31-19-192 mysqld: 2016-02-19 12:35:19 140684908553984 [Note] WSREP: gcomm: closing backend
Feb 19 12:35:20 ip-172-31-19-192 mysqld: 2016-02-19 12:35:20 140684908553984 [Note] WSREP: view(view_id(NON_PRIM,23e701f3,6) memb {
Feb 19 12:35:20 ip-172-31-19-192 mysqld: 23e701f3,0
Feb 19 12:35:20 ip-172-31-19-192 mysqld: } joined {
Feb 19 12:35:20 ip-172-31-19-192 mysqld: } left {
Feb 19 12:35:20 ip-172-31-19-192 mysqld: } partitioned {
Feb 19 12:35:20 ip-172-31-19-192 mysqld: 474dfc6f,0
Feb 19 12:35:20 ip-172-31-19-192 mysqld: })
Feb 19 12:35:20 ip-172-31-19-192 mysqld: 2016-02-19 12:35:20 140684908553984 [Note] WSREP: (23e701f3, 'tcp://0.0.0.0:4567') turning message relay requesting off
Feb 19 12:35:20 ip-172-31-19-192 mysqld: 2016-02-19 12:35:20 140684908553984 [Note] WSREP: view((empty))
Feb 19 12:35:20 ip-172-31-19-192 mysqld: 2016-02-19 12:35:20 140684908553984 [Note] WSREP: gcomm: closed
Feb 19 12:35:20 ip-172-31-19-192 mysqld: 2016-02-19 12:35:20 140684908553984 [Note] WSREP: /usr/sbin/mysqld: Terminated.
Feb 19 12:35:20 ip-172-31-19-192 systemd: mariadb.service: main process exited, code=killed, status=6/ABRT
Feb 19 12:35:20 ip-172-31-19-192 systemd: Failed to start MariaDB database server.
Feb 19 12:35:20 ip-172-31-19-192 systemd: Unit mariadb.service entered failed state.
Feb 19 12:35:21 ip-172-31-19-192 mysqld: WSREP_SST: [ERROR] Parent mysqld process (PID:2463) terminated unexpectedly. (20160219 12:35:21.184)
Feb 19 12:35:21 ip-172-31-19-192 mysqld: WSREP_SST: [INFO] Joiner cleanup. rsync PID: 2501 (20160219 12:35:21.186)
Feb 19 12:35:21 ip-172-31-19-192 rsyncd[2501]: rsync error: received SIGINT, SIGTERM, or SIGHUP (code 20) at rsync.c(551) [Receiver=3.0.9]
Feb 19 12:35:21 ip-172-31-19-192 mysqld: WSREP_SST: [INFO] Joiner cleanup done. (20160219 12:35:21.691)
Feb 19 12:35:25 ip-172-31-19-192 systemd: mariadb.service holdoff time over, scheduling restart.
Feb 19 12:35:25 ip-172-31-19-192 systemd: Stopping MariaDB database server...
Feb 19 12:35:25 ip-172-31-19-192 systemd: Starting MariaDB database server...
Feb 19 12:35:25 ip-172-31-19-192 mysqld: 2016-02-19 12:35:25 140674047051904 [Note] /usr/sbin/mysqld (mysqld 10.1.11-MariaDB) starting as process 2543 ...
Feb 19 12:35:25 ip-172-31-19-192 mysqld: 2016-02-19 12:35:25 140674047051904 [Note] WSREP: Read nil XID from storage engines, skipping position init
Feb 19 12:35:25 ip-172-31-19-192 mysqld: 2016-02-19 12:35:25 140674047051904 [Note] WSREP: wsrep_load(): loading provider library '/usr/lib64/galera/libgalera_smm.so'
Feb 19 12:35:25 ip-172-31-19-192 mysqld: 2016-02-19 12:35:25 140674047051904 [Note] WSREP: wsrep_load(): Galera 25.3.12(r3516) by Codership Oy <info@codership.com> loaded successfully.
Feb 19 12:35:25 ip-172-31-19-192 mysqld: 2016-02-19 12:35:25 140674047051904 [Note] WSREP: CRC-32C: using hardware acceleration.
Feb 19 12:35:25 ip-172-31-19-192 mysqld: 2016-02-19 12:35:25 140674047051904 [Note] WSREP: Found saved state: 00000000-0000-0000-0000-000000000000:-1
Feb 19 12:35:25 ip-172-31-19-192 mysqld: 2016-02-19 12:35:25 140674047051904 [Note] WSREP: Passing config to GCS: base_dir = /var/lib/mysql/; base_host = 172.31.19.192; 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 = /var/lib/mysql/; gcache.keep_pages_size = 0; gcache.mem_size = 0; gcache.name = /var/lib/mysql//galera.cache; gcache.page_size = 128M; gcache.size = 128M; 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.ignore_quorum = false; pc.ignore_sb = false
Feb 19 12:35:25 ip-172-31-19-192 mysqld: 2016-02-19 12:35:25 140673818818304 [Note] WSREP: Service thread queue flushed.
Feb 19 12:35:25 ip-172-31-19-192 mysqld: 2016-02-19 12:35:25 140674047051904 [Note] WSREP: Assign initial position for certification: -1, protocol version: -1
Feb 19 12:35:25 ip-172-31-19-192 mysqld: 2016-02-19 12:35:25 140674047051904 [Note] WSREP: wsrep_sst_grab()
Feb 19 12:35:25 ip-172-31-19-192 mysqld: 2016-02-19 12:35:25 140674047051904 [Note] WSREP: Start replication
Feb 19 12:35:25 ip-172-31-19-192 mysqld: 2016-02-19 12:35:25 140674047051904 [Note] WSREP: Setting initial position to 00000000-0000-0000-0000-000000000000:-1
Feb 19 12:35:25 ip-172-31-19-192 mysqld: 2016-02-19 12:35:25 140674047051904 [Note] WSREP: protonet asio version 0
Feb 19 12:35:25 ip-172-31-19-192 mysqld: 2016-02-19 12:35:25 140674047051904 [Note] WSREP: Using CRC-32C for message checksums.
Feb 19 12:35:25 ip-172-31-19-192 mysqld: 2016-02-19 12:35:25 140674047051904 [Note] WSREP: backend: asio
Feb 19 12:35:25 ip-172-31-19-192 mysqld: 2016-02-19 12:35:25 140674047051904 [Warning] WSREP: access file(/var/lib/mysql//gvwstate.dat) failed(No such file or directory)
Feb 19 12:35:25 ip-172-31-19-192 mysqld: 2016-02-19 12:35:25 140674047051904 [Note] WSREP: restore pc from disk failed
Feb 19 12:35:25 ip-172-31-19-192 mysqld: 2016-02-19 12:35:25 140674047051904 [Note] WSREP: GMCast version 0
Feb 19 12:35:25 ip-172-31-19-192 mysqld: 2016-02-19 12:35:25 140674047051904 [Note] WSREP: (28e8b828, 'tcp://0.0.0.0:4567') listening at tcp://0.0.0.0:4567
Feb 19 12:35:25 ip-172-31-19-192 mysqld: 2016-02-19 12:35:25 140674047051904 [Note] WSREP: (28e8b828, 'tcp://0.0.0.0:4567') multicast: , ttl: 1
Feb 19 12:35:25 ip-172-31-19-192 mysqld: 2016-02-19 12:35:25 140674047051904 [Note] WSREP: EVS version 0
Feb 19 12:35:25 ip-172-31-19-192 mysqld: 2016-02-19 12:35:25 140674047051904 [Note] WSREP: gcomm: connecting to group 'my_wsrep_cluster', peer '172.31.22.174:,172.31.19.192:'
Feb 19 12:35:25 ip-172-31-19-192 mysqld: 2016-02-19 12:35:25 140674047051904 [Warning] WSREP: (28e8b828, 'tcp://0.0.0.0:4567') address 'tcp://172.31.19.192:4567' points to own listening address, blacklisting
Feb 19 12:35:25 ip-172-31-19-192 mysqld: 2016-02-19 12:35:25 140674047051904 [Note] WSREP: (28e8b828, 'tcp://0.0.0.0:4567') turning message relay requesting on, nonlive peers:
Feb 19 12:35:25 ip-172-31-19-192 mysqld: 2016-02-19 12:35:25 140674047051904 [Note] WSREP: declaring 474dfc6f at tcp://172.31.22.174:4567 stable
Feb 19 12:35:25 ip-172-31-19-192 mysqld: 2016-02-19 12:35:25 140674047051904 [Note] WSREP: Node 474dfc6f state prim
Feb 19 12:35:25 ip-172-31-19-192 mysqld: 2016-02-19 12:35:25 140674047051904 [Note] WSREP: view(view_id(PRIM,28e8b828,8) memb {
Feb 19 12:35:25 ip-172-31-19-192 mysqld: 28e8b828,0
Feb 19 12:35:25 ip-172-31-19-192 mysqld: 474dfc6f,0
Feb 19 12:35:25 ip-172-31-19-192 mysqld: } joined {
Feb 19 12:35:25 ip-172-31-19-192 mysqld: } left {
Feb 19 12:35:25 ip-172-31-19-192 mysqld: } partitioned {
Feb 19 12:35:25 ip-172-31-19-192 mysqld: })
Feb 19 12:35:25 ip-172-31-19-192 mysqld: 2016-02-19 12:35:25 140674047051904 [Note] WSREP: save pc into disk
Feb 19 12:35:26 ip-172-31-19-192 mysqld: 2016-02-19 12:35:26 140674047051904 [Note] WSREP: gcomm: connected
Feb 19 12:35:26 ip-172-31-19-192 mysqld: 2016-02-19 12:35:26 140674047051904 [Note] WSREP: Changing maximum packet size to 64500, resulting msg size: 32636
Feb 19 12:35:26 ip-172-31-19-192 mysqld: 2016-02-19 12:35:26 140674047051904 [Note] WSREP: Shifting CLOSED -> OPEN (TO: 0)
Feb 19 12:35:26 ip-172-31-19-192 mysqld: 2016-02-19 12:35:26 140674047051904 [Note] WSREP: Opened channel 'my_wsrep_cluster'
Feb 19 12:35:26 ip-172-31-19-192 mysqld: 2016-02-19 12:35:26 140673760093952 [Note] WSREP: New COMPONENT: primary = yes, bootstrap = no, my_idx = 0, memb_num = 2
Feb 19 12:35:26 ip-172-31-19-192 mysqld: 2016-02-19 12:35:26 140673760093952 [Note] WSREP: STATE_EXCHANGE: sent state UUID: 2981cc91-d72f-11e5-8035-6a7f61753a42
Feb 19 12:35:26 ip-172-31-19-192 mysqld: 2016-02-19 12:35:26 140674047051904 [Note] WSREP: Waiting for SST to complete.
Feb 19 12:35:26 ip-172-31-19-192 mysqld: 2016-02-19 12:35:26 140673760093952 [Note] WSREP: STATE EXCHANGE: sent state msg: 2981cc91-d72f-11e5-8035-6a7f61753a42
Feb 19 12:35:26 ip-172-31-19-192 mysqld: 2016-02-19 12:35:26 140673760093952 [Note] WSREP: STATE EXCHANGE: got state msg: 2981cc91-d72f-11e5-8035-6a7f61753a42 from 0 ()
Feb 19 12:35:26 ip-172-31-19-192 mysqld: 2016-02-19 12:35:26 140673760093952 [Note] WSREP: STATE EXCHANGE: got state msg: 2981cc91-d72f-11e5-8035-6a7f61753a42 from 1 ()
Feb 19 12:35:26 ip-172-31-19-192 mysqld: 2016-02-19 12:35:26 140673760093952 [Note] WSREP: Quorum results:
Feb 19 12:35:26 ip-172-31-19-192 mysqld: version    = 3,
Feb 19 12:35:26 ip-172-31-19-192 mysqld: component  = PRIMARY,
Feb 19 12:35:26 ip-172-31-19-192 mysqld: conf_id    = 7,
Feb 19 12:35:26 ip-172-31-19-192 mysqld: members    = 1/2 (joined/total),
Feb 19 12:35:26 ip-172-31-19-192 mysqld: act_id     = 1,
Feb 19 12:35:26 ip-172-31-19-192 mysqld: last_appl. = -1,
Feb 19 12:35:26 ip-172-31-19-192 mysqld: protocols  = 0/7/3 (gcs/repl/appl),
Feb 19 12:35:26 ip-172-31-19-192 mysqld: group UUID = 474f3f92-d723-11e5-8da3-d3e87bd5db9a
Feb 19 12:35:26 ip-172-31-19-192 mysqld: 2016-02-19 12:35:26 140673760093952 [Note] WSREP: Flow-control interval: [23, 23]
Feb 19 12:35:26 ip-172-31-19-192 mysqld: 2016-02-19 12:35:26 140673760093952 [Note] WSREP: Shifting OPEN -> PRIMARY (TO: 1)
Feb 19 12:35:26 ip-172-31-19-192 mysqld: 2016-02-19 12:35:26 140674046737152 [Note] WSREP: State transfer required:
Feb 19 12:35:26 ip-172-31-19-192 mysqld: Group state: 474f3f92-d723-11e5-8da3-d3e87bd5db9a:1
Feb 19 12:35:26 ip-172-31-19-192 mysqld: Local state: 00000000-0000-0000-0000-000000000000:-1
Feb 19 12:35:26 ip-172-31-19-192 mysqld: 2016-02-19 12:35:26 140674046737152 [Note] WSREP: New cluster view: global state: 474f3f92-d723-11e5-8da3-d3e87bd5db9a:1, view# 8: Primary, number of nodes: 2, my index: 0, protocol version 3
Feb 19 12:35:26 ip-172-31-19-192 mysqld: 2016-02-19 12:35:26 140674046737152 [Warning] WSREP: Gap in state sequence. Need state transfer.
Feb 19 12:35:26 ip-172-31-19-192 mysqld: 2016-02-19 12:35:26 140673751701248 [Note] WSREP: Running: 'wsrep_sst_rsync --role 'joiner' --address '172.31.19.192' --datadir '/var/lib/mysql/'   --parent '2543'  '' '
Feb 19 12:35:26 ip-172-31-19-192 rsyncd[2581]: rsyncd version 3.0.9 starting, listening on port 4444
Feb 19 12:35:26 ip-172-31-19-192 mysqld: 2016-02-19 12:35:26 140674046737152 [Note] WSREP: Prepared SST request: rsync|172.31.19.192:4444/rsync_sst
Feb 19 12:35:26 ip-172-31-19-192 mysqld: 2016-02-19 12:35:26 140674046737152 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
Feb 19 12:35:26 ip-172-31-19-192 mysqld: 2016-02-19 12:35:26 140674046737152 [Note] WSREP: REPL Protocols: 7 (3, 2)
Feb 19 12:35:26 ip-172-31-19-192 mysqld: 2016-02-19 12:35:26 140673818818304 [Note] WSREP: Service thread queue flushed.
Feb 19 12:35:26 ip-172-31-19-192 mysqld: 2016-02-19 12:35:26 140674046737152 [Note] WSREP: Assign initial position for certification: 1, protocol version: 3
Feb 19 12:35:26 ip-172-31-19-192 mysqld: 2016-02-19 12:35:26 140673818818304 [Note] WSREP: Service thread queue flushed.
Feb 19 12:35:26 ip-172-31-19-192 mysqld: 2016-02-19 12:35:26 140674046737152 [Warning] WSREP: Failed to prepare for incremental state transfer: Local state UUID (00000000-0000-0000-0000-000000000000) does not match group state UUID (474f3f92-d723-11e5-8da3-d3e87bd5db9a): 1 (Operation not permitted)
Feb 19 12:35:26 ip-172-31-19-192 mysqld: at galera/src/replicator_str.cpp:prepare_for_IST():482. IST will be unavailable.
Feb 19 12:35:26 ip-172-31-19-192 mysqld: 2016-02-19 12:35:26 140673760093952 [Note] WSREP: Member 0.0 () requested state transfer from '*any*'. Selected 1.0 ()(SYNCED) as donor.
Feb 19 12:35:26 ip-172-31-19-192 mysqld: 2016-02-19 12:35:26 140673760093952 [Note] WSREP: Shifting PRIMARY -> JOINER (TO: 1)
Feb 19 12:35:26 ip-172-31-19-192 mysqld: 2016-02-19 12:35:26 140674046737152 [Note] WSREP: Requesting state transfer: success, donor: 1
Feb 19 12:35:28 ip-172-31-19-192 mysqld: 2016-02-19 12:35:28 140673760093952 [Warning] WSREP: 1.0 (): State transfer to 0.0 () failed: -78 (Remote address changed)
Feb 19 12:35:28 ip-172-31-19-192 mysqld: 2016-02-19 12:35:28 140673760093952 [ERROR] WSREP: gcs/src/gcs_group.cpp:gcs_group_handle_join_msg():731: Will never receive state. Need to abort.
Feb 19 12:35:28 ip-172-31-19-192 mysqld: 2016-02-19 12:35:28 140673760093952 [Note] WSREP: gcomm: terminating thread
Feb 19 12:35:28 ip-172-31-19-192 mysqld: 2016-02-19 12:35:28 140673760093952 [Note] WSREP: gcomm: joining thread
Feb 19 12:35:28 ip-172-31-19-192 mysqld: 2016-02-19 12:35:28 140673760093952 [Note] WSREP: gcomm: closing backend
Feb 19 12:35:28 ip-172-31-19-192 mysqld: 2016-02-19 12:35:28 140673760093952 [Note] WSREP: (28e8b828, 'tcp://0.0.0.0:4567') turning message relay requesting off
Feb 19 12:35:29 ip-172-31-19-192 mysqld: 2016-02-19 12:35:29 140673760093952 [Note] WSREP: view(view_id(NON_PRIM,28e8b828,8) memb {
Feb 19 12:35:29 ip-172-31-19-192 mysqld: 28e8b828,0
Feb 19 12:35:29 ip-172-31-19-192 mysqld: } joined {
Feb 19 12:35:29 ip-172-31-19-192 mysqld: } left {
Feb 19 12:35:29 ip-172-31-19-192 mysqld: } partitioned {
Feb 19 12:35:29 ip-172-31-19-192 mysqld: 474dfc6f,0
Feb 19 12:35:29 ip-172-31-19-192 mysqld: })
Feb 19 12:35:29 ip-172-31-19-192 mysqld: 2016-02-19 12:35:29 140673760093952 [Note] WSREP: view((empty))
Feb 19 12:35:29 ip-172-31-19-192 mysqld: 2016-02-19 12:35:29 140673760093952 [Note] WSREP: gcomm: closed
Feb 19 12:35:29 ip-172-31-19-192 mysqld: 2016-02-19 12:35:29 140673760093952 [Note] WSREP: /usr/sbin/mysqld: Terminated.
Feb 19 12:35:29 ip-172-31-19-192 systemd: mariadb.service: main process exited, code=killed, status=6/ABRT
Feb 19 12:35:29 ip-172-31-19-192 systemd: Failed to start MariaDB database server.
Feb 19 12:35:29 ip-172-31-19-192 systemd: Unit mariadb.service entered failed state.
Feb 19 12:35:29 ip-172-31-19-192 mysqld: WSREP_SST: [ERROR] Parent mysqld process (PID:2543) terminated unexpectedly. (20160219 12:35:29.597)
Feb 19 12:35:29 ip-172-31-19-192 mysqld: WSREP_SST: [INFO] Joiner cleanup. rsync PID: 2581 (20160219 12:35:29.599)
Feb 19 12:35:30 ip-172-31-19-192 rsyncd[2581]: rsync error: received SIGINT, SIGTERM, or SIGHUP (code 20) at rsync.c(551) [Receiver=3.0.9]
Feb 19 12:35:30 ip-172-31-19-192 mysqld: WSREP_SST: [INFO] Joiner cleanup done. (20160219 12:35:30.104)
Feb 19 12:35:34 ip-172-31-19-192 systemd: mariadb.service holdoff time over, scheduling restart.
Feb 19 12:35:34 ip-172-31-19-192 systemd: Stopping MariaDB database server...
Feb 19 12:35:34 ip-172-31-19-192 systemd: Starting MariaDB database server...
Feb 19 12:35:34 ip-172-31-19-192 mysqld: 2016-02-19 12:35:34 139912045295744 [Note] /usr/sbin/mysqld (mysqld 10.1.11-MariaDB) starting as process 2625 ...
Feb 19 12:35:34 ip-172-31-19-192 mysqld: 2016-02-19 12:35:34 139912045295744 [Note] WSREP: Read nil XID from storage engines, skipping position init
Feb 19 12:35:34 ip-172-31-19-192 mysqld: 2016-02-19 12:35:34 139912045295744 [Note] WSREP: wsrep_load(): loading provider library '/usr/lib64/galera/libgalera_smm.so'
Feb 19 12:35:34 ip-172-31-19-192 mysqld: 2016-02-19 12:35:34 139912045295744 [Note] WSREP: wsrep_load(): Galera 25.3.12(r3516) by Codership Oy <info@codership.com> loaded successfully.
Feb 19 12:35:34 ip-172-31-19-192 mysqld: 2016-02-19 12:35:34 139912045295744 [Note] WSREP: CRC-32C: using hardware acceleration.
Feb 19 12:35:34 ip-172-31-19-192 mysqld: 2016-02-19 12:35:34 139912045295744 [Note] WSREP: Found saved state: 00000000-0000-0000-0000-000000000000:-1
Feb 19 12:35:34 ip-172-31-19-192 mysqld: 2016-02-19 12:35:34 139912045295744 [Note] WSREP: Passing config to GCS: base_dir = /var/lib/mysql/; base_host = 172.31.19.192; 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 = /var/lib/mysql/; gcache.keep_pages_size = 0; gcache.mem_size = 0; gcache.name = /var/lib/mysql//galera.cache; gcache.page_size = 128M; gcache.size = 128M; 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.ignore_quorum = false; pc.ignore_sb = false
Feb 19 12:35:34 ip-172-31-19-192 mysqld: 2016-02-19 12:35:34 139911814444800 [Note] WSREP: Service thread queue flushed.
Feb 19 12:35:34 ip-172-31-19-192 mysqld: 2016-02-19 12:35:34 139912045295744 [Note] WSREP: Assign initial position for certification: -1, protocol version: -1
Feb 19 12:35:34 ip-172-31-19-192 mysqld: 2016-02-19 12:35:34 139912045295744 [Note] WSREP: wsrep_sst_grab()
Feb 19 12:35:34 ip-172-31-19-192 mysqld: 2016-02-19 12:35:34 139912045295744 [Note] WSREP: Start replication
Feb 19 12:35:34 ip-172-31-19-192 mysqld: 2016-02-19 12:35:34 139912045295744 [Note] WSREP: Setting initial position to 00000000-0000-0000-0000-000000000000:-1
Feb 19 12:35:34 ip-172-31-19-192 mysqld: 2016-02-19 12:35:34 139912045295744 [Note] WSREP: protonet asio version 0
Feb 19 12:35:34 ip-172-31-19-192 mysqld: 2016-02-19 12:35:34 139912045295744 [Note] WSREP: Using CRC-32C for message checksums.
Feb 19 12:35:34 ip-172-31-19-192 mysqld: 2016-02-19 12:35:34 139912045295744 [Note] WSREP: backend: asio
Feb 19 12:35:34 ip-172-31-19-192 mysqld: 2016-02-19 12:35:34 139912045295744 [Warning] WSREP: access file(/var/lib/mysql//gvwstate.dat) failed(No such file or directory)
Feb 19 12:35:34 ip-172-31-19-192 mysqld: 2016-02-19 12:35:34 139912045295744 [Note] WSREP: restore pc from disk failed
Feb 19 12:35:34 ip-172-31-19-192 mysqld: 2016-02-19 12:35:34 139912045295744 [Note] WSREP: GMCast version 0
Feb 19 12:35:34 ip-172-31-19-192 mysqld: 2016-02-19 12:35:34 139912045295744 [Note] WSREP: (2e322b1a, 'tcp://0.0.0.0:4567') listening at tcp://0.0.0.0:4567
Feb 19 12:35:34 ip-172-31-19-192 mysqld: 2016-02-19 12:35:34 139912045295744 [Note] WSREP: (2e322b1a, 'tcp://0.0.0.0:4567') multicast: , ttl: 1
Feb 19 12:35:34 ip-172-31-19-192 mysqld: 2016-02-19 12:35:34 139912045295744 [Note] WSREP: EVS version 0
Feb 19 12:35:34 ip-172-31-19-192 mysqld: 2016-02-19 12:35:34 139912045295744 [Note] WSREP: gcomm: connecting to group 'my_wsrep_cluster', peer '172.31.22.174:,172.31.19.192:'
Feb 19 12:35:34 ip-172-31-19-192 mysqld: 2016-02-19 12:35:34 139912045295744 [Warning] WSREP: (2e322b1a, 'tcp://0.0.0.0:4567') address 'tcp://172.31.19.192:4567' points to own listening address, blacklisting
Feb 19 12:35:34 ip-172-31-19-192 mysqld: 2016-02-19 12:35:34 139912045295744 [Note] WSREP: (2e322b1a, 'tcp://0.0.0.0:4567') turning message relay requesting on, nonlive peers:
Feb 19 12:35:34 ip-172-31-19-192 mysqld: 2016-02-19 12:35:34 139912045295744 [Note] WSREP: declaring 474dfc6f at tcp://172.31.22.174:4567 stable
Feb 19 12:35:34 ip-172-31-19-192 mysqld: 2016-02-19 12:35:34 139912045295744 [Note] WSREP: Node 474dfc6f state prim
Feb 19 12:35:34 ip-172-31-19-192 mysqld: 2016-02-19 12:35:34 139912045295744 [Note] WSREP: view(view_id(PRIM,2e322b1a,10) memb {
Feb 19 12:35:34 ip-172-31-19-192 mysqld: 2e322b1a,0
Feb 19 12:35:34 ip-172-31-19-192 mysqld: 474dfc6f,0
Feb 19 12:35:34 ip-172-31-19-192 mysqld: } joined {
Feb 19 12:35:34 ip-172-31-19-192 mysqld: } left {
Feb 19 12:35:34 ip-172-31-19-192 mysqld: } partitioned {
Feb 19 12:35:34 ip-172-31-19-192 mysqld: })
Feb 19 12:35:34 ip-172-31-19-192 mysqld: 2016-02-19 12:35:34 139912045295744 [Note] WSREP: save pc into disk
Feb 19 12:35:35 ip-172-31-19-192 mysqld: 2016-02-19 12:35:35 139912045295744 [Note] WSREP: gcomm: connected
Feb 19 12:35:35 ip-172-31-19-192 mysqld: 2016-02-19 12:35:35 139912045295744 [Note] WSREP: Changing maximum packet size to 64500, resulting msg size: 32636
Feb 19 12:35:35 ip-172-31-19-192 mysqld: 2016-02-19 12:35:35 139912045295744 [Note] WSREP: Shifting CLOSED -> OPEN (TO: 0)
Feb 19 12:35:35 ip-172-31-19-192 mysqld: 2016-02-19 12:35:35 139912045295744 [Note] WSREP: Opened channel 'my_wsrep_cluster'
Feb 19 12:35:35 ip-172-31-19-192 mysqld: 2016-02-19 12:35:35 139911755720448 [Note] WSREP: New COMPONENT: primary = yes, bootstrap = no, my_idx = 0, memb_num = 2
Feb 19 12:35:35 ip-172-31-19-192 mysqld: 2016-02-19 12:35:35 139911755720448 [Note] WSREP: STATE_EXCHANGE: sent state UUID: 2ecb3fac-d72f-11e5-983f-a263893355be
Feb 19 12:35:35 ip-172-31-19-192 mysqld: 2016-02-19 12:35:35 139912045295744 [Note] WSREP: Waiting for SST to complete.
Feb 19 12:35:35 ip-172-31-19-192 mysqld: 2016-02-19 12:35:35 139911755720448 [Note] WSREP: STATE EXCHANGE: sent state msg: 2ecb3fac-d72f-11e5-983f-a263893355be
Feb 19 12:35:35 ip-172-31-19-192 mysqld: 2016-02-19 12:35:35 139911755720448 [Note] WSREP: STATE EXCHANGE: got state msg: 2ecb3fac-d72f-11e5-983f-a263893355be from 0 ()
Feb 19 12:35:35 ip-172-31-19-192 mysqld: 2016-02-19 12:35:35 139911755720448 [Note] WSREP: STATE EXCHANGE: got state msg: 2ecb3fac-d72f-11e5-983f-a263893355be from 1 ()
Feb 19 12:35:35 ip-172-31-19-192 mysqld: 2016-02-19 12:35:35 139911755720448 [Note] WSREP: Quorum results:
Feb 19 12:35:35 ip-172-31-19-192 mysqld: version    = 3,
Feb 19 12:35:35 ip-172-31-19-192 mysqld: component  = PRIMARY,
Feb 19 12:35:35 ip-172-31-19-192 mysqld: conf_id    = 9,
Feb 19 12:35:35 ip-172-31-19-192 mysqld: members    = 1/2 (joined/total),
Feb 19 12:35:35 ip-172-31-19-192 mysqld: act_id     = 1,
Feb 19 12:35:35 ip-172-31-19-192 mysqld: last_appl. = -1,
Feb 19 12:35:35 ip-172-31-19-192 mysqld: protocols  = 0/7/3 (gcs/repl/appl),
Feb 19 12:35:35 ip-172-31-19-192 mysqld: group UUID = 474f3f92-d723-11e5-8da3-d3e87bd5db9a
Feb 19 12:35:35 ip-172-31-19-192 mysqld: 2016-02-19 12:35:35 139911755720448 [Note] WSREP: Flow-control interval: [23, 23]
Feb 19 12:35:35 ip-172-31-19-192 mysqld: 2016-02-19 12:35:35 139911755720448 [Note] WSREP: Shifting OPEN -> PRIMARY (TO: 1)
Feb 19 12:35:35 ip-172-31-19-192 mysqld: 2016-02-19 12:35:35 139912044980992 [Note] WSREP: State transfer required:
Feb 19 12:35:35 ip-172-31-19-192 mysqld: Group state: 474f3f92-d723-11e5-8da3-d3e87bd5db9a:1
Feb 19 12:35:35 ip-172-31-19-192 mysqld: Local state: 00000000-0000-0000-0000-000000000000:-1
Feb 19 12:35:35 ip-172-31-19-192 mysqld: 2016-02-19 12:35:35 139912044980992 [Note] WSREP: New cluster view: global state: 474f3f92-d723-11e5-8da3-d3e87bd5db9a:1, view# 10: Primary, number of nodes: 2, my index: 0, protocol version 3
Feb 19 12:35:35 ip-172-31-19-192 mysqld: 2016-02-19 12:35:35 139912044980992 [Warning] WSREP: Gap in state sequence. Need state transfer.
Feb 19 12:35:35 ip-172-31-19-192 mysqld: 2016-02-19 12:35:35 139911747327744 [Note] WSREP: Running: 'wsrep_sst_rsync --role 'joiner' --address '172.31.19.192' --datadir '/var/lib/mysql/'   --parent '2625'  '' '
Feb 19 12:35:35 ip-172-31-19-192 rsyncd[2663]: rsyncd version 3.0.9 starting, listening on port 4444
Feb 19 12:35:35 ip-172-31-19-192 mysqld: 2016-02-19 12:35:35 139912044980992 [Note] WSREP: Prepared SST request: rsync|172.31.19.192:4444/rsync_sst
Feb 19 12:35:35 ip-172-31-19-192 mysqld: 2016-02-19 12:35:35 139912044980992 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
Feb 19 12:35:35 ip-172-31-19-192 mysqld: 2016-02-19 12:35:35 139912044980992 [Note] WSREP: REPL Protocols: 7 (3, 2)
Feb 19 12:35:35 ip-172-31-19-192 mysqld: 2016-02-19 12:35:35 139911814444800 [Note] WSREP: Service thread queue flushed.
Feb 19 12:35:35 ip-172-31-19-192 mysqld: 2016-02-19 12:35:35 139912044980992 [Note] WSREP: Assign initial position for certification: 1, protocol version: 3
Feb 19 12:35:35 ip-172-31-19-192 mysqld: 2016-02-19 12:35:35 139911814444800 [Note] WSREP: Service thread queue flushed.
Feb 19 12:35:35 ip-172-31-19-192 mysqld: 2016-02-19 12:35:35 139912044980992 [Warning] WSREP: Failed to prepare for incremental state transfer: Local state UUID (00000000-0000-0000-0000-000000000000) does not match group state UUID (474f3f92-d723-11e5-8da3-d3e87bd5db9a): 1 (Operation not permitted)
Feb 19 12:35:35 ip-172-31-19-192 mysqld: at galera/src/replicator_str.cpp:prepare_for_IST():482. IST will be unavailable.
Feb 19 12:35:35 ip-172-31-19-192 mysqld: 2016-02-19 12:35:35 139911755720448 [Note] WSREP: Member 0.0 () requested state transfer from '*any*'. Selected 1.0 ()(SYNCED) as donor.
Feb 19 12:35:35 ip-172-31-19-192 mysqld: 2016-02-19 12:35:35 139911755720448 [Note] WSREP: Shifting PRIMARY -> JOINER (TO: 1)
Feb 19 12:35:35 ip-172-31-19-192 mysqld: 2016-02-19 12:35:35 139912044980992 [Note] WSREP: Requesting state transfer: success, donor: 1
Feb 19 12:35:36 ip-172-31-19-192 mysqld: 2016-02-19 12:35:36 139911755720448 [Warning] WSREP: 1.0 (): State transfer to 0.0 () failed: -78 (Remote address changed)
Feb 19 12:35:36 ip-172-31-19-192 mysqld: 2016-02-19 12:35:36 139911755720448 [ERROR] WSREP: gcs/src/gcs_group.cpp:gcs_group_handle_join_msg():731: Will never receive state. Need to abort.
Feb 19 12:35:36 ip-172-31-19-192 mysqld: 2016-02-19 12:35:36 139911755720448 [Note] WSREP: gcomm: terminating thread
Feb 19 12:35:36 ip-172-31-19-192 mysqld: 2016-02-19 12:35:36 139911755720448 [Note] WSREP: gcomm: joining thread
Feb 19 12:35:36 ip-172-31-19-192 mysqld: 2016-02-19 12:35:36 139911755720448 [Note] WSREP: gcomm: closing backend
Feb 19 12:35:37 ip-172-31-19-192 mysqld: 2016-02-19 12:35:37 139911755720448 [Note] WSREP: view(view_id(NON_PRIM,2e322b1a,10) memb {
Feb 19 12:35:37 ip-172-31-19-192 mysqld: 2e322b1a,0
Feb 19 12:35:37 ip-172-31-19-192 mysqld: } joined {
Feb 19 12:35:37 ip-172-31-19-192 mysqld: } left {
Feb 19 12:35:37 ip-172-31-19-192 mysqld: } partitioned {
Feb 19 12:35:37 ip-172-31-19-192 mysqld: 474dfc6f,0
Feb 19 12:35:37 ip-172-31-19-192 mysqld: })
Feb 19 12:35:37 ip-172-31-19-192 mysqld: 2016-02-19 12:35:37 139911755720448 [Note] WSREP: (2e322b1a, 'tcp://0.0.0.0:4567') turning message relay requesting off
Feb 19 12:35:37 ip-172-31-19-192 mysqld: 2016-02-19 12:35:37 139911755720448 [Note] WSREP: view((empty))
Feb 19 12:35:37 ip-172-31-19-192 mysqld: 2016-02-19 12:35:37 139911755720448 [Note] WSREP: gcomm: closed
Feb 19 12:35:37 ip-172-31-19-192 mysqld: 2016-02-19 12:35:37 139911755720448 [Note] WSREP: /usr/sbin/mysqld: Terminated.
Feb 19 12:35:37 ip-172-31-19-192 systemd: mariadb.service: main process exited, code=killed, status=6/ABRT
Feb 19 12:35:37 ip-172-31-19-192 systemd: Failed to start MariaDB database server.
Feb 19 12:35:37 ip-172-31-19-192 systemd: Unit mariadb.service entered failed state.
Feb 19 12:35:38 ip-172-31-19-192 mysqld: WSREP_SST: [ERROR] Parent mysqld process (PID:2625) terminated unexpectedly. (20160219 12:35:38.462)
Feb 19 12:35:38 ip-172-31-19-192 mysqld: WSREP_SST: [INFO] Joiner cleanup. rsync PID: 2663 (20160219 12:35:38.464)
Feb 19 12:35:38 ip-172-31-19-192 systemd: Stopping MariaDB database server...
Feb 19 12:35:38 ip-172-31-19-192 systemd: Stopped MariaDB database server.
Feb 19 12:35:38 ip-172-31-19-192 rsyncd[2663]: rsync error: received SIGINT, SIGTERM, or SIGHUP (code 20) at rsync.c(551) [Receiver=3.0.9]
Feb 19 12:35:38 ip-172-31-19-192 mysqld: WSREP_SST: [INFO] Joiner cleanup done. (20160219 12:35:38.969)



 Comments   
Comment by Nirbhay Choubey (Inactive) [ 2016-02-26 ]

This is most likely due to MariaDB's current systemd Restart setting.

https://github.com/MariaDB/server/blob/10.1/support-files/mariadb.service.in#L69-L72

On SST failure, the node aborts and systemd tries to bring it back on. After multiple failed
attempts, I think the user/admin should either manually fix the problem and restart the node
or simply restart the service with Restart changed to a different value (e.g. Restart=no).

Comment by Daniel Black [ 2018-04-01 ]

While the SST failure could be change from an abort to some exit status, there's no easy way for systemd to go from that to say only restart exit status X only so many times.

Could do something more generically with https://www.freedesktop.org/software/systemd/man/systemd.unit.html#StartLimitBurst=

Comment by Jan Lindström [ 2023-04-11 ]

10.1 is EOL.

Generated at Thu Feb 08 07:35:54 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.