Cannot join cluster - State transfer to 0.0 () failed: -22 (Invalid argument) nfo

2,594 views

Skip to first unread message

Jay J

unread,

Sep 5, 2014, 6:14:06 AM9/5/14

to codersh...@googlegroups.com

Have been at it for a while, with no luck. The donor node is established, second node is connected, the third node just won't budge.

Here's what I have in log:

140905 10:06:40 mysqld_safe Starting mysqld daemon with databases from /var/lib/mysql/
140905 10:06:40 mysqld_safe WSREP: Running position recovery with --log_error='/var/lib/mysql//wsrep_recovery.aiDHra' --pid-file='/var/lib/mysql//MySQL4-recover.pid'
140905 10:06:43 mysqld_safe WSREP: Recovered position 00000000-0000-0000-0000-000000000000:-1
140905 10:06:43 [Note] WSREP: wsrep_start_position var submitted: '00000000-0000-0000-0000-000000000000:-1'
140905 10:06:43 [Note] WSREP: Read nil XID from storage engines, skipping position init
140905 10:06:43 [Note] WSREP: wsrep_load(): loading provider library '/usr/lib/galera/libgalera_smm.so'
140905 10:06:43 [Note] WSREP: wsrep_load(): Galera 25.3.5-wheezy(rXXXX) by Codership Oy <in...@codership.com> loaded successfully.
140905 10:06:43 [Note] WSREP: CRC-32C: using hardware acceleration.
140905 10:06:43 [Note] WSREP: Found saved state: 00000000-0000-0000-0000-000000000000:-1
140905 10:06:43 [Note] WSREP: Passing config to GCS: base_host = 10.0.1.11; base_port = 4567; cert.log_conflicts = no; debug = no; evs.inactive_check_period = PT0.5S; evs.inactive_timeout = PT15S; evs.join_retrans_period = PT1S; evs.max_install_timeouts = 1; 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; pc.npvo = false; pc.version = 0; pc.wait_prim = true; pc.wait_prim_timeout = P30S; pc.weight = 1; protonet.b
140905 10:06:43 [Note] WSREP: Service thread queue flushed.
140905 10:06:43 [Note] WSREP: Assign initial position for certification: -1, protocol version: -1
140905 10:06:43 [Note] WSREP: wsrep_sst_grab()
140905 10:06:43 [Note] WSREP: Start replication
140905 10:06:43 [Note] WSREP: Setting initial position to 00000000-0000-0000-0000-000000000000:-1
140905 10:06:43 [Note] WSREP: protonet asio version 0
140905 10:06:43 [Note] WSREP: Using CRC-32C (optimized) for message checksums.
140905 10:06:43 [Note] WSREP: backend: asio
140905 10:06:43 [Note] WSREP: GMCast version 0
140905 10:06:43 [Note] WSREP: (56501797-34e4-11e4-8e2e-9fa1b255c46f, 'tcp://0.0.0.0:4567') listening at tcp://0.0.0.0:4567
140905 10:06:43 [Note] WSREP: (56501797-34e4-11e4-8e2e-9fa1b255c46f, 'tcp://0.0.0.0:4567') multicast: , ttl: 1
140905 10:06:43 [Note] WSREP: EVS version 0
140905 10:06:43 [Note] WSREP: PC version 0
140905 10:06:43 [Note] WSREP: gcomm: connecting to group 'my_wsrep_cluster', peer '10.0.1.5:,10.0.1.10:,10.0.1.11:'
140905 10:06:43 [Warning] WSREP: (56501797-34e4-11e4-8e2e-9fa1b255c46f, 'tcp://0.0.0.0:4567') address 'tcp://10.0.1.11:4567' points to own listening address, blacklisting
140905 10:06:43 [Note] WSREP: (56501797-34e4-11e4-8e2e-9fa1b255c46f, 'tcp://0.0.0.0:4567') address 'tcp://10.0.1.11:4567' pointing to uuid 56501797-34e4-11e4-8e2e-9fa1b255c46f is blacklisted, skipping
140905 10:06:43 [Note] WSREP: (56501797-34e4-11e4-8e2e-9fa1b255c46f, 'tcp://0.0.0.0:4567') address 'tcp://10.0.1.11:4567' pointing to uuid 56501797-34e4-11e4-8e2e-9fa1b255c46f is blacklisted, skipping
140905 10:06:43 [Note] WSREP: (56501797-34e4-11e4-8e2e-9fa1b255c46f, 'tcp://0.0.0.0:4567') address 'tcp://10.0.1.11:4567' pointing to uuid 56501797-34e4-11e4-8e2e-9fa1b255c46f is blacklisted, skipping
140905 10:06:43 [Note] WSREP: (56501797-34e4-11e4-8e2e-9fa1b255c46f, 'tcp://0.0.0.0:4567') address 'tcp://10.0.1.11:4567' pointing to uuid 56501797-34e4-11e4-8e2e-9fa1b255c46f is blacklisted, skipping
140905 10:06:43 [Note] WSREP: declaring a4cd4f05-3478-11e4-9c81-16be9a238acd stable
140905 10:06:43 [Note] WSREP: declaring aba18e31-3478-11e4-ab11-5e91bb169bab stable
140905 10:06:43 [Note] WSREP: Node a4cd4f05-3478-11e4-9c81-16be9a238acd state prim
140905 10:06:43 [Note] WSREP: view(view_id(PRIM,56501797-34e4-11e4-8e2e-9fa1b255c46f,12) memb {
56501797-34e4-11e4-8e2e-9fa1b255c46f,0
a4cd4f05-3478-11e4-9c81-16be9a238acd,0
aba18e31-3478-11e4-ab11-5e91bb169bab,0
} joined {
} left {
} partitioned {
})
140905 10:06:43 [Note] WSREP: gcomm: connected
140905 10:06:43 [Note] WSREP: Changing maximum packet size to 64500, resulting msg size: 32636
140905 10:06:43 [Note] WSREP: Shifting CLOSED -> OPEN (TO: 0)
140905 10:06:43 [Note] WSREP: Opened channel 'my_wsrep_cluster'
140905 10:06:43 [Note] WSREP: New COMPONENT: primary = yes, bootstrap = no, my_idx = 0, memb_num = 3
140905 10:06:43 [Note] WSREP: Waiting for SST to complete.
140905 10:06:43 [Note] WSREP: STATE_EXCHANGE: sent state UUID: 56a72a83-34e4-11e4-a017-07567a513baf
140905 10:06:43 [Note] WSREP: STATE EXCHANGE: sent state msg: 56a72a83-34e4-11e4-a017-07567a513baf
140905 10:06:43 [Note] WSREP: STATE EXCHANGE: got state msg: 56a72a83-34e4-11e4-a017-07567a513baf from 1 ()
140905 10:06:43 [Note] WSREP: STATE EXCHANGE: got state msg: 56a72a83-34e4-11e4-a017-07567a513baf from 2 ()
140905 10:06:43 [Note] WSREP: STATE EXCHANGE: got state msg: 56a72a83-34e4-11e4-a017-07567a513baf from 0 ()
140905 10:06:43 [Note] WSREP: Quorum results:
version = 3,
component = PRIMARY,
conf_id = 9,
members = 2/3 (joined/total),
act_id = 2944373,
last_appl. = -1,
protocols = 0/5/3 (gcs/repl/appl),
group UUID = 40179a77-2bf4-11e4-b46a-a30695b570ce
140905 10:06:43 [Note] WSREP: Flow-control interval: [28, 28]
140905 10:06:43 [Note] WSREP: Shifting OPEN -> PRIMARY (TO: 2944373)
140905 10:06:43 [Note] WSREP: State transfer required:
Group state: 40179a77-2bf4-11e4-b46a-a30695b570ce:2944373
Local state: 00000000-0000-0000-0000-000000000000:-1
140905 10:06:43 [Note] WSREP: New cluster view: global state: 40179a77-2bf4-11e4-b46a-a30695b570ce:2944373, view# 10: Primary, number of nodes: 3, my index: 0, protocol version 3
140905 10:06:43 [Warning] WSREP: Gap in state sequence. Need state transfer.
140905 10:06:45 [Note] WSREP: Running: 'wsrep_sst_xtrabackup-v2 --role 'joiner' --address '10.0.1.11' --auth '' --datadir '/var/lib/mysql/' --defaults-file '/etc/mysql/my.cnf' --parent '883''
WSREP_SST: [INFO] Streaming with xbstream (20140905 10:06:46.192)
WSREP_SST: [INFO] Using socat as streamer (20140905 10:06:46.200)
WSREP_SST: [INFO] Using openssl based encryption with socat: with key and crt (20140905 10:06:46.212)
WSREP_SST: [INFO] Decrypting with certificate /etc/ssl/mysql/server-cert.pem, key /etc/ssl/mysql/server-key.pem (20140905 10:06:46.221)
WSREP_SST: [INFO] Evaluating socat -u openssl-listen:4444,reuseaddr,cert=/etc/ssl/mysql/server-cert.pem,key=/etc/ssl/mysql/server-key.pem,verify=0 stdio | pv -f -i 10 -N joiner | xbstream -x; RC=( ${PIPESTATUS[@]} ) (20140905 10:06:46.246)
140905 10:06:46 [Note] WSREP: Prepared SST request: xtrabackup-v2|10.0.1.11:4444/xtrabackup_sst
140905 10:06:46 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
140905 10:06:46 [Note] WSREP: REPL Protocols: 5 (3, 1)
140905 10:06:46 [Note] WSREP: Service thread queue flushed.
140905 10:06:46 [Note] WSREP: Assign initial position for certification: 2944373, protocol version: 3
140905 10:06:46 [Note] WSREP: Service thread queue flushed.
140905 10:06:46 [Warning] WSREP: Failed to prepare for incremental state transfer: Local state UUID (00000000-0000-0000-0000-000000000000) does not match group state UUID (40179a77-2bf4-11e4-b46a-a30695b570ce): 1 (Operation not permitted)
at galera/src/replicator_str.cpp:prepare_for_IST():447. IST will be unavailable.
140905 10:06:46 [Note] WSREP: Member 0.0 () requested state transfer from '*any*'. Selected 1.0 ()(SYNCED) as donor.
140905 10:06:46 [Note] WSREP: Shifting PRIMARY -> JOINER (TO: 2944383)
140905 10:06:46 [Note] WSREP: Requesting state transfer: success, donor: 1
joiner: 137B 0:00:00 [ 255B/s] [<=> ]
WSREP_SST: [INFO] Proceeding with SST (20140905 10:06:46.813)
WSREP_SST: [INFO] Cleaning the existing datadir (20140905 10:06:46.826)
removed '/var/lib/mysql/mysql-bin.000001'
removed '/var/lib/mysql/mysql-bin.000004'
removed '/var/lib/mysql/mysql-bin.index'
removed '/var/lib/mysql/mysql-bin.000003'
removed '/var/lib/mysql/monitpw.pem'
removed '/var/lib/mysql/mysql-bin.000005'
removed '/var/lib/mysql/aria_log_control'
removed '/var/lib/mysql/performance_schema/performance_timers.frm'
removed '/var/lib/mysql/performance_schema/file_summary_by_instance.frm'
removed '/var/lib/mysql/performance_schema/events_waits_summary_by_instance.frm'
removed '/var/lib/mysql/performance_schema/db.opt'
removed '/var/lib/mysql/performance_schema/file_summary_by_event_name.frm'
removed '/var/lib/mysql/performance_schema/file_instances.frm'
removed '/var/lib/mysql/performance_schema/setup_consumers.frm'
removed '/var/lib/mysql/performance_schema/events_waits_history_long.frm'
removed '/var/lib/mysql/performance_schema/cond_instances.frm'
removed '/var/lib/mysql/performance_schema/events_waits_summary_global_by_event_name.frm'
removed '/var/lib/mysql/performance_schema/events_waits_summary_by_thread_by_event_name.frm'
removed '/var/lib/mysql/performance_schema/events_waits_current.frm'
removed '/var/lib/mysql/performance_schema/threads.frm'
removed '/var/lib/mysql/performance_schema/rwlock_instances.frm'
removed '/var/lib/mysql/performance_schema/events_waits_history.frm'
removed '/var/lib/mysql/performance_schema/setup_timers.frm'
removed '/var/lib/mysql/performance_schema/setup_instruments.frm'
removed '/var/lib/mysql/performance_schema/mutex_instances.frm'
removed directory: '/var/lib/mysql/performance_schema'
removed '/var/lib/mysql/mysql-bin.000007'
removed '/var/lib/mysql/bootstrapped'
removed '/var/lib/mysql/ib_logfile1'
removed '/var/lib/mysql/mysql-bin.000006'
removed '/var/lib/mysql/aria_log.00000001'
removed '/var/lib/mysql/ibdata1'
removed '/var/lib/mysql/mysql.sock'
removed '/var/lib/mysql/ib_logfile0'
removed '/var/lib/mysql/rootpw.pem'
removed '/var/lib/mysql/mysql-bin.000002'
removed '/var/lib/mysql/mysql/proxies_priv.MYD'
removed '/var/lib/mysql/mysql/plugin.MYD'
removed '/var/lib/mysql/mysql/help_topic.MYD'
removed '/var/lib/mysql/mysql/user.MYI'
removed '/var/lib/mysql/mysql/help_relation.frm'
removed '/var/lib/mysql/mysql/ndb_binlog_index.frm'
removed '/var/lib/mysql/mysql/general_log.CSV'
removed '/var/lib/mysql/mysql/time_zone_transition.frm'
removed '/var/lib/mysql/mysql/servers.frm'
removed '/var/lib/mysql/mysql/help_keyword.MYI'
removed '/var/lib/mysql/mysql/ndb_binlog_index.MYI'
removed '/var/lib/mysql/mysql/user.frm'
removed '/var/lib/mysql/mysql/tables_priv.MYI'
removed '/var/lib/mysql/mysql/time_zone.MYI'
removed '/var/lib/mysql/mysql/time_zone_transition.MYI'
removed '/var/lib/mysql/mysql/time_zone.MYD'
removed '/var/lib/mysql/mysql/proc.MYD'
removed '/var/lib/mysql/mysql/procs_priv.MYI'
removed '/var/lib/mysql/mysql/tables_priv.frm'
removed '/var/lib/mysql/mysql/time_zone_leap_second.frm'
removed '/var/lib/mysql/mysql/time_zone_transition_type.frm'
removed '/var/lib/mysql/mysql/proc.frm'
removed '/var/lib/mysql/mysql/help_topic.frm'
removed '/var/lib/mysql/mysql/slow_log.CSM'
removed '/var/lib/mysql/mysql/plugin.MYI'
removed '/var/lib/mysql/mysql/slow_log.frm'
removed '/var/lib/mysql/mysql/slow_log.CSV'
removed '/var/lib/mysql/mysql/columns_priv.frm'
removed '/var/lib/mysql/mysql/general_log.CSM'
removed '/var/lib/mysql/mysql/time_zone.frm'
removed '/var/lib/mysql/mysql/procs_priv.frm'
removed '/var/lib/mysql/mysql/help_category.MYD'
removed '/var/lib/mysql/mysql/time_zone_transition_type.MYI'
removed '/var/lib/mysql/mysql/help_category.MYI'
removed '/var/lib/mysql/mysql/user.MYD'
removed '/var/lib/mysql/mysql/servers.MYI'
removed '/var/lib/mysql/mysql/time_zone_leap_second.MYI'
removed '/var/lib/mysql/mysql/host.frm'
removed '/var/lib/mysql/mysql/event.frm'
removed '/var/lib/mysql/mysql/help_topic.MYI'
removed '/var/lib/mysql/mysql/procs_priv.MYD'
removed '/var/lib/mysql/mysql/help_relation.MYD'
removed '/var/lib/mysql/mysql/db.MYD'
removed '/var/lib/mysql/mysql/event.MYI'
removed '/var/lib/mysql/mysql/func.MYI'
removed '/var/lib/mysql/mysql/proc.MYI'
removed '/var/lib/mysql/mysql/plugin.frm'
removed '/var/lib/mysql/mysql/help_keyword.frm'
removed '/var/lib/mysql/mysql/time_zone_name.MYD'
removed '/var/lib/mysql/mysql/db.MYI'
removed '/var/lib/mysql/mysql/time_zone_transition_type.MYD'
removed '/var/lib/mysql/mysql/help_keyword.MYD'
removed '/var/lib/mysql/mysql/func.frm'
removed '/var/lib/mysql/mysql/time_zone_transition.MYD'
removed '/var/lib/mysql/mysql/ndb_binlog_index.MYD'
removed '/var/lib/mysql/mysql/columns_priv.MYI'
removed '/var/lib/mysql/mysql/columns_priv.MYD'
removed '/var/lib/mysql/mysql/func.MYD'
removed '/var/lib/mysql/mysql/proxies_priv.MYI'
removed '/var/lib/mysql/mysql/help_relation.MYI'
removed '/var/lib/mysql/mysql/servers.MYD'
removed '/var/lib/mysql/mysql/time_zone_name.MYI'
removed '/var/lib/mysql/mysql/proxies_priv.frm'
removed '/var/lib/mysql/mysql/tables_priv.MYD'
removed '/var/lib/mysql/mysql/host.MYI'
removed '/var/lib/mysql/mysql/general_log.frm'
removed '/var/lib/mysql/mysql/event.MYD'
removed '/var/lib/mysql/mysql/host.MYD'
removed '/var/lib/mysql/mysql/time_zone_name.frm'
removed '/var/lib/mysql/mysql/help_category.frm'
removed '/var/lib/mysql/mysql/time_zone_leap_second.MYD'
removed '/var/lib/mysql/mysql/db.frm'
removed directory: '/var/lib/mysql/mysql'
WSREP_SST: [INFO] Evaluating socat -u openssl-listen:4444,reuseaddr,cert=/etc/ssl/mysql/server-cert.pem,key=/etc/ssl/mysql/server-key.pem,verify=0 stdio | pv -f -i 10 -N joiner | xbstream -x; RC=( ${PIPESTATUS[@]} ) (20140905 10:06:46.960)
joiner: 0B 0:00:10 [ 0B/s] [<=> ]
140905 10:06:57 [Warning] WSREP: 1.0 (): State transfer to 0.0 () failed: -22 (Invalid argument)
nfo' (20140905 10:06:57.297)
140905 10:06:57 [ERROR] WSREP: gcs/src/gcs_group.c:gcs_group_handle_join_msg():723: Will never receive state. Need to abort.
WSREP_SST: [INFO] -rwxr-xr-x 1 mysql mysql 143 Jul140905 10:06:57 [Note] WSREP: gcomm: joining thread
ysql mysql 134219048 Sep 5 10:06 /var/lib/mysql//galera.cache
-rwxr-xr-x 1 mysql mysql 104 Sep 5 10:06 /var/lib/mysql//grastate.dat
-rwxr-xr-x 1 mysql mysql 1061 Jul 23 02:12 /var/lib/mysql//innobackup.backup.log
-rwxr-xr-x 1 mysql mysql 17411522 Jul 23 02:12 /var/lib/mysql//mysql-1.error.log
-rwxr-xr-x 1 mysql mysql 209342 Jul 22 00:21 /var/lib/mysql//mysql-3.error.log
-rwxr-xr-x 1 mysql mysql 3365 Jul 17 19:52 /var/lib/mysql//mysql-error.log
-rwxr-xr-x 1 mysql mysql 742725 Jul 23 01:52 /var/lib/mysql//mysql-slow.log
-rwxr-xr-x 1 mysql mysql 806506 Sep 5 10:03 /var/lib/mysql//mysql.error.log
140905 10:06:57 [Note] WSREP: gcomm: closing backend
lib/mysql//sst_in_progress (20140905 10:06:57.320)
140905 10:06:57 [Note] WSREP: view(view_id(NON_PRIM,56501797-34e4-11e4-8e2e-9WSREP_SST: [INFO] Removing the sst_in_progress file (20140905 10:06:57.345)
left {
} partitioned {
a4cd4f05-3478-11e4-9c81-16be9a238acd,0
aba18e31-3478-11e4-ab11-5e91bb169bab,0
})
140905 10:06:57 [Note] WSREP: view((empty))
140905 10:06:57 [Note] WSREP: gcomm: closed
140905 10:06:57 [Note] WSREP: /usr/sbin/mysqld: Terminated.
140905 10:06:57 mysqld_safe mysqld from pid file /var/lib/mysql/mysql.pid ended

Would appreciate any pointers, I'm sure I'm just missing something.

Environment: Mariadb 5.5 Galera in Docker as per https://github.com/neildunbar/mariadb55

alexey.y...@galeracluster.com

unread,

Sep 5, 2014, 11:18:01 AM9/5/14

to codersh...@googlegroups.com

On 2014-09-05 13:14, Jay J wrote:
> Have been at it for a while, with no luck. The donor node is
> established,
> second node is connected, the third node just won't budge.
>
> Here's what I have in log: