Problem with IST when a node is recovering after normal stop

Laurent MINOST

unread,

Mar 14, 2012, 8:35:10 AM3/14/12

to codersh...@googlegroups.com

Hi,

Using Galera with versions below :

Galera Library 23.2.0 - galera-23.2.0-src.tar.gz

and MySQL 5.5.20 - mysql-5.5.20_wsrep_23.4-linux-x86_64.tar.gz

3 nodes in the cluster and having a strange behaviour when I shutdown one of the node and restart it :

------ Log of node1 when shutting down node2 :

120314 12:41:42 [Note] WSREP: GMCast::handle_stable_view: view(view_id(PRIM,4eb79155-6d9d-11e1-0800-4ce267baa4ec,20) memb {

4eb79155-6d9d-11e1-0800-4ce267baa4ec,

8a274b9b-6dc2-11e1-0800-46dccafcd983,

} joined {

} left {

} partitioned {

54483391-6c53-11e1-0800-e9f853ac6358,

})

120314 12:41:42 [Note] WSREP: New COMPONENT: primary = yes, my_idx = 0, memb_num = 2

120314 12:41:42 [Note] WSREP: forgetting 54483391-6c53-11e1-0800-e9f853ac6358 (tcp://192.168.0.110:4567)

120314 12:41:42 [Note] WSREP: declaring 8a274b9b-6dc2-11e1-0800-46dccafcd983 stable

120314 12:41:42 [Note] WSREP: STATE_EXCHANGE: sent state UUID: ab3a978c-6dca-11e1-0800-1298391903f0

120314 12:41:42 [Note] WSREP: STATE EXCHANGE: sent state msg: ab3a978c-6dca-11e1-0800-1298391903f0

120314 12:41:42 [Note] WSREP: STATE EXCHANGE: got state msg: ab3a978c-6dca-11e1-0800-1298391903f0 from 0 (cygnus)

120314 12:41:42 [Note] WSREP: STATE EXCHANGE: got state msg: ab3a978c-6dca-11e1-0800-1298391903f0 from 1 (vmdebian2)

120314 12:41:42 [Note] WSREP: Quorum results:

version = 2,

component = PRIMARY,

conf_id = 19,

members = 2/2 (joined/total),

act_id = 114755,

last_appl. = 114523,

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

group UUID = 7757c866-6c09-11e1-0800-08c23d11f6b3

120314 12:41:42 [Note] WSREP: Flow-control interval: [12, 23]

120314 12:41:42 [Note] WSREP: New cluster view: global state: 7757c866-6c09-11e1-0800-08c23d11f6b3:114755, view# 20: Primary, number of nodes: 2, my index: 0, protocol version 1

120314 12:41:42 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.

120314 12:41:42 [Note] WSREP: Assign initial position for certification: 114755, protocol version: 2

120314 12:41:47 [Note] WSREP: cleaning up 54483391-6c53-11e1-0800-e9f853ac6358 (tcp://192.168.0.110:4567)

-> Seems OK

------ Log of node2 when shutting down node2 :

120314 12:41:41 [Note] /usr/sbin/mysqld: Normal shutdown

120314 12:41:41 [Note] WSREP: Stop replication

120314 12:41:41 [Note] WSREP: Closing send monitor...

120314 12:41:41 [Note] WSREP: Closed send monitor.

120314 12:41:41 [Note] WSREP: gcomm: terminating thread

120314 12:41:41 [Note] WSREP: gcomm: joining thread

120314 12:41:41 [Note] WSREP: gcomm: closing backend

120314 12:41:41 [Note] WSREP: evs::proto(54483391-6c53-11e1-0800-e9f853ac6358, LEAVING, view_id(REG,4eb79155-6d9d-11e1-0800-4ce267baa4ec,19)) uuid 4eb79155-6d9d-11e1-0800-4ce267baa4ec missing from install message, assuming partitioned

120314 12:41:41 [Note] WSREP: evs::proto(54483391-6c53-11e1-0800-e9f853ac6358, LEAVING, view_id(REG,4eb79155-6d9d-11e1-0800-4ce267baa4ec,19)) uuid 8a274b9b-6dc2-11e1-0800-46dccafcd983 missing from install message, assuming partitioned

120314 12:41:41 [Note] WSREP: New COMPONENT: primary = no, my_idx = 0, memb_num = 1

120314 12:41:41 [Note] WSREP: GMCast::handle_stable_view: view(view_id(NON_PRIM,4eb79155-6d9d-11e1-0800-4ce267baa4ec,19) memb {

54483391-6c53-11e1-0800-e9f853ac6358,

} joined {

} left {

} partitioned {

4eb79155-6d9d-11e1-0800-4ce267baa4ec,

8a274b9b-6dc2-11e1-0800-46dccafcd983,

})

120314 12:41:41 [Note] WSREP: GMCast::handle_stable_view: view((empty))

120314 12:41:41 [Note] WSREP: gcomm: closed

120314 12:41:41 [Note] WSREP: Flow-control interval: [8, 16]

120314 12:41:41 [Note] WSREP: Received NON-PRIMARY.

120314 12:41:41 [Note] WSREP: Shifting SYNCED -> OPEN (TO: 114755)

120314 12:41:41 [Note] WSREP: Received self-leave message.

120314 12:41:41 [Note] WSREP: Flow-control interval: [0, 0]

120314 12:41:41 [Note] WSREP: Received SELF-LEAVE. Closing connection.

120314 12:41:41 [Note] WSREP: Shifting OPEN -> CLOSED (TO: 114755)

120314 12:41:41 [Note] WSREP: RECV thread exiting 0: Success

120314 12:41:41 [Note] WSREP: New cluster view: global state: 7757c866-6c09-11e1-0800-08c23d11f6b3:114755, view# -1: non-Primary, number of nodes: 1, my index: 0, protocol version 1

120314 12:41:41 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.

120314 12:41:41 [Note] WSREP: New cluster view: global state: 7757c866-6c09-11e1-0800-08c23d11f6b3:114755, view# -1: non-Primary, number of nodes: 0, my index: -1, protocol version 1

120314 12:41:41 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.

120314 12:41:41 [Note] WSREP: applier thread exiting (code:0)

120314 12:41:41 [Note] WSREP: recv_thread() joined.

120314 12:41:41 [Note] WSREP: Closing slave action queue.

120314 12:41:43 [Note] WSREP: SST kill local trx: 246733

120314 12:41:43 [Note] WSREP: rollbacker thread exiting

120314 12:41:43 [Note] Event Scheduler: Purging the queue. 0 events

120314 12:41:43 [Note] WSREP: dtor state: CLOSED

120314 12:41:43 [Note] WSREP: apply mon: entered 0

120314 12:41:44 [Note] WSREP: mon: entered 111634 oooe fraction 0 oool fraction 8.06206e-05

120314 12:41:44 [Note] WSREP: cert index usage at exit 339

120314 12:41:44 [Note] WSREP: cert trx map usage at exit 234

120314 12:41:44 [Note] WSREP: deps set usage at exit 0

120314 12:41:44 [Note] WSREP: avg deps dist 90.8376

120314 12:41:44 [Note] WSREP: wsdb trx map usage 0 conn query map usage 0

120314 12:41:44 [Note] WSREP: Shifting CLOSED -> DESTROYED (TO: 114755)

120314 12:41:44 [Note] WSREP: Flushing memory map to disk...

120314 12:41:44 InnoDB: Starting shutdown...

120314 12:41:46 InnoDB: Shutdown completed; log sequence number 617857171

120314 12:41:46 [Note] /usr/sbin/mysqld: Shutdown complete

-> Seems OK

------ Log of node1 when restarting node2 :

120314 13:03:21 [Note] WSREP: (4eb79155-6d9d-11e1-0800-4ce267baa4ec, 'tcp://0.0.0.0:4567') cleaning up duplicate 0x7fc080001120 after established 0x7fc080001810

120314 13:03:21 [Note] WSREP: (4eb79155-6d9d-11e1-0800-4ce267baa4ec, 'tcp://0.0.0.0:4567') cleaning up duplicate 0x16ad9b0 after established 0x7fc080002430

120314 13:03:21 [Note] WSREP: New COMPONENT: primary = yes, my_idx = 0, memb_num = 3

120314 13:03:21 [Note] WSREP: GMCast::handle_stable_view: view(view_id(PRIM,4eb79155-6d9d-11e1-0800-4ce267baa4ec,21) memb {

4eb79155-6d9d-11e1-0800-4ce267baa4ec,

8a274b9b-6dc2-11e1-0800-46dccafcd983,

b0452092-6dcd-11e1-0800-555f18cbadc9,

} joined {

} left {

} partitioned {

})

120314 13:03:21 [Note] WSREP: declaring 8a274b9b-6dc2-11e1-0800-46dccafcd983 stable

120314 13:03:21 [Note] WSREP: declaring b0452092-6dcd-11e1-0800-555f18cbadc9 stable

120314 13:03:21 [Note] WSREP: STATE_EXCHANGE: sent state UUID: b1e22797-6dcd-11e1-0800-8b91e67379ba

120314 13:03:21 [Note] WSREP: STATE EXCHANGE: sent state msg: b1e22797-6dcd-11e1-0800-8b91e67379ba

120314 13:03:21 [Note] WSREP: STATE EXCHANGE: got state msg: b1e22797-6dcd-11e1-0800-8b91e67379ba from 0 (cygnus)

120314 13:03:21 [Note] WSREP: STATE EXCHANGE: got state msg: b1e22797-6dcd-11e1-0800-8b91e67379ba from 1 (vmdebian2)

120314 13:03:22 [Note] WSREP: STATE EXCHANGE: got state msg: b1e22797-6dcd-11e1-0800-8b91e67379ba from 2 (vmdebian1)

120314 13:03:22 [Note] WSREP: Quorum results:

version = 2,

component = PRIMARY,

conf_id = 20,

members = 2/3 (joined/total),

act_id = 116071,

last_appl. = 116068,

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

group UUID = 7757c866-6c09-11e1-0800-08c23d11f6b3

120314 13:03:22 [Note] WSREP: Flow-control interval: [14, 28]

120314 13:03:22 [Note] WSREP: New cluster view: global state: 7757c866-6c09-11e1-0800-08c23d11f6b3:116071, view# 21: Primary, number of nodes: 3, my index: 0, protocol version 1

120314 13:03:22 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.

120314 13:03:22 [Note] WSREP: Assign initial position for certification: 116071, protocol version: 2

120314 13:03:25 [Note] WSREP: Node 2 (vmdebian1) requested state transfer from '*any*'. Selected 0 (cygnus)(SYNCED) as donor.

120314 13:03:25 [Note] WSREP: Shifting SYNCED -> DONOR/DESYNCED (TO: 116073)

120314 13:03:25 [Note] WSREP: IST request: 7757c866-6c09-11e1-0800-08c23d11f6b3:114755-116071|tcp://192.168.0.110:4568

120314 13:03:25 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.

120314 13:03:25 [Note] WSREP: Running: 'wsrep_sst_rsync 'donor' '192.168.0.110:4444/rsync_sst' 'sst:5T13wPid' '/opt/mysql-galera/data/' '/etc/my-galera.cnf' '7757c866-6c09-11e1-0800-08c23d11f6b3' '114755' '1''

120314 13:03:25 [Note] WSREP: sst_donor_thread signaled with 0

120314 13:03:25 [Note] WSREP: async IST sender starting to serve tcp://192.168.0.110:4568 sending 114756-116071

------ Log of node2 when restarting node2 :

120314 13:03:07 mysqld_safe Starting mysqld daemon with databases from /var/lib/mysql

120314 13:03:07 [Note] WSREP: wsrep_load(): loading provider library '/usr/lib/galera/libgalera_smm.so'

120314 13:03:07 [Note] WSREP: wsrep_load(): Galera 23.2.0(r120) by Codership Oy <in...@codership.com> loaded succesfully.

120314 13:03:07 [Note] WSREP: Preallocating 134217728/268436768 bytes in '/var/lib/mysql//galera.cache'...

120314 13:03:18 [Note] WSREP: Passing config to GCS: gcache.dir = /var/lib/mysql/; gcache.keep_pages_size = 0; gcache.mem_size = 0; gcache.name = /var/lib/mysql//galera.cache; gcache.page_size = 256M; gcache.size = 256M; gcs.fc_debug = 0; gcs.fc_factor = 0.5; gcs.fc_limit = 16; gcs.fc_master_slave = NO; gcs.max_packet_size = 64500; gcs.max_throttle = 0.25; gcs.recv_q_hard_limit = 2147483647; gcs.recv_q_soft_limit = 0.25; replicator.causal_read_timeout = PT30S; replicator.commit_order = 3

120314 13:03:19 [Note] WSREP: wsrep_sst_grab()

120314 13:03:19 [Note] WSREP: Start replication

120314 13:03:19 [Note] WSREP: Found saved state: 7757c866-6c09-11e1-0800-08c23d11f6b3:114755

120314 13:03:19 [Note] WSREP: Assign initial position for certification: 114755, protocol version: -1

120314 13:03:19 [Note] WSREP: Setting initial position to 7757c866-6c09-11e1-0800-08c23d11f6b3:114755

120314 13:03:19 [Note] WSREP: protonet asio version 0

120314 13:03:19 [Note] WSREP: backend: asio

120314 13:03:19 [Note] WSREP: GMCast version 0

120314 13:03:19 [Note] WSREP: (b0452092-6dcd-11e1-0800-555f18cbadc9, 'tcp://0.0.0.0:4567') listening at tcp://0.0.0.0:4567

120314 13:03:19 [Note] WSREP: (b0452092-6dcd-11e1-0800-555f18cbadc9, 'tcp://0.0.0.0:4567') multicast: , ttl: 1

120314 13:03:19 [Note] WSREP: EVS version 0

120314 13:03:19 [Note] WSREP: PC version 0

120314 13:03:19 [Note] WSREP: gcomm: connecting to group 'my_wsrep_cluster', peer '192.168.0.4:4567'

120314 13:03:19 [Note] WSREP: (b0452092-6dcd-11e1-0800-555f18cbadc9, 'tcp://0.0.0.0:4567') cleaning up duplicate 0x8b06ba8 after established 0x8b17e98

120314 13:03:19 [Note] WSREP: GMCast::handle_stable_view: view(view_id(PRIM,4eb79155-6d9d-11e1-0800-4ce267baa4ec,21) memb {

4eb79155-6d9d-11e1-0800-4ce267baa4ec,

8a274b9b-6dc2-11e1-0800-46dccafcd983,

b0452092-6dcd-11e1-0800-555f18cbadc9,

} joined {

} left {

} partitioned {

})

120314 13:03:19 [Note] WSREP: declaring 4eb79155-6d9d-11e1-0800-4ce267baa4ec stable

120314 13:03:19 [Note] WSREP: declaring 8a274b9b-6dc2-11e1-0800-46dccafcd983 stable

120314 13:03:20 [Note] WSREP: gcomm: connected

120314 13:03:20 [Note] WSREP: Changing maximum packet size to 64500, resulting msg size: 32636

120314 13:03:20 [Note] WSREP: Shifting CLOSED -> OPEN (TO: 0)

120314 13:03:20 [Note] WSREP: Opened channel 'my_wsrep_cluster'

120314 13:03:20 [Note] WSREP: Waiting for SST to complete.

120314 13:03:20 [Note] WSREP: New COMPONENT: primary = yes, my_idx = 2, memb_num = 3

120314 13:03:20 [Note] WSREP: STATE EXCHANGE: Waiting for state UUID.

120314 13:03:20 [Note] WSREP: STATE EXCHANGE: sent state msg: b1e22797-6dcd-11e1-0800-8b91e67379ba

120314 13:03:20 [Note] WSREP: STATE EXCHANGE: got state msg: b1e22797-6dcd-11e1-0800-8b91e67379ba from 0 (cygnus)

120314 13:03:20 [Note] WSREP: STATE EXCHANGE: got state msg: b1e22797-6dcd-11e1-0800-8b91e67379ba from 1 (vmdebian2)

120314 13:03:20 [Note] WSREP: STATE EXCHANGE: got state msg: b1e22797-6dcd-11e1-0800-8b91e67379ba from 2 (vmdebian1)

120314 13:03:20 [Note] WSREP: Quorum results:

version = 2,

component = PRIMARY,

conf_id = 20,

members = 2/3 (joined/total),

act_id = 116071,

last_appl. = -1,

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

group UUID = 7757c866-6c09-11e1-0800-08c23d11f6b3

120314 13:03:20 [Note] WSREP: Flow-control interval: [14, 28]

120314 13:03:20 [Note] WSREP: Shifting OPEN -> PRIMARY (TO: 116071)

120314 13:03:20 [Note] WSREP: State transfer required:

Group state: 7757c866-6c09-11e1-0800-08c23d11f6b3:116071

Local state: 7757c866-6c09-11e1-0800-08c23d11f6b3:114755

120314 13:03:20 [Note] WSREP: New cluster view: global state: 7757c866-6c09-11e1-0800-08c23d11f6b3:116071, view# 21: Primary, number of nodes: 3, my index: 2, protocol version 1

120314 13:03:20 [Warning] WSREP: Gap in state sequence. Need state transfer.

120314 13:03:22 [Note] WSREP: Running: 'wsrep_sst_rsync 'joiner' '192.168.0.110' 'sst:5T13wPid' '/var/lib/mysql/' '/etc/mysql/my.cnf' '1176' 2>sst.err'

120314 13:03:23 [Note] WSREP: Prepared SST request: rsync|192.168.0.110:4444/rsync_sst

120314 13:03:23 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.

120314 13:03:23 [Note] WSREP: Assign initial position for certification: 116071, protocol version: 2

120314 13:03:23 [Note] WSREP: Prepared IST receiver, listening at: tcp://192.168.0.110:4568

120314 13:03:23 [Note] WSREP: Node 2 (vmdebian1) requested state transfer from '*any*'. Selected 0 (cygnus)(SYNCED) as donor.

120314 13:03:23 [Note] WSREP: Shifting PRIMARY -> JOINER (TO: 116073)

120314 13:03:23 [Note] WSREP: Requesting state transfer: success, donor: 0

120314 13:03:25 [Note] WSREP: SST complete, seqno: 114755

120314 13:03:25 [ERROR] Can't open shared library '/usr/lib/galera/semisync_master.so' (errno: 0 cannot open shared object file: No such file or directory)

120314 13:03:25 [Warning] Couldn't load plugin named 'rpl_semi_sync_master' with soname 'semisync_master.so'.

120314 13:03:25 [ERROR] Can't open shared library '/usr/lib/galera/semisync_slave.so' (errno: 0 cannot open shared object file: No such file or directory)

120314 13:03:25 [Warning] Couldn't load plugin named 'rpl_semi_sync_slave' with soname 'semisync_slave.so'.

120314 13:03:25 InnoDB: The InnoDB memory heap is disabled

120314 13:03:25 InnoDB: Mutexes and rw_locks use GCC atomic builtins

120314 13:03:25 InnoDB: Compressed tables use zlib 1.2.3.3

120314 13:03:25 InnoDB: Using Linux native AIO

120314 13:03:25 InnoDB: Initializing buffer pool, size = 64.0M

120314 13:03:25 InnoDB: Completed initialization of buffer pool

120314 13:03:25 InnoDB: highest supported file format is Barracuda.

120314 13:03:26 InnoDB: Waiting for the background threads to start

120314 13:03:27 InnoDB: 1.1.8 started; log sequence number 617857171

120314 13:03:28 [Note] Event Scheduler: Loaded 0 events

120314 13:03:28 [Note] WSREP: Signalling provider to continue.

120314 13:03:28 [Note] WSREP: Received SST: 7757c866-6c09-11e1-0800-08c23d11f6b3:114755

120314 13:03:28 [Note] WSREP: SST received: 7757c866-6c09-11e1-0800-08c23d11f6b3:114755

120314 13:03:28 [Note] WSREP: Receiving IST: 1316 writesets, seqnos 114755-116071

120314 13:03:28 [Note] /usr/sbin/mysqld: ready for connections.

Version: '5.5.20-log' socket: '/var/lib/mysql/mysql.sock' port: 3306 Source distribution, wsrep_23.4.r3713

120314 13:03:59 [Warning] IP address '192.168.0.1' could not be resolved: Name or service not known

Then, I can wait even for hours but nothing new is happening and this is the status of the 2 nodes through mysql shell :

node1 :

mysql> show status like 'wsrep%';

+----------------------------+--------------------------------------+

| Variable_name | Value |

+----------------------------+--------------------------------------+

| wsrep_local_state_uuid | 7757c866-6c09-11e1-0800-08c23d11f6b3 |

| wsrep_protocol_version | 3 |

| wsrep_last_committed | 117834 |

| wsrep_replicated | 6412 |

| wsrep_replicated_bytes | 12888505 |

| wsrep_received | 14039 |

| wsrep_received_bytes | 31360018 |

| wsrep_local_commits | 6375 |

| wsrep_local_cert_failures | 3 |

| wsrep_local_bf_aborts | 129 |

| wsrep_local_replays | 103 |

| wsrep_local_send_queue | 0 |

| wsrep_local_send_queue_avg | 0.000000 |

| wsrep_local_recv_queue | 0 |

| wsrep_local_recv_queue_avg | 0.000000 |

| wsrep_flow_control_paused | 0.000000 |

| wsrep_flow_control_sent | 0 |

| wsrep_flow_control_recv | 0 |

| wsrep_cert_deps_distance | 93.660767 |

| wsrep_apply_oooe | 0.000000 |

| wsrep_apply_oool | 0.000000 |

| wsrep_apply_window | 1.000000 |

| wsrep_commit_oooe | 0.000000 |

| wsrep_commit_oool | 0.000000 |

| wsrep_commit_window | 1.000000 |

| wsrep_local_state | 2 |

| wsrep_local_state_comment | Donor (+) |

| wsrep_cert_index_size | 1866 |

| wsrep_cluster_conf_id | 21 |

| wsrep_cluster_size | 3 |

| wsrep_cluster_state_uuid | 7757c866-6c09-11e1-0800-08c23d11f6b3 |

| wsrep_cluster_status | Primary |

| wsrep_connected | ON |

| wsrep_local_index | 0 |

| wsrep_provider_name | Galera |

| wsrep_provider_vendor | Codership Oy <in...@codership.com> |

| wsrep_provider_version | 2.0(rXXXX) |

| wsrep_ready | ON |

+----------------------------+--------------------------------------+

38 rows in set (0.00 sec)

node2 :

mysql> show status like 'wsrep%';

+----------------------------+--------------------------------------+

| Variable_name | Value |

+----------------------------+--------------------------------------+

| wsrep_local_state_uuid | 7757c866-6c09-11e1-0800-08c23d11f6b3 |

| wsrep_protocol_version | 3 |

| wsrep_last_committed | 114755 |

| wsrep_replicated | 0 |

| wsrep_replicated_bytes | 0 |

| wsrep_received | 1 |

| wsrep_received_bytes | 243 |

| wsrep_local_commits | 0 |

| wsrep_local_cert_failures | 0 |

| wsrep_local_bf_aborts | 0 |

| wsrep_local_replays | 0 |

| wsrep_local_send_queue | 0 |

| wsrep_local_send_queue_avg | 0.000000 |

| wsrep_local_recv_queue | 1766 |

| wsrep_local_recv_queue_avg | 0.000000 |

| wsrep_flow_control_paused | 0.000000 |

| wsrep_flow_control_sent | 0 |

| wsrep_flow_control_recv | 0 |

| wsrep_cert_deps_distance | 0.000000 |

| wsrep_apply_oooe | 0.000000 |

| wsrep_apply_oool | 0.000000 |

| wsrep_apply_window | 0.000000 |

| wsrep_commit_oooe | 0.000000 |

| wsrep_commit_oool | 0.000000 |

| wsrep_commit_window | 0.000000 |

| wsrep_local_state | 1 |

| wsrep_local_state_comment | Waiting for SST (4) |

| wsrep_cert_index_size | 0 |

| wsrep_cluster_conf_id | 21 |

| wsrep_cluster_size | 3 |

| wsrep_cluster_state_uuid | 7757c866-6c09-11e1-0800-08c23d11f6b3 |

| wsrep_cluster_status | Primary |

| wsrep_connected | ON |

| wsrep_local_index | 2 |

| wsrep_provider_name | Galera |

| wsrep_provider_vendor | Codership Oy <in...@codership.com> |

| wsrep_provider_version | 23.2.0(r120) |

| wsrep_ready | OFF |

+----------------------------+--------------------------------------+

38 rows in set (0.00 sec)

node3 is OK and status 4 with comment Synced (6).

Some questions/wondering :

- Why the node2 seems not being able to recover IST from node1 ?

- If I understand well, as node2 is waiting to be sync from node1 then it is unavailable for serving requests -> seems logical, but what is the status for node1 ? It is showing local state 2 / Donor (+), does the node is available to serve request (select & insert) in this state or not ? If it's not the case then I only have 1 node available out of free in this case and so with a high traffic this can be a problem ...

- I saw a Warning message about my IP address 192.168.0.1 (which is the main IP address of eth0 for node1) but node is listening on 192.168.0.4 which is an alias of eth0 :

eth0 Link encap:Ethernet HWaddr 00:13:D4:87:35:3A

inet adr:192.168.0.1 Bcast:192.168.0.255 Masque:255.255.255.0

eth0:3 Link encap:Ethernet HWaddr 00:13:D4:87:35:3A

inet adr:192.168.0.4 Bcast:192.168.0.255 Masque:255.255.255.0

node2 is having IP address 192.168.0.110 :

eth0 Link encap:Ethernet HWaddr 08:00:27:28:83:d7

inet adr:192.168.0.110 Bcast:192.168.0.255 Masque:255.255.255.0

Does the alias can cause a problem ?

Any help/advices would be very appreciated, thanks by advance for your time.

BR,

Laurent

Alex Yurchenko

unread,

Mar 14, 2012, 10:14:23 AM3/14/12

to codersh...@googlegroups.com

Hi,

Excellent information coverage!

On both nodes: sudo iptables -L

port 4568 must be open.

If that does not help, on node1 try

telnet 192.168.0.110 4568

> - If I understand well, as node2 is waiting to be sync from node1
> then it
> is unavailable for serving requests -> seems logical, but what is the
> status for node1 ? It is showing local state 2 / Donor (+), does the
> node
> is available to serve request (select & insert) in this state or not
> ? If
> it's not the case then I only have 1 node available out of free in
> this
> case and so with a high traffic this can be a problem ...

It is a bit complicated - Donor state actually consists of some
"substates". So, Donor won't reject SQL request (wsrep_ready=ON). But
depending on the "substate" COMMIT (or autocommit) may be blocked if
Donor is serving mysqldump or rsync. If Donor is serving IST, there is
no blocking.

> - I saw a Warning message about my IP address 192.168.0.1 (which is
> the
> main IP address of eth0 for node1) but node is listening on
> 192.168.0.4
> which is an alias of eth0 :

It is not a wsrep warning, so it is unrelated. Most likely it comes
from mysql authentication module, complaining about client connection.

> eth0 Link encap:Ethernet HWaddr 00:13:D4:87:35:3A
> inet adr:192.168.0.1 Bcast:192.168.0.255
> Masque:255.255.255.0
>
> eth0:3 Link encap:Ethernet HWaddr 00:13:D4:87:35:3A
> inet adr:192.168.0.4 Bcast:192.168.0.255
> Masque:255.255.255.0
>
> node2 is having IP address 192.168.0.110 :
> eth0 Link encap:Ethernet HWaddr 08:00:27:28:83:d7
> inet adr:192.168.0.110 Bcast:192.168.0.255
> Masque:255.255.255.0
>
> Does the alias can cause a problem ?

It should not.

> Any help/advices would be very appreciated, thanks by advance for
> your time.

See above about iptables. Typically firewall rules just silently drop
packets.

Regards,
Alex

> BR,
>
> Laurent

--
Alexey Yurchenko,
Codership Oy, www.codership.com
Skype: alexey.yurchenko, Phone: +358-400-516-011

Laurent MINOST

unread,

Mar 14, 2012, 11:26:08 AM3/14/12

to codersh...@googlegroups.com

Le mercredi 14 mars 2012 15:14:23 UTC+1, Alexey Yurchenko a écrit :

Hi,
Excellent information coverage!

Thks, I think that the more informations I provide then less difficult it will be for us to find the root cause ;)

-> node1 is having firewall rules enabled via iptables but accepting all traffic from 192.168.0.0/24 first :

Chain INPUT (policy ACCEPT)

...

ACCEPT all -- 192.168.0.0/24 anywhere

...

More, I have a chain dedicated to rules dropped for being logged (Chain LOG_DROP) so I check system logs and no drop there.
As a last test, if we did not find the cause after this, I will make a test without any firewall/iptables rules on this node.

-> node2 is having iptables installed but not used so no rules :

root@vmdebian1:/var/log/mysql# sudo iptables -L

Chain INPUT (policy ACCEPT)

target prot opt source destination

Chain FORWARD (policy ACCEPT)

target prot opt source destination

Chain OUTPUT (policy ACCEPT)

target prot opt source destination

port 4568 must be open.

Do you mean it should be listening and always bind or only when IST is running ? because at the moment (I restarted the two nodes and they finally got sync through total rsync sync), I have no 4568 port listening on the *three* nodes :

# netstat -lpvnt | grep 4568

#

If that does not help, on node1 try
telnet 192.168.0.110 4568

# telnet 192.168.0.110 4568

Trying 192.168.0.110...

telnet: connect to address 192.168.0.110: Connection refused

-> logic cause of the non listening port on node2 but is it normal ?

> - If I understand well, as node2 is waiting to be sync from node1
> then it
> is unavailable for serving requests -> seems logical, but what is the
> status for node1 ? It is showing local state 2 / Donor (+), does the
> node
> is available to serve request (select & insert) in this state or not
> ? If
> it's not the case then I only have 1 node available out of free in
> this
> case and so with a high traffic this can be a problem ...
It is a bit complicated - Donor state actually consists of some
"substates". So, Donor won't reject SQL request (wsrep_ready=ON). But
depending on the "substate" COMMIT (or autocommit) may be blocked if
Donor is serving mysqldump or rsync. If Donor is serving IST, there is
no blocking.

Ok thks a lot for clearing all these steps :) I was very interested in the answer to this question because I'm using an HAproxy load balancer in front of Galera cluster to dispatch requests to 3 nodes, it is working through a check on an xinetd service running on each node which ask node status through a bash script connecting to the mysql service and checking the 'wsrep_local_state' service to see the node state, for the moment I have only authorized this script, and consequently HAproxy, to mark node as UP if it returns state 4 (Synced (6)), all others states marked the node as DOWN which makes the whole cluster with 1 node only left when full resync of a node is needed because I have then one node in state 2 (Donor) and the other one in state 1 (Waiting for SST). With IST working, it would be very very more efficient I think :)

> - I saw a Warning message about my IP address 192.168.0.1 (which is
> the
> main IP address of eth0 for node1) but node is listening on
> 192.168.0.4
> which is an alias of eth0 :
It is not a wsrep warning, so it is unrelated. Most likely it comes
from mysql authentication module, complaining about client connection.

OK, thks ! Good to know, I have some cron checking for mysql status and variables so it is probably that.

> eth0 Link encap:Ethernet HWaddr 00:13:D4:87:35:3A
> inet adr:192.168.0.1 Bcast:192.168.0.255
> Masque:255.255.255.0
>
> eth0:3 Link encap:Ethernet HWaddr 00:13:D4:87:35:3A
> inet adr:192.168.0.4 Bcast:192.168.0.255
> Masque:255.255.255.0
>
> node2 is having IP address 192.168.0.110 :
> eth0 Link encap:Ethernet HWaddr 08:00:27:28:83:d7
> inet adr:192.168.0.110 Bcast:192.168.0.255
> Masque:255.255.255.0
>
> Does the alias can cause a problem ?
It should not.

I should be able to put the service listening on node1 on the main IP addresse of eth0 instead of the aliased IP address so I will be able to discard this hypothetic pb. Will try and let you know.

> Any help/advices would be very appreciated, thanks by advance for
> your time.
See above about iptables. Typically firewall rules just silently drop
packets.
Regards,
Alex

Thks for your time and support Alex ;)

Laurent MINOST

unread,

Mar 14, 2012, 11:42:07 AM3/14/12

to codersh...@googlegroups.com

Hi again,

having some new informations that can be useful, after restarting node1 to change its IP Address to 192.168.0.1, I'm now having in their logs :

-> node1 (192.168.0.1), named 'cygnus' :

120314 16:27:45 [Note] /opt/mysql-galera/bin/mysqld: Shutdown complete

120314 16:27:45 mysqld_safe mysqld from pid file /opt/mysql-galera/data/mysqld.pid ended

120314 16:31:13 mysqld_safe Starting mysqld daemon with databases from /opt/mysql-galera/data

120314 16:31:13 [Note] WSREP: wsrep_load(): loading provider library '/opt/mysql-galera/lib/plugin/libgalera_smm.so'

120314 16:31:13 [Note] WSREP: wsrep_load(): Galera 2.0(rXXXX) by Codership Oy <in...@codership.com> loaded succesfully.

120314 16:31:13 [Note] WSREP: Reusing existing '/opt/mysql-galera/data//galera.cache'.

120314 16:31:13 [Note] WSREP: Passing config to GCS: gcache.dir = /opt/mysql-galera/data/; gcache.keep_pages_size = 0; gcache.mem_size = 0; gcache.name = /opt/mysql-galera/data//galera.cache; gcache.page_size = 256M; gcache.size = 256M; gcs.fc_debug = 0; gcs.fc_factor = 0.5; 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; replicator.causal_read_timeout = PT30S; replicator.commit_order = 3

120314 16:31:13 [Note] WSREP: wsrep_sst_grab()

120314 16:31:13 [Note] WSREP: Start replication

120314 16:31:13 [Note] WSREP: Found saved state: 7757c866-6c09-11e1-0800-08c23d11f6b3:130077

120314 16:31:13 [Note] WSREP: Assign initial position for certification: 130077, protocol version: -1

120314 16:31:13 [Note] WSREP: Setting initial position to 7757c866-6c09-11e1-0800-08c23d11f6b3:130077

120314 16:31:13 [Note] WSREP: protonet asio version 0

120314 16:31:13 [Note] WSREP: backend: asio

120314 16:31:13 [Note] WSREP: GMCast version 0

120314 16:31:13 [Note] WSREP: (bbb18bd3-6dea-11e1-0800-fe0178262e69, 'tcp://0.0.0.0:4567') listening at tcp://0.0.0.0:4567

120314 16:31:13 [Note] WSREP: (bbb18bd3-6dea-11e1-0800-fe0178262e69, 'tcp://0.0.0.0:4567') multicast: , ttl: 1

120314 16:31:13 [Note] WSREP: EVS version 0

120314 16:31:13 [Note] WSREP: PC version 0

120314 16:31:13 [Note] WSREP: gcomm: connecting to group 'my_wsrep_cluster', peer '192.168.0.120:4567'

120314 16:31:15 [Warning] WSREP: last inactive check more than PT1.5S ago, skipping check

120314 16:31:15 [Note] WSREP: GMCast::handle_stable_view: view(view_id(PRIM,2e60c6fc-6ddf-11e1-0800-f373f6654f39,31) memb {

2e60c6fc-6ddf-11e1-0800-f373f6654f39,

8da57a23-6dde-11e1-0800-f64f42cfeef4,

bbb18bd3-6dea-11e1-0800-fe0178262e69,

} joined {

} left {

} partitioned {

})

120314 16:31:15 [Note] WSREP: declaring 2e60c6fc-6ddf-11e1-0800-f373f6654f39 stable

120314 16:31:15 [Note] WSREP: declaring 8da57a23-6dde-11e1-0800-f64f42cfeef4 stable

120314 16:31:16 [Note] WSREP: gcomm: connected

120314 16:31:16 [Note] WSREP: Changing maximum packet size to 64500, resulting msg size: 32636

120314 16:31:16 [Note] WSREP: Shifting CLOSED -> OPEN (TO: 0)

120314 16:31:16 [Note] WSREP: Opened channel 'my_wsrep_cluster'

120314 16:31:16 [Note] WSREP: New COMPONENT: primary = yes, my_idx = 2, memb_num = 3

120314 16:31:16 [Note] WSREP: Waiting for SST to complete.

120314 16:31:16 [Note] WSREP: STATE EXCHANGE: Waiting for state UUID.

120314 16:31:16 [Note] WSREP: STATE EXCHANGE: sent state msg: bc9af775-6dea-11e1-0800-a0a69dbf0e19

120314 16:31:16 [Note] WSREP: STATE EXCHANGE: got state msg: bc9af775-6dea-11e1-0800-a0a69dbf0e19 from 0 (vmdebian1)

120314 16:31:16 [Note] WSREP: STATE EXCHANGE: got state msg: bc9af775-6dea-11e1-0800-a0a69dbf0e19 from 1 (vmdebian2)

120314 16:31:16 [Note] WSREP: STATE EXCHANGE: got state msg: bc9af775-6dea-11e1-0800-a0a69dbf0e19 from 2 (cygnus)

120314 16:31:16 [Note] WSREP: Quorum results:

version = 2,

component = PRIMARY,

conf_id = 30,

members = 2/3 (joined/total),

act_id = 130402,

last_appl. = -1,

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

group UUID = 7757c866-6c09-11e1-0800-08c23d11f6b3

120314 16:31:16 [Note] WSREP: Flow-control interval: [14, 28]

120314 16:31:16 [Note] WSREP: Shifting OPEN -> PRIMARY (TO: 130402)

120314 16:31:16 [Note] WSREP: State transfer required:

Group state: 7757c866-6c09-11e1-0800-08c23d11f6b3:130402

Local state: 7757c866-6c09-11e1-0800-08c23d11f6b3:130077

120314 16:31:16 [Note] WSREP: New cluster view: global state: 7757c866-6c09-11e1-0800-08c23d11f6b3:130402, view# 31: Primary, number of nodes: 3, my index: 2, protocol version 1

120314 16:31:16 [Warning] WSREP: Gap in state sequence. Need state transfer.

120314 16:31:18 [Note] WSREP: Running: 'wsrep_sst_rsync 'joiner' '192.168.0.1' 'sst:5T13wPid' '/opt/mysql-galera/data/' '/etc/my-galera.cnf' '6815' 2>sst.err'

120314 16:31:18 [Note] WSREP: Prepared SST request: rsync|192.168.0.1:4444/rsync_sst

120314 16:31:18 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.

120314 16:31:18 [Note] WSREP: Assign initial position for certification: 130402, protocol version: 2

120314 16:31:18 [Note] WSREP: Prepared IST receiver, listening at: tcp://192.168.0.1:4568

120314 16:31:18 [Note] WSREP: Node 2 (cygnus) requested state transfer from '*any*'. Selected 0 (vmdebian1)(SYNCED) as donor.

120314 16:31:18 [Note] WSREP: Shifting PRIMARY -> JOINER (TO: 130402)

120314 16:31:18 [Note] WSREP: Requesting state transfer: success, donor: 0

120314 16:31:20 [Note] WSREP: SST complete, seqno: 130077

120314 16:31:20 InnoDB: The InnoDB memory heap is disabled

120314 16:31:20 InnoDB: Mutexes and rw_locks use GCC atomic builtins

120314 16:31:20 InnoDB: Compressed tables use zlib 1.2.3

120314 16:31:20 InnoDB: Using Linux native AIO

120314 16:31:20 InnoDB: Initializing buffer pool, size = 512.0M

120314 16:31:20 InnoDB: Completed initialization of buffer pool

120314 16:31:21 InnoDB: highest supported file format is Barracuda.

120314 16:31:22 InnoDB: Waiting for the background threads to start

120314 16:31:23 InnoDB: 1.1.8 started; log sequence number 639903874

120314 16:31:23 [Note] Event Scheduler: Loaded 0 events

120314 16:31:23 [Note] WSREP: Signalling provider to continue.

120314 16:31:23 [Note] WSREP: Received SST: 7757c866-6c09-11e1-0800-08c23d11f6b3:130077

120314 16:31:23 [Note] WSREP: SST received: 7757c866-6c09-11e1-0800-08c23d11f6b3:130077

120314 16:31:23 [Note] WSREP: Receiving IST: 325 writesets, seqnos 130077-130402

120314 16:31:23 [Note] /opt/mysql-galera/bin/mysqld: ready for connections.

Version: '5.5.20-log' socket: '/opt/mysql-galera/data/mysql.sock' port: 3306 Source distribution, wsrep_23.4.r3713

-> node2 (192.168.0.110) named 'vmdebian1' :

120314 16:31:15 [Note] WSREP: New COMPONENT: primary = yes, my_idx = 0, memb_num = 3

120314 16:31:15 [Note] WSREP: GMCast::handle_stable_view: view(view_id(PRIM,2e60c6fc-6ddf-11e1-0800-f373f6654f39,31) memb {

2e60c6fc-6ddf-11e1-0800-f373f6654f39,

8da57a23-6dde-11e1-0800-f64f42cfeef4,

bbb18bd3-6dea-11e1-0800-fe0178262e69,

} joined {

} left {

} partitioned {

})

120314 16:31:15 [Note] WSREP: declaring 8da57a23-6dde-11e1-0800-f64f42cfeef4 stable

120314 16:31:15 [Note] WSREP: declaring bbb18bd3-6dea-11e1-0800-fe0178262e69 stable

120314 16:31:15 [Note] WSREP: STATE_EXCHANGE: sent state UUID: bc9af775-6dea-11e1-0800-a0a69dbf0e19

120314 16:31:15 [Note] WSREP: STATE EXCHANGE: sent state msg: bc9af775-6dea-11e1-0800-a0a69dbf0e19

120314 16:31:15 [Note] WSREP: STATE EXCHANGE: got state msg: bc9af775-6dea-11e1-0800-a0a69dbf0e19 from 0 (vmdebian1)

120314 16:31:15 [Note] WSREP: STATE EXCHANGE: got state msg: bc9af775-6dea-11e1-0800-a0a69dbf0e19 from 1 (vmdebian2)

120314 16:31:15 [Note] WSREP: STATE EXCHANGE: got state msg: bc9af775-6dea-11e1-0800-a0a69dbf0e19 from 2 (cygnus)

120314 16:31:15 [Note] WSREP: Quorum results:

version = 2,

component = PRIMARY,

conf_id = 30,

members = 2/3 (joined/total),

act_id = 130402,

last_appl. = 130067,

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

group UUID = 7757c866-6c09-11e1-0800-08c23d11f6b3

120314 16:31:15 [Note] WSREP: Flow-control interval: [14, 28]

120314 16:31:15 [Note] WSREP: New cluster view: global state: 7757c866-6c09-11e1-0800-08c23d11f6b3:130402, view# 31: Primary, number of nodes: 3, my index: 0, protocol version 1

120314 16:31:15 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.

120314 16:31:15 [Note] WSREP: Assign initial position for certification: 130402, protocol version: 2

120314 16:31:18 [Note] WSREP: Node 2 (cygnus) requested state transfer from '*any*'. Selected 0 (vmdebian1)(SYNCED) as donor.

120314 16:31:18 [Note] WSREP: Shifting SYNCED -> DONOR/DESYNCED (TO: 130402)

120314 16:31:18 [Note] WSREP: IST request: 7757c866-6c09-11e1-0800-08c23d11f6b3:130077-130402|tcp://192.168.0.1:4568

120314 16:31:18 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.

120314 16:31:18 [Note] WSREP: Running: 'wsrep_sst_rsync 'donor' '192.168.0.1:4444/rsync_sst' 'sst:5T13wPid' '/var/lib/mysql/' '/etc/mysql/my.cnf' '7757c866-6c09-11e1-0800-08c23d11f6b3' '130077' '1''

120314 16:31:18 [Note] WSREP: sst_donor_thread signaled with 0

120314 16:31:18 [Note] WSREP: async IST sender starting to serve tcp://192.168.0.1:4568 sending 130078-130402

So on the log from node1 I can see an entry saying :

120314 16:31:18 [Note] WSREP: Prepared IST receiver, listening at: tcp://192.168.0.1:4568

but after verifying on the node I can tell you that there is no service listening on this port so maybe the root cause is there but why it's not listening ? :

# netstat -lpvnt | grep -i 4568

#

Maybe it's explaining the last entry in node2's logs which is saying sending IST probably to a non existing/binded service at node1 ... ?

Hope it will help ?

BR,

Laurent

Alex Yurchenko

unread,

Mar 14, 2012, 12:13:31 PM3/14/12

to codersh...@googlegroups.com

This is all very mysterious.

Any firewalls/NATs/routers between the nodes?

Any chance to see an output of

gdb --batch -ex 'thr apply all bt' -p $(pidof mysqld)
/opt/mysql-galera/bin/mysqld

from node1?

Also could you post output of

netstat -anpt | grep 4568

on BOTH nodes?

Also, what distribution/libstdc++ version?

Thanks,
Alex

--

Laurent MINOST

unread,

Mar 14, 2012, 5:44:59 PM3/14/12

to codersh...@googlegroups.com

Le mercredi 14 mars 2012 17:13:31 UTC+1, Alexey Yurchenko a écrit :

This is all very mysterious.
Any firewalls/NATs/routers between the nodes?

Nothing, only a switch on which PCs are connected : Cluster is a test environment, node1 is a Linux server, node2 is a VirtualBox's virtual machine, node3 is also another VirtualBox's virtual machine.
node2 and 3 are on the same Linux server connected to the same switch as node1, very basic architecture.

Any chance to see an output of
gdb --batch -ex 'thr apply all bt' -p $(pidof mysqld)
/opt/mysql-galera/bin/mysqld
from node1?

Sure, I attached you the output from gdb in a file named gdb_galera.txt.
Don't hesitate if you need any others informations, command output.

Also could you post output of
netstat -anpt | grep 4568
on BOTH nodes?

Same as the one already outputed before :

-> node1 :

[root@cygnus MAISON ~]# netstat -anpt | grep 4568

[root@cygnus MAISON ~]#

-> node2 :

root@vmdebian1:~# netstat -anpt | grep 4568

root@vmdebian1:~#

-> node3 :
root@vmdebian2:~# netstat -anpt | grep 4568
root@vmdebian2:~#

Also, what distribution/libstdc++ version?

-> node1 :

# cat /etc/fedora-release

Fedora release 16 (Verne)

# uname -a

Linux cygnus 3.2.3-2.fc16.x86_64 #1 SMP Fri Feb 3 20:08:08 UTC 2012 x86_64 x86_64 x86_64 GNU/Linux

# rpm -qa | grep -i libstdc++

libstdc++-devel-4.6.2-1.fc16.x86_64

compat-libstdc++-33-3.2.3-68.1.i686

libstdc++-4.6.2-1.fc16.i686

compat-libstdc++-33-3.2.3-68.1.x86_64

compat-libstdc++-296-2.96-143.1.i686

libstdc++-4.6.2-1.fc16.x86_64

[root@cygnus MAISON lib64]# ls -al /usr/lib/libstdc++*

-rwxr-xr-x 1 root root 272892 8 févr. 2011 /usr/lib/libstdc++-3-libc6.2-2-2.10.0.so

lrwxrwxrwx. 1 root root 31 31 juil. 2011 /usr/lib/libstdc++-libc6.2-2.so.3 -> libstdc++-3-libc6.2-2-2.10.0.so

lrwxrwxrwx. 1 root root 18 31 juil. 2011 /usr/lib/libstdc++.so.5 -> libstdc++.so.5.0.7

-rwxr-xr-x. 1 root root 733376 8 févr. 2011 /usr/lib/libstdc++.so.5.0.7

lrwxrwxrwx 1 root root 19 20 janv. 18:28 /usr/lib/libstdc++.so.6 -> libstdc++.so.6.0.16

-rwxr-xr-x 1 root root 934428 27 oct. 13:34 /usr/lib/libstdc++.so.6.0.16

[root@cygnus MAISON lib64]# ls -al /usr/lib64/libstdc++*

lrwxrwxrwx. 1 root root 18 31 juil. 2011 /usr/lib64/libstdc++.so.5 -> libstdc++.so.5.0.7

-rwxr-xr-x. 1 root root 825592 8 févr. 2011 /usr/lib64/libstdc++.so.5.0.7

lrwxrwxrwx 1 root root 19 20 janv. 16:16 /usr/lib64/libstdc++.so.6 -> libstdc++.so.6.0.16

-rwxr-xr-x 1 root root 994256 27 oct. 13:43 /usr/lib64/libstdc++.so.6.0.16

-> node2 and 3 are installed with same distribution :

root@vmdebian1:~# cat /etc/debian_version

6.0.4

root@vmdebian1:~# uname -a

Linux vmdebian1 2.6.32-5-686 #1 SMP Mon Jan 16 16:04:25 UTC 2012 i686 GNU/Linux

root@vmdebian1:~# dpkg -l | grep -i libstd

ii libstdc++6 4.4.5-8 The GNU Standard C++ Library v3

root@vmdebian1:~# dpkg -L libstdc++6

/.

/usr

/usr/lib

/usr/lib/libstdc++.so.6.0.13

/usr/share

/usr/share/doc

/usr/lib/libstdc++.so.6

/usr/share/doc/libstdc++6

root@vmdebian1:~# ls -al /usr/lib/libstdc++*

lrwxrwxrwx 1 root root 19 9 janv. 10:26 /usr/lib/libstdc++.so.6 -> libstdc++.so.6.0.13

-rw-r--r-- 1 root root 975012 14 nov. 2010 /usr/lib/libstdc++.so.6.0.13

Thanks,

Thks for your support !
BR

Alex

Laurent

gdb_galera.txt

Laurent MINOST

unread,

Mar 21, 2012, 4:03:37 AM3/21/12

to codersh...@googlegroups.com

Hi,

Anyone who is having some tips or advise about this problem please ? IST here is still not working properly, no 4568 port listening ?

Thanks.
BR,

Laurent

Alexey Yurchenko

unread,

Mar 21, 2012, 8:36:46 PM3/21/12

to codersh...@googlegroups.com

Hi Laurent,

Sorry for keeping it so long, unfortunately we have higher priorities right now. I must say that I managed to reproduce this situation once (also with a joiner in a VM), but had to postpone forensics and eventually had to discard it. Given that it all happens to VM'ed joiner, could you try to reverse node1 and node2 roles and get node1 to join the working cluster.

Another option is to run node2 and node3 in "sandboxes" instead of VMs (different ports, sockets, pids, data dirs).

I'm quite sure it has something to do with the cluster setup (probably some race with VM opening a listen port or something like that) rather than Galera internals.

Regards,
Alex

Laurent MINOST

unread,

Mar 27, 2012, 9:42:24 AM3/27/12

to codersh...@googlegroups.com

Hi Alexei,

Thanks for your reply and time for testing.
Sorry for the late response from my side but I was also trying to reinstall on new nodes to get a new and clear situation.
So I finally reinstalled mysqld + libgalera on 2 physical servers (cygnus & laurane) for the first nodes and a Virtual Machine under VirtualBox for the last node (vmfedora1). I was forced to use a virtualmachine rather than multiple mysqld on a same machine because of the fact that I'm also testing Cluster Control Monitor for Galera at the same time, and this one needs separate machine otherwise it is almost impossible to have 2 nodes (at least for the cmon agent part) on a same physical machine ...

By the way, after reinstalling all of this, I had the same problem with IST between node1 and 2 so I don't think there is something related with virtual machines ... maybe it's my configuration which is not good on my side, by the way I can do tests if you want and if you have (limited I know and understand ;) ) time, don't hesitate !

Thanks a lot. BR,

Laurent

Henrik Ingo

unread,

Mar 29, 2012, 3:38:34 AM3/29/12

to Laurent MINOST, codersh...@googlegroups.com

FWIW, I would install ClusterControl into the VM. Just a tip.

henrik

> --
> You received this message because you are subscribed to the Google Groups
> "codership" group.
> To view this discussion on the web visit
> https://groups.google.com/d/msg/codership-team/-/eY9Nypmc1X0J.
>
> To post to this group, send email to codersh...@googlegroups.com.
> To unsubscribe from this group, send email to
> codership-tea...@googlegroups.com.
> For more options, visit this group at
> http://groups.google.com/group/codership-team?hl=en.

--
henri...@avoinelama.fi
+358-40-8211286 skype: henrik.ingo irc: hingo
www.openlife.cc

My LinkedIn profile: http://www.linkedin.com/profile/view?id=9522559

Allan

unread,

Mar 29, 2012, 8:29:15 AM3/29/12

to codersh...@googlegroups.com

Hello Laurent,

I also now have 3 nodes that are working on a Solaris 11 platform. The next step for me is to write a health check for my internal load balancer that will not only provide a status for the load balancer, but also take appropriate action to restart a node, notify Administrator, etc..

Your post below got me interested.

"Ok thks a lot for clearing all these steps :) I was very interested in the answer to this question because I'm using an HAproxy load balancer in front of Galera cluster to dispatch requests to 3 nodes, it is working through a check on an xinetd service running on each node which ask node status through a bash script connecting to the mysql service and checking the 'wsrep_local_state' service to see the node state, for the moment I have only authorized this script, and consequently HAproxy, to mark node as UP if it returns state 4 (Synced (6)), all others states marked the node as DOWN which makes the whole cluster with 1 node only left when full resync of a node is needed because I have then one node in state 2 (Donor) and the other one in state 1 (Waiting for SST). With IST working, it would be very very more efficient I think :)"

Would it be posible to take a look at your script? I would like some baseline from which to start the development of my Solaris - Galera health check. Anything you have, bash script, etc. would be nice.

I appreciate your comments.

-Allan

------------------

Laurent MINOST

unread,

Mar 29, 2012, 9:06:05 AM3/29/12

to codersh...@googlegroups.com, Laurent MINOST, henri...@avoinelama.fi

Hi Henrik,

Sorry, I do not really understand your answer ?

Currently, ClusterControl GUI and MySQL server are installed on a separate Virtual Machine, this is the fourth machine and on every Galera nodes I have the Cluster Control Monitor Agent which is installed and used by the "main" process on the fourth machine to monitor and grab node's status.

What I was meaning is that Cluster Control seems to require an agent installed for each galera nodes so I need to install each Galera nodes on separate machine.

BR,

Laurent

> To post to this group, send email to codership-team@googlegroups.com.

> To unsubscribe from this group, send email to

> codership-team+unsubscribe@googlegroups.com.

> For more options, visit this group at
> http://groups.google.com/group/codership-team?hl=en.

Laurent MINOST

unread,

Mar 29, 2012, 9:32:08 AM3/29/12

to codersh...@googlegroups.com

Le jeudi 29 mars 2012 14:29:15 UTC+2, Allan a écrit :

Hello Laurent,

Hi Allan ! :)

I also now have 3 nodes that are working on a Solaris 11 platform. The next step for me is to write a health check for my internal load balancer that will not only provide a status for the load balancer, but also take appropriate action to restart a node, notify Administrator, etc..

I would also be really interested in your experience about setting up Galera especially about the IST part which seems to be the major problem I'm currently facing since it does not seem to work properly on my side each time an IST is started.
More, If you succead later to build a scriptable solution for monitoring and with limited control on Galera nodes remotely, I would also be interested to have a look ...

Your post below got me interested.

"Ok thks a lot for clearing all these steps :) I was very interested in the answer to this question because I'm using an HAproxy load balancer in front of Galera cluster to dispatch requests to 3 nodes, it is working through a check on an xinetd service running on each node which ask node status through a bash script connecting to the mysql service and checking the 'wsrep_local_state' service to see the node state, for the moment I have only authorized this script, and consequently HAproxy, to mark node as UP if it returns state 4 (Synced (6)), all others states marked the node as DOWN which makes the whole cluster with 1 node only left when full resync of a node is needed because I have then one node in state 2 (Donor) and the other one in state 1 (Waiting for SST). With IST working, it would be very very more efficient I think :)"

Would it be posible to take a look at your script? I would like some baseline from which to start the development of my Solaris - Galera health check. Anything you have, bash script, etc. would be nice.

Sure, currently I'm using some scripts modified and inspired from Alex Williams page located at http://www.alexwilliams.ca/blog/2009/08/10/using-haproxy-for-mysql-failover-and-redundancy/

I have attached a tar.gz file with 4 main files which are needed :

- 1_line_to_add_to_etc_services
These are the lines you need to add to /etc/services to make the following xinetd script works.

- 2_mysql_haproxy_check_galera.sh
This is the main script which will connect to the local Galera node and check for the current Galera status, i could be improved by checking the status number rather than the status description. If status is OK (I have only add Synced status as an OK status for HAproxy) then it will returns back an HTTP code 200; otherwise 503.

- 3_mysql_check_galera
This is the xinetd service script that should be added within xinetd.d directory. Xinetd will then need to be restarted.

- 4_haproxy.cfg
This is a sample HAproxy.cfg file to test the scripts below with.

Don't hesitate if you have any questions and feel free to improve these scripts if needed, I would be glad to see your improvements on these forums so it can benefits to the Galera community.

Thks.

BR,

I appreciate your comments.
-Allan

Laurent

galera_healthcheck_scripts.tar.gz

Allan

unread,

Mar 29, 2012, 10:19:43 AM3/29/12

to codersh...@googlegroups.com

Laurent,

Thank you for your speedy response to my request for sample health check scripts. I will review them for sure.

About your problem with IST, on Solaris I had major problems and cound not get any sync to occur until I applied mysql_upgrade to the database on each node.

I saw some note in the logs that said some tables wer missing, and I eventually figured out that the mysql_upgrade program had to be run.

After I did that, I started seeing IST messages in my logs indicating that some more chatter was taking place between the nodes. My real test was to have 3 nodes running, then offline one of them. I then did some inserts to a test table on the live nodes, brought the offflined node back online and then it got synced properly and my data was there.

My logs look like the following.

NODE 1 - THE LIVE NODE WHICH REMAINED IN OPERATION WHILE NODE 3 WAS SHUTDOWN.

----------------------------------------------------------------------------------------------------------------------------------------

120328 23:08:44 [Note] WSREP: Node 3 (db3-zone) requested state transfer from '*any*'. Selected 0 (db1-zone)(SYNCED) as donor.
120328 23:08:44 [Note] WSREP: Shifting SYNCED -> DONOR/DESYNCED (TO: 10)
120328 23:08:44 [Note] WSREP: IST request: f8587306-72c4-11e1-0800-252d66c88835:9-10|tcp://172.16.3.40:4568
usage: hostname [system_name]
usage: hostname [system_name]
usage: hostname [system_name]
/usr/local/mysql-5.5.20-solaris11-i386//bin/wsrep_sst_mysqldump: line 55: ip: not found
Bypassing state dump.
120328 23:08:45 [Note] WSREP: async IST sender starting to serve tcp://172.16.3.40:4568 sending 10-10
120328 23:08:45 [Note] WSREP: async IST sender served
120328 23:08:45 [Note] WSREP: 0 (db1-zone): State transfer to 3 (db3-zone) complete.
120328 23:08:45 [Note] WSREP: Shifting DONOR/DESYNCED -> JOINED (TO: 10)
120328 23:08:45 [Note] WSREP: 3 (db3-zone): State transfer from 0 (db1-zone) complete.
120328 23:08:45 [Note] WSREP: Member 0 (db1-zone) synced with group.
120328 23:08:45 [Note] WSREP: Shifting JOINED -> SYNCED (TO: 10)
120328 23:08:45 [Note] WSREP: Synchronized with group, ready for connections
120328 23:08:45 [Note] WSREP: Member 3 (db3-zone) synced with group.

NODE 3 AFTER IT WAS BROUGHT BACK ONLINE.

-----------------------------------------------------------------------

120328 23:08:42 [Note] WSREP: Quorum results:

version = 2,
component = PRIMARY,

conf_id    = 8,
members    = 3/4 (joined/total),
act_id     = 10,

last_appl. = -1,
protocols = 0/3/1 (gcs/repl/appl),

group UUID = f8587306-72c4-11e1-0800-252d66c88835
120328 23:08:42 [Note] WSREP: Flow-control interval: [16, 32]
120328 23:08:42 [Note] WSREP: Shifting OPEN -> PRIMARY (TO: 10)
120328 23:08:42 [Note] WSREP: State transfer required:
Group state: f8587306-72c4-11e1-0800-252d66c88835:10
Local state: f8587306-72c4-11e1-0800-252d66c88835:9
120328 23:08:42 [Note] WSREP: New cluster view: global state: f8587306-72c4-11e1-0800-252d66c88835:10, view# 9: Primary, number of nodes: 4, my index: 3, protocol version 1
120328 23:08:42 [Warning] WSREP: Gap in state sequence. Need state transfer.
120328 23:08:44 [Note] WSREP: Prepared SST request: mysqldump|172.16.3.40:3306
/usr/local/mysql-5.5.20-solaris11-i386//bin/wsrep_notify[44]: local: not found [No such file or directory]
120328 23:08:44 [Note] WSREP: Assign initial position for certification: 10, protocol version: 2
120328 23:08:44 [Note] WSREP: Prepared IST receiver, listening at: tcp://172.16.3.40:4568
120328 23:08:44 [Note] WSREP: Node 3 (db3-zone) requested state transfer from '*any*'. Selected 0 (db1-zone)(SYNCED) as donor.
120328 23:08:44 [Note] WSREP: Shifting PRIMARY -> JOINER (TO: 10)
120328 23:08:44 [Note] WSREP: Requesting state transfer: success, donor: 0
120328 23:08:45 [Note] WSREP: wsrep_start_position var submitted: 'f8587306-72c4-11e1-0800-252d66c88835:9'
120328 23:08:45 [Note] WSREP: Received SST: f8587306-72c4-11e1-0800-252d66c88835:9
120328 23:08:45 [Note] WSREP: SST received: f8587306-72c4-11e1-0800-252d66c88835:9
120328 23:08:45 [Note] WSREP: Receiving IST: 1 writesets, seqnos 9-10
120328 23:08:45 [Note] WSREP: IST received: f8587306-72c4-11e1-0800-252d66c88835:10
120328 23:08:45 [Note] WSREP: 0 (db1-zone): State transfer to 3 (db3-zone) complete.
120328 23:08:45 [Note] WSREP: 3 (db3-zone): State transfer from 0 (db1-zone) complete.
120328 23:08:45 [Note] WSREP: Shifting JOINER -> JOINED (TO: 10)
120328 23:08:45 [Note] WSREP: Member 0 (db1-zone) synced with group.
120328 23:08:45 [Note] WSREP: Member 3 (db3-zone) synced with group.
120328 23:08:45 [Note] WSREP: Shifting JOINED -> SYNCED (TO: 10)
120328 23:08:45 [Note] WSREP: Synchronized with group, ready for connections

-----------------------------------

HOPE THIS HELPS.

If there is a problem there in the logs, let me know.

One final note. For virtualization I am using Solaris 11 zones (very lightweight). Each node is like its own server complete network, processes, and everything else. I like the tiny footprint.

Again, than you for the scripts you sent. My initial thought is that I am not going to use the traditional

HAProxy method, instead my load balancer is Solaris ILB (Internal Load Balancer). But I may have to use HAProxy, I am just not sure as I am not familiar with it.

Thanks,

Allan

unread,

Mar 29, 2012, 11:22:55 AM3/29/12

to codersh...@googlegroups.com

Alexey,

I was discussing with Laurent what I did to get IST flowing on Solaris, but after sending my response to him I noticed that the log snippit had an actual error in it which came from the following.

/usr/local/mysql-5.5.20-solaris11-i386//bin/wsrep_sst_mysqldump: line 55: ip: not found

Apparently the command on line 55 is not a valid Solaris command. (i.e. ip route get listed below).

    # Now if ip program is not found in the path, we can't return 0 since
    # it would block any address. Thankfully grep should fail in this case
    ip route get "$1" | grep local >/dev/null && return 0

return 1

The IST synchronization did process the transactions and the actual databases were synchronized despite the wsrep_sst_mysqldump not running.

SEE LOGS BELOW.

Alex, is this going to be ok? Normally netstat is used to obtain routing info on Solaris. In my case I know all transactions are routed through a virtual switch that acts like a router and sends packets directly to the node that gets addressed.

What should I do?

Thank you in advance,

Allan

------------------

Alexey, my log snipits are below here..

120328 23:08:42 [Note] WSREP: Quorum results:

version = 2,
component = PRIMARY,

conf_id = 8,

members = 3/4 (joined/total),
act_id = 10,

last_appl. = -1,
protocols = 0/3/1 (gcs/repl/appl),

group UUID = f8587306-72c4-11e1-0800-252d66c88835
120328 23:08:42 [Note] WSREP: Flow-control interval: [16, 32]
120328 23:08:42 [Note] WSREP: Shifting OPEN -> PRIMARY (TO: 10)
120328 23:08:42 [Note] WSREP: State transfer required:
Group state: f8587306-72c4-11e1-0800-252d66c88835:10
Local state: f8587306-72c4-11e1-0800-252d66c88835:9
120328 23:08:42 [Note] WSREP: New cluster view: global state: f8587306-72c4-11e1-0800-252d66c88835:10, view# 9: Primary, number of nodes: 4, my index: 3, protocol version 1
120328 23:08:42 [Warning] WSREP: Gap in state sequence. Need state transfer.
120328 23:08:44 [Note] WSREP: Prepared SST request: mysqldump|172.16.3.40:3306
/usr/local/mysql-5.5.20-solaris11-i386//bin/wsrep_notify[44]: local: not found [No such file or directory]
120328 23:08:44 [Note] WSREP: Assign initial position for certification: 10, protocol version: 2
120328 23:08:44 [Note] WSREP: Prepared IST receiver, listening at: tcp://172.16.3.40:4568

120328 23:08:44 [Note] WSREP: Node 3 (db3-zone) requested state transfer from '*any*'. Selected 0 (db1-zone)(SYNCED) as donor.

120328 23:08:44 [Note] WSREP: Shifting PRIMARY -> JOINER (TO: 10)
120328 23:08:44 [Note] WSREP: Requesting state transfer: success, donor: 0
120328 23:08:45 [Note] WSREP: wsrep_start_position var submitted: 'f8587306-72c4-11e1-0800-252d66c88835:9'
120328 23:08:45 [Note] WSREP: Received SST: f8587306-72c4-11e1-0800-252d66c88835:9
120328 23:08:45 [Note] WSREP: SST received: f8587306-72c4-11e1-0800-252d66c88835:9
120328 23:08:45 [Note] WSREP: Receiving IST: 1 writesets, seqnos 9-10
120328 23:08:45 [Note] WSREP: IST received: f8587306-72c4-11e1-0800-252d66c88835:10
120328 23:08:45 [Note] WSREP: 0 (db1-zone): State transfer to 3 (db3-zone) complete.
120328 23:08:45 [Note] WSREP: 3 (db3-zone): State transfer from 0 (db1-zone) complete.
120328 23:08:45 [Note] WSREP: Shifting JOINER -> JOINED (TO: 10)
120328 23:08:45 [Note] WSREP: Member 0 (db1-zone) synced with group.
120328 23:08:45 [Note] WSREP: Member 3 (db3-zone) synced with group.
120328 23:08:45 [Note] WSREP: Shifting JOINED -> SYNCED (TO: 10)
120328 23:08:45 [Note] WSREP: Synchronized with group, ready for connections

-----------------------------------

HOPE THIS HELPS.

If there is a problem there in the logs, let me know.

Sincerely,

Allan

Alex Yurchenko

unread,

Mar 29, 2012, 1:49:47 PM3/29/12

to codersh...@googlegroups.com

On 2012-03-29 18:22, Allan wrote:
> Alexey,
>
> I was discussing with Laurent what I did to get IST flowing on
> Solaris, but
> after sending my response to him I noticed that the log snippit had
> an
> actual error in it which came from the following.
>
> /usr/local/mysql-5.5.20-solaris11-i386//bin/wsrep_sst_mysqldump: line
> 55:
> ip: not found
>
> Apparently the command on line 55 is not a valid Solaris command.
> (i.e. ip
> route get listed below).
>
> # Now if ip program is not found in the path, we can't return 0
> since
> # it would block any address. Thankfully grep should fail in this
> case
> ip route get "$1" | grep local >/dev/null && return 0
> return 1

Well, this is just a protection against addresses like 127.0.0.1,
localhost and the like which would make donor to load mysqldump onto
itself. This protection does not work in your case, but as you can see,
it returns 1 and the rest of the code does.

> The IST synchronization did process the transactions and the actual
> databases were synchronized despite the wsrep_sst_mysqldump not
> running.

I'm quite sure it was.

> SEE LOGS BELOW.
>
> Alex, is this going to be ok? Normally netstat is used to obtain
> routing
> info on Solaris. In my case I know all transactions are routed
> through a
> virtual switch that acts like a router and sends packets directly to
> the
> node that gets addressed.
>
> What should I do?

Allan, I'd be more concerned about

> 120328 23:08:44 [Note] WSREP: Prepared SST request:

> mysqldump|*172.16.3.40:3306* <http://172.16.3.40:3306/>

> 120328 23:08:44 [Note] WSREP: Prepared IST receiver, listening at:

> tcp://*172.16.3.40:4568* <http://172.16.3.40:4568/>

what a hell is this string after tcp:// ??? Is this a new way to write
IP address or hostname in Solaris?

Anyways, it seems to pass (to my bewilderment), so it works.

> f8587306-72c4-11e1-0800-252d66c88835:9-10|tcp://*172.16.3.40:4568*<http://172.16.3.40:4568/>

> usage: hostname [system_name]
> usage: hostname [system_name]
> usage: hostname [system_name]
> /usr/local/mysql-5.5.20-solaris11-i386//bin/wsrep_sst_mysqldump: line
> 55:
> ip: not found
> Bypassing state dump.
> 120328 23:08:45 [Note] WSREP: async IST sender starting to serve

> tcp://*
> 172.16.3.40:4568* <http://172.16.3.40:4568/> sending 10-10

> 120328 23:08:44 [Note] WSREP: Prepared SST request: mysqldump|*
> 172.16.3.40:3306* <http://172.16.3.40:3306/>

> /usr/local/mysql-5.5.20-solaris11-i386//bin/wsrep_notify[44]: local:
> not
> found [No such file or directory]
> 120328 23:08:44 [Note] WSREP: Assign initial position for
> certification:
> 10, protocol version: 2
> 120328 23:08:44 [Note] WSREP: Prepared IST receiver, listening at:

> tcp://*
> 172.16.3.40:4568* <http://172.16.3.40:4568/>

Allan

unread,

Mar 29, 2012, 2:13:16 PM3/29/12

to codersh...@googlegroups.com

Alexey,

yes the transaction did pass all the data just fine, does that mean the rest of the wsrep_sst_mysqldump ran ok?

Or did this transaction just come from the buffer?

In other words, if the dump above did not work and I get a node that falls offline and stays offline for extended period, and I try to bring it back up, then since so mysql dump is executed will it miss some data?

as far as hostname is concered, I am issue the startup on primary node with --skip-name-resolve because mysql was taking a long time to resolve names on these database nodes when connecting to each other. In my case these nodes are on a private etherstub network and do not have access to DNS. However, I do have entries in hosts file. In the wsrep.cnf files I use ip addresses only.

Thank you

Allan

Alexey Yurchenko

unread,

Mar 29, 2012, 2:18:18 PM3/29/12

to codersh...@googlegroups.com

SST script worked fine.

Henrik Ingo

unread,

Mar 29, 2012, 4:35:57 PM3/29/12

to Laurent MINOST, codersh...@googlegroups.com

Ah sorry, I understood you differently then. I thought you had 3
physical servers.

henrik

>> > To post to this group, send email to codersh...@googlegroups.com.

>> > To unsubscribe from this group, send email to

>> > codership-tea...@googlegroups.com.

Laurent MINOST

unread,

Apr 19, 2012, 9:41:27 AM4/19/12

to codersh...@googlegroups.com

Hi,

This problem is still existing ( at least from my side ), so I would like to know if someone else is facing the same behaviour please ?

After a simple and normal stop of a node, IST seems to be starting but seems to then stalled sometimes and so two nodes implicated in the recovery (Donor and Joiner) are then unavailable and stay stalled in their status making almost two nodes unavailable for the whole cluster if no human action is done !

If it could help to found the culprit/root cause of the problem, below are the logs for the two nodes impacted, I want to precise that these two nodes are physical servers :

- node1 : named cygnus is the node which was stopped and that is now coming back as Joiner and should received properly IST

- node2 : named laurane is the node which was choosed as Donor.

node1's shutdown was initiated at 14:46:47 as the log shows.

node1's log :

120419 14:30:02 [Note] WSREP: MDL conflict -> BF abort

request: (2 seqno 5154113 mode 1 Qstate 1 cmd 0 8 TRUNCATE TABLE poller_time)

granted: (583918 seqno 5154114 mode 0 Qstate 1 cmd 3 5 INSERT INTO poller_time (poller_id, pid, start_time, end_time) VALUES (0, 19630, NOW()

120419 14:46:47 [Note] /opt/mysql-galera/bin/mysqld: Normal shutdown

120419 14:46:47 [Note] WSREP: Stop replication

120419 14:46:47 [Note] WSREP: Closing send monitor...

120419 14:46:47 [Note] WSREP: Closed send monitor.

120419 14:46:47 [Note] WSREP: gcomm: terminating thread

120419 14:46:47 [Note] WSREP: gcomm: joining thread

120419 14:46:47 [Note] WSREP: gcomm: closing backend

120419 14:46:47 [Note] WSREP: evs::proto(2d6df99a-886e-11e1-0800-15e7fc053cbb, LEAVING, view_id(REG,2d6df99a-886e-11e1-0800-15e7fc053cbb,75)) uuid c61c9f05-8914-11e1-0800-60eb1083cb96 missing from install message, assuming partitioned

120419 14:46:47 [Note] WSREP: evs::proto(2d6df99a-886e-11e1-0800-15e7fc053cbb, LEAVING, view_id(REG,2d6df99a-886e-11e1-0800-15e7fc053cbb,75)) uuid d2e4fb87-8870-11e1-0800-38327ad7aba0 missing from install message, assuming partitioned

120419 14:46:47 [Note] WSREP: GMCast::handle_stable_view: view(view_id(NON_PRIM,2d6df99a-886e-11e1-0800-15e7fc053cbb,75) memb {

2d6df99a-886e-11e1-0800-15e7fc053cbb,

} joined {

} left {

} partitioned {

c61c9f05-8914-11e1-0800-60eb1083cb96,

d2e4fb87-8870-11e1-0800-38327ad7aba0,

})

120419 14:46:47 [Note] WSREP: New COMPONENT: primary = no, my_idx = 0, memb_num = 1

120419 14:46:47 [Note] WSREP: GMCast::handle_stable_view: view((empty))

120419 14:46:47 [Note] WSREP: gcomm: closed

120419 14:46:47 [Note] WSREP: Flow-control interval: [8, 16]

120419 14:46:47 [Note] WSREP: Received NON-PRIMARY.

120419 14:46:47 [Note] WSREP: Shifting SYNCED -> OPEN (TO: 5160086)

120419 14:46:47 [Note] WSREP: Received self-leave message.

120419 14:46:47 [Note] WSREP: Flow-control interval: [0, 0]

120419 14:46:47 [Note] WSREP: Received SELF-LEAVE. Closing connection.

120419 14:46:47 [Note] WSREP: Shifting OPEN -> CLOSED (TO: 5160086)

120419 14:46:47 [Note] WSREP: RECV thread exiting 0: Success

120419 14:46:47 [Note] WSREP: recv_thread() joined.

120419 14:46:47 [Note] WSREP: Closing slave action queue.

120419 14:46:47 [Note] WSREP: New cluster view: global state: 61408137-81c8-11e1-0800-5dbd477990e1:5160086, view# -1: non-Primary, number of nodes: 1, my index: 0, protocol version 1

120419 14:46:48 [Note] WSREP: New cluster view: global state: 61408137-81c8-11e1-0800-5dbd477990e1:5160086, view# -1: non-Primary, number of nodes: 0, my index: -1, protocol version 1

120419 14:46:48 [Note] WSREP: applier thread exiting (code:0)

120419 14:46:49 [Note] WSREP: SST kill local trx: 588248

120419 14:46:49 [Note] WSREP: rollbacker thread exiting

120419 14:46:49 [Note] Event Scheduler: Purging the queue. 0 events

120419 14:46:49 [Note] WSREP: dtor state: CLOSED

120419 14:46:49 [Note] WSREP: mon: entered 3 oooe fraction 0 oool fraction 0

120419 14:46:49 [Note] WSREP: mon: entered 930739 oooe fraction 0 oool fraction 0.000114962

120419 14:46:49 [Note] WSREP: cert index usage at exit 804

120419 14:46:49 [Note] WSREP: cert trx map usage at exit 309

120419 14:46:49 [Note] WSREP: deps set usage at exit 0

120419 14:46:49 [Note] WSREP: avg deps dist 330.854

120419 14:46:49 [Note] WSREP: wsdb trx map usage 0 conn query map usage 0

120419 14:46:49 [Note] WSREP: Shifting CLOSED -> DESTROYED (TO: 5160086)

120419 14:46:49 [Note] WSREP: Flushing memory map to disk...

120419 14:46:50 [Note] unregister_replicator OK

120419 14:46:50 InnoDB: Starting shutdown...

120419 14:46:53 InnoDB: Shutdown completed; log sequence number 12275710641

120419 14:46:53 [Note] /opt/mysql-galera/bin/mysqld: Shutdown complete

120419 14:46:54 mysqld_safe mysqld from pid file /opt/mysql-galera/data/mysqld.pid ended

120419 14:47:38 mysqld_safe Starting mysqld daemon with databases from /opt/mysql-galera/data

120419 14:47:38 [Note] WSREP: wsrep_load(): loading provider library '/opt/mysql-galera/lib/plugin/libgalera_smm.so'

120419 14:47:38 [Note] WSREP: wsrep_load(): Galera 2.0(rXXXX) by Codership Oy <in...@codership.com> loaded succesfully.

120419 14:47:38 [Note] WSREP: Reusing existing '/opt/mysql-galera/data//galera.cache'.

120419 14:47:38 [Note] WSREP: Passing config to GCS: gcache.dir = /opt/mysql-galera/data/; gcache.keep_pages_size = 0; gcache.mem_size = 0; gcache.name = /opt/mysql-galera/data//galera.cache; gcache.page_size = 128M; gcache.size = 128M; gcs.fc_debug = 0; gcs.fc_factor = 0.5; 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; replicator.causal_read_timeout = PT30S; replicator.commit_order = 3

120419 14:47:38 [Note] WSREP: wsrep_sst_grab()

120419 14:47:38 [Note] WSREP: Start replication

120419 14:47:38 [Note] WSREP: Found saved state: 61408137-81c8-11e1-0800-5dbd477990e1:5160086

120419 14:47:38 [Note] WSREP: Assign initial position for certification: 5160086, protocol version: -1

120419 14:47:38 [Note] WSREP: Setting initial position to 61408137-81c8-11e1-0800-5dbd477990e1:5160086

120419 14:47:38 [Note] WSREP: protonet asio version 0

120419 14:47:38 [Note] WSREP: backend: asio

120419 14:47:38 [Note] WSREP: GMCast version 0

120419 14:47:38 [Note] WSREP: (d86affd3-8a1d-11e1-0800-5ea3f3e2042e, 'tcp://0.0.0.0:4567') listening at tcp://0.0.0.0:4567

120419 14:47:38 [Note] WSREP: (d86affd3-8a1d-11e1-0800-5ea3f3e2042e, 'tcp://0.0.0.0:4567') multicast: , ttl: 1

120419 14:47:38 [Note] WSREP: EVS version 0

120419 14:47:38 [Note] WSREP: PC version 0

120419 14:47:38 [Note] WSREP: gcomm: connecting to group 'my_wsrep_cluster', peer '192.168.0.5:4567'

120419 14:47:39 [Note] WSREP: GMCast::handle_stable_view: view(view_id(PRIM,c61c9f05-8914-11e1-0800-60eb1083cb96,77) memb {

c61c9f05-8914-11e1-0800-60eb1083cb96,

d2e4fb87-8870-11e1-0800-38327ad7aba0,

d86affd3-8a1d-11e1-0800-5ea3f3e2042e,

} joined {

} left {

} partitioned {

})

120419 14:47:39 [Note] WSREP: declaring c61c9f05-8914-11e1-0800-60eb1083cb96 stable

120419 14:47:39 [Note] WSREP: declaring d2e4fb87-8870-11e1-0800-38327ad7aba0 stable

120419 14:47:39 [Note] WSREP: gcomm: connected

120419 14:47:39 [Note] WSREP: Changing maximum packet size to 64500, resulting msg size: 32636

120419 14:47:39 [Note] WSREP: Shifting CLOSED -> OPEN (TO: 0)

120419 14:47:39 [Note] WSREP: Opened channel 'my_wsrep_cluster'

120419 14:47:39 [Note] WSREP: New COMPONENT: primary = yes, my_idx = 2, memb_num = 3

120419 14:47:39 [Note] WSREP: STATE EXCHANGE: Waiting for state UUID.

120419 14:47:39 [Note] WSREP: Waiting for SST to complete.

120419 14:47:39 [Note] WSREP: STATE EXCHANGE: sent state msg: d911f3b9-8a1d-11e1-0800-94d10f7c556a

120419 14:47:39 [Note] WSREP: STATE EXCHANGE: got state msg: d911f3b9-8a1d-11e1-0800-94d10f7c556a from 0 (laurane.lolomin.net)

120419 14:47:39 [Note] WSREP: STATE EXCHANGE: got state msg: d911f3b9-8a1d-11e1-0800-94d10f7c556a from 1 (vmfedora1)

120419 14:47:39 [Note] WSREP: STATE EXCHANGE: got state msg: d911f3b9-8a1d-11e1-0800-94d10f7c556a from 2 (cygnus.lolomin.net)

120419 14:47:39 [Note] WSREP: Quorum results:

version = 2,

component = PRIMARY,

conf_id = 63,

members = 2/3 (joined/total),

act_id = 5160427,

last_appl. = -1,

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

group UUID = 61408137-81c8-11e1-0800-5dbd477990e1

120419 14:47:39 [Note] WSREP: Flow-control interval: [14, 28]

120419 14:47:39 [Note] WSREP: Shifting OPEN -> PRIMARY (TO: 5160427)

120419 14:47:39 [Note] WSREP: State transfer required:

Group state: 61408137-81c8-11e1-0800-5dbd477990e1:5160427

Local state: 61408137-81c8-11e1-0800-5dbd477990e1:5160086

120419 14:47:39 [Note] WSREP: New cluster view: global state: 61408137-81c8-11e1-0800-5dbd477990e1:5160427, view# 64: Primary, number of nodes: 3, my index: 2, protocol version 1

120419 14:47:39 [Warning] WSREP: Gap in state sequence. Need state transfer.

120419 14:47:41 [Note] WSREP: Running: 'wsrep_sst_rsync 'joiner' '192.168.0.1' 'sst:5T13wPid' '/opt/mysql-galera/data/' '/etc/my-galera.cnf' '6751' 2>sst.err'

120419 14:47:42 [Note] WSREP: Prepared SST request: rsync|192.168.0.1:4444/rsync_sst

ERROR 2003 (HY000): Can't connect to MySQL server on 'cygnus' (111)

120419 14:47:42 [Note] WSREP: Assign initial position for certification: 5160427, protocol version: 2

120419 14:47:42 [Note] WSREP: Prepared IST receiver, listening at: tcp://192.168.0.1:4568

120419 14:47:42 [Note] WSREP: Node 2 (cygnus.lolomin.net) requested state transfer from '*any*'. Selected 0 (laurane.lolomin.net)(SYNCED) as donor.

120419 14:47:42 [Note] WSREP: Shifting PRIMARY -> JOINER (TO: 5160434)

120419 14:47:42 [Note] WSREP: Requesting state transfer: success, donor: 0

120419 14:47:44 [Note] WSREP: SST complete, seqno: 5160086

120419 14:47:44 InnoDB: The InnoDB memory heap is disabled

120419 14:47:44 InnoDB: Mutexes and rw_locks use GCC atomic builtins

120419 14:47:44 InnoDB: Compressed tables use zlib 1.2.3

120419 14:47:44 InnoDB: Using Linux native AIO

120419 14:47:44 InnoDB: Initializing buffer pool, size = 512.0M

120419 14:47:44 InnoDB: Completed initialization of buffer pool

120419 14:47:44 InnoDB: highest supported file format is Barracuda.

120419 14:47:45 InnoDB: Waiting for the background threads to start

120419 14:47:46 InnoDB: 1.1.8 started; log sequence number 12275710641

120419 14:47:47 [Note] Event Scheduler: Loaded 0 events

120419 14:47:47 [Note] WSREP: Signalling provider to continue.

120419 14:47:47 [Note] WSREP: Received SST: 61408137-81c8-11e1-0800-5dbd477990e1:5160086

120419 14:47:47 [Note] /opt/mysql-galera/bin/mysqld: ready for connections.

Version: '5.5.20-log' socket: '/opt/mysql-galera/data/mysql.sock' port: 3306 Source distribution, wsrep_23.4.r3713

120419 14:47:47 [Note] WSREP: SST received: 61408137-81c8-11e1-0800-5dbd477990e1:5160086

120419 14:47:47 [Note] WSREP: Receiving IST: 341 writesets, seqnos 5160086-5160427

node2's log :

120419 10:50:02 [Note] WSREP: MDL conflict -> BF abort

request: (1 seqno 5080636 mode 1 Qstate 1 cmd 0 8 TRUNCATE TABLE poller_time)

granted: (346474 seqno 5080637 mode 0 Qstate 1 cmd 3 5 INSERT INTO poller_time (poller_id, pid, start_time, end_time) VALUES (0, 14193, NOW()

120419 14:46:47 [Note] WSREP: GMCast::handle_stable_view: view(view_id(PRIM,c61c9f05-8914-11e1-0800-60eb1083cb96,76) memb {

c61c9f05-8914-11e1-0800-60eb1083cb96,

d2e4fb87-8870-11e1-0800-38327ad7aba0,

} joined {

} left {

} partitioned {

2d6df99a-886e-11e1-0800-15e7fc053cbb,

})

120419 14:46:47 [Note] WSREP: New COMPONENT: primary = yes, my_idx = 0, memb_num = 2

120419 14:46:47 [Note] WSREP: forgetting 2d6df99a-886e-11e1-0800-15e7fc053cbb (tcp://192.168.0.1:4567)

120419 14:46:47 [Note] WSREP: declaring d2e4fb87-8870-11e1-0800-38327ad7aba0 stable

120419 14:46:47 [Note] WSREP: STATE_EXCHANGE: sent state UUID: ba05ef61-8a1d-11e1-0800-058e29c0df9f

120419 14:46:47 [Note] WSREP: STATE EXCHANGE: sent state msg: ba05ef61-8a1d-11e1-0800-058e29c0df9f

120419 14:46:47 [Note] WSREP: STATE EXCHANGE: got state msg: ba05ef61-8a1d-11e1-0800-058e29c0df9f from 0 (laurane.lolomin.net)

120419 14:46:47 [Note] WSREP: STATE EXCHANGE: got state msg: ba05ef61-8a1d-11e1-0800-058e29c0df9f from 1 (vmfedora1)

120419 14:46:47 [Note] WSREP: Quorum results:

version = 2,

component = PRIMARY,

conf_id = 62,

members = 2/2 (joined/total),

act_id = 5160086,

last_appl. = 5159779,

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

group UUID = 61408137-81c8-11e1-0800-5dbd477990e1

120419 14:46:47 [Note] WSREP: Flow-control interval: [12, 23]

120419 14:46:47 [Note] WSREP: New cluster view: global state: 61408137-81c8-11e1-0800-5dbd477990e1:5160086, view# 63: Primary, number of nodes: 2, my index: 0, protocol version 1

120419 14:46:48 [Note] WSREP: Assign initial position for certification: 5160086, protocol version: 2

120419 14:46:52 [Note] WSREP: cleaning up 2d6df99a-886e-11e1-0800-15e7fc053cbb (tcp://192.168.0.1:4567)

120419 14:47:39 [Note] WSREP: GMCast::handle_stable_view: view(view_id(PRIM,c61c9f05-8914-11e1-0800-60eb1083cb96,77) memb {

c61c9f05-8914-11e1-0800-60eb1083cb96,

d2e4fb87-8870-11e1-0800-38327ad7aba0,

d86affd3-8a1d-11e1-0800-5ea3f3e2042e,

} joined {

} left {

} partitioned {

})

120419 14:47:39 [Note] WSREP: New COMPONENT: primary = yes, my_idx = 0, memb_num = 3

120419 14:47:39 [Note] WSREP: declaring d2e4fb87-8870-11e1-0800-38327ad7aba0 stable

120419 14:47:39 [Note] WSREP: declaring d86affd3-8a1d-11e1-0800-5ea3f3e2042e stable

120419 14:47:39 [Note] WSREP: STATE_EXCHANGE: sent state UUID: d911f3b9-8a1d-11e1-0800-94d10f7c556a

120419 14:47:39 [Note] WSREP: STATE EXCHANGE: sent state msg: d911f3b9-8a1d-11e1-0800-94d10f7c556a

120419 14:47:39 [Note] WSREP: STATE EXCHANGE: got state msg: d911f3b9-8a1d-11e1-0800-94d10f7c556a from 0 (laurane.lolomin.net)

120419 14:47:39 [Note] WSREP: STATE EXCHANGE: got state msg: d911f3b9-8a1d-11e1-0800-94d10f7c556a from 1 (vmfedora1)

120419 14:47:39 [Note] WSREP: STATE EXCHANGE: got state msg: d911f3b9-8a1d-11e1-0800-94d10f7c556a from 2 (cygnus.lolomin.net)

120419 14:47:39 [Note] WSREP: Quorum results:

version = 2,

component = PRIMARY,

conf_id = 63,

members = 2/3 (joined/total),

act_id = 5160427,

last_appl. = 5160161,

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

group UUID = 61408137-81c8-11e1-0800-5dbd477990e1

120419 14:47:39 [Note] WSREP: Flow-control interval: [14, 28]

120419 14:47:39 [Note] WSREP: New cluster view: global state: 61408137-81c8-11e1-0800-5dbd477990e1:5160427, view# 64: Primary, number of nodes: 3, my index: 0, protocol version 1

120419 14:47:40 [Note] WSREP: Assign initial position for certification: 5160427, protocol version: 2

120419 14:47:42 [Note] WSREP: Node 2 (cygnus.lolomin.net) requested state transfer from '*any*'. Selected 0 (laurane.lolomin.net)(SYNCED) as donor.

120419 14:47:42 [Note] WSREP: Shifting SYNCED -> DONOR/DESYNCED (TO: 5160434)

120419 14:47:42 [Note] WSREP: IST request: 61408137-81c8-11e1-0800-5dbd477990e1:5160086-5160427|tcp://192.168.0.1:4568

120419 14:47:43 [Note] WSREP: Running: 'wsrep_sst_rsync 'donor' '192.168.0.1:4444/rsync_sst' 'sst:5T13wPid' '/opt/mysql-galera/data/' '/etc/my-galera.cnf' '61408137-81c8-11e1-0800-5dbd477990e1' '5160086' '1''

120419 14:47:43 [Note] WSREP: sst_donor_thread signaled with 0

120419 14:47:43 [Note] WSREP: async IST sender starting to serve tcp://192.168.0.1:4568 sending 5160087-5160427

node1's netstat :

# netstat -lpvnt | grep -iE "(3306|4567|4568)"

tcp 0 0 0.0.0.0:4567 0.0.0.0:* LISTEN 6751/mysqld

tcp 0 0 192.168.0.1:3306 0.0.0.0:* LISTEN 6751/mysqld

node2's netstat :

# netstat -lpvnt | grep -iE "(3306|4567|4568)"

tcp 0 0 192.168.0.5:3306 0.0.0.0:* LISTEN 23714/mysqld

tcp 0 0 0.0.0.0:4567 0.0.0.0:* LISTEN 23714/mysqld

No FW between nodes, simple 100 Mbits LAN.

Then in this state, none of the two nodes will display something in their error_logs ...

Any help/advise/indications would be appreciated. I can also do any test/debug if needed but I don't know if I will be able to let the nodes in this state a lot of time ...

Thanks !
Regards,

Laurent

Alex Yurchenko

unread,

Apr 19, 2012, 12:53:22 PM4/19/12

to codersh...@googlegroups.com

Hi Laurent,

I created a ticket on LP to track this issue:
https://bugs.launchpad.net/galera/+bug/985747