rsync: did not see server greeting

[Raghavendra D Prabhu]

During rsync SST in one of the tests, got this:

...............
130815 4:46:17 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
130815 4:46:17 [Note] WSREP: Running: 'wsrep_sst_rsync --role 'donor' --address '127.0.0.1:4964/rsync_sst' --auth '(null)' --socket '/tmp/RQGmysql.13060.sock' --datadir '/mnt/workspace/PXC-5.5-mrandgen/BTYPE/debug/Host/centos6-64/41/tmp.awMy6wdtGt/current1_4/node0/data/' --defaults-file '' --gtid '9b1b251d-0565-11e3-904f-87af4061d88c:0''
130815 4:46:17 [Note] WSREP: sst_donor_thread signaled with 0
130815 4:46:18 [Note] WSREP: Flushing tables for SST...
130815 4:46:18 [Note] WSREP: Provider paused at 9b1b251d-0565-11e3-904f-87af4061d88c:0
130815 4:46:18 [Note] WSREP: Tables flushed.
rsync: did not see server greeting
rsync error: error starting client-server protocol (code 5) at main.c(1503) [sender=3.0.6]
WSREP_SST: [ERROR] rsync returned code 5: (20130815 04:46:18.462)
130815 4:46:18 [ERROR] WSREP: Failed to read from: wsrep_sst_rsync --role 'donor' --address '127.0.0.1:4964/rsync_sst' --auth '(null)' --socket '/tmp/RQGmysql.13060.sock' --datadir '/mnt/workspace/PXC-5.5-mrandgen/BTYPE/debug/Host/centos6-64/41/tmp.awMy6wdtGt/current1_4/node0/data/' --defaults-file '' --gtid '9b1b251d-0565-11e3-904f-87af4061d88c:0'
130815 4:46:18 [Note] WSREP: Provider resumed.
130815 4:46:18 [ERROR] WSREP: Process completed with error: wsrep_sst_rsync --role 'donor' --address '127.0.0.1:4964/rsync_sst' --auth '(null)' --socket '/tmp/RQGmysql.13060.sock' --datadir '/mnt/workspace/PXC-5.5-mrandgen/BTYPE/debug/Host/centos6-64/41/tmp.awMy6wdtGt/current1_4/node0/data/' --defaults-file '' --gtid '9b1b251d-0565-11e3-904f-87af4061d88c:0': 255 (Unknown error 255)
130815 4:46:18 [Warning] WSREP: 0 (jhc-new-2-centos6-64): State transfer to 1 (jhc-new-2-centos6-64) failed: -1 (Operation not permitted)
130815 4:46:18 [Note] WSREP: Shifting DONOR/DESYNCED -> JOINED (TO: 0)
130815 4:46:19 [Note] WSREP: Node 9b173b4b-0565-11e3-a4b2-cf16c747f3e4 state prim
130815 4:46:19 [Note] WSREP: view(view_id(PRIM,9b173b4b-0565-11e3-a4b2-cf16c747f3e4,3) memb {

...............................................................

Specificially

rsync: did not see server greeting
rsync error: error starting client-server protocol (code 5) at main.c(1503) [sender=3.0.6]

Interestingly, this happened after a bit of transfer. Needs to
be investigated further, will attach the logs.

[Raghavendra D Prabhu (raghavendra-prabhu)]

The trial log.

[Raghavendra D Prabhu (raghavendra-prabhu)]

The vardir of node0 and node1.

[Raghavendra D Prabhu (raghavendra-prabhu)]

rsync version:

rsync version 3.0.6 protocol version 30
Copyright (C) 1996-2009 by Andrew Tridgell, Wayne Davison, and others.
Web site: http://rsync.samba.org/
Capabilities:
    64-bit files, 64-bit inums, 64-bit timestamps, 64-bit long ints,
    socketpairs, hardlinks, symlinks, IPv6, batchfiles, inplace,
    append, ACLs, xattrs, iconv, symtimes

rsync comes with ABSOLUTELY NO WARRANTY. This is free software, and you
are welcome to redistribute it under certain conditions. See the GNU
General Public Licence for details.

[Alex Yurchenko (ayurchen)]

Raghu, this might be related to using parallelized rsync SST: it could be that joiner failed to spawn another server process fast enough. Perhaps adjusting rsync timeouts on the client (donor) side may help:
 --contimeout=SECONDS set daemon connection timeout in seconds

[Raghavendra D Prabhu (raghavendra-prabhu)]

@Alex,

From rsync manual, the error for timeout seems to be 30/35
whereas in this case it is 5.

However, since there are multiple connections to the daemon,
something like that cannot be ruled out.

[Raghavendra D Prabhu (raghavendra-prabhu)]

Got this again:

131027 17:51:32 [Note] WSREP: Flow-control interval: [23, 23]
131027 17:51:32 [Note] WSREP: New cluster view: global state: 6842d7b6-3f30-11e3-a7ff-ea4b5b154a86:0, view# 2: Primary, number of nodes: 2, my index: 0, protocol version 2
131027 17:51:32 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
131027 17:51:32 [Note] WSREP: Assign initial position for certification: 0, protocol version: 2
131027 17:51:35 [Note] WSREP: Node 1 (jhc-new-centos6-64) requested state transfer from '*any*'. Selected 0 (jhc-new-centos6-64)(SYNCED) as donor.
131027 17:51:35 [Note] WSREP: Shifting SYNCED -> DONOR/DESYNCED (TO: 0)
131027 17:51:35 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
131027 17:51:35 [Note] WSREP: Running: 'wsrep_sst_rsync --role 'donor' --address '127.0.0.1:4986/rsync_sst' --auth '(null)' --socket '/tmp/RQGmysql.10410.sock' --datadir '/mnt/workspace/PXC-5.5-mrandgen/BTYPE/release/Host/centos6-64/112/tmp.1mDmdZwMwl/current1_7/node0/data/' --defaults-file '' --gtid '6842d7b6-3f30-11e3-a7ff-ea4b5b154a86:0''
131027 17:51:35 [Note] WSREP: sst_donor_thread signaled with 0
131027 17:51:35 [Note] WSREP: Flushing tables for SST...
131027 17:51:35 [Note] WSREP: Provider paused at 6842d7b6-3f30-11e3-a7ff-ea4b5b154a86:0
131027 17:51:35 [Note] WSREP: Tables flushed.
rsync: did not see server greeting
rsync error: error starting client-server protocol (code 5) at main.c(1503) [sender=3.0.6]
WSREP_SST: [ERROR] rsync returned code 5: (20131027 17:51:36.207)
131027 17:51:36 [ERROR] WSREP: Failed to read from: wsrep_sst_rsync --role 'donor' --address '127.0.0.1:4986/rsync_sst' --auth '(null)' --socket '/tmp/RQGmysql.10410.sock' --datadir '/mnt/workspace/PXC-5.5-mrandgen/BTYPE/release/Host/centos6-64/112/tmp.1mDmdZwMwl/current1_7/node0/data/' --defaults-file '' --gtid '6842d7b6-3f30-11e3-a7ff-ea4b5b154a86:0'
131027 17:51:36 [Note] WSREP: Provider resumed.
131027 17:51:36 [ERROR] WSREP: Process completed with error: wsrep_sst_rsync --role 'donor' --address '127.0.0.1:4986/rsync_sst' --auth '(null)' --socket '/tmp/RQGmysql.10410.sock' --datadir '/mnt/workspace/PXC-5.5-mrandgen/BTYPE/release/Host/centos6-64/112/tmp.1mDmdZwMwl/current1_7/node0/data/' --defaults-file '' --gtid '6842d7b6-3f30-11e3-a7ff-ea4b5b154a86:0': 255 (Unknown error 255)
131027 17:51:36 [Warning] WSREP: 0 (jhc-new-centos6-64): State transfer to 1 (jhc-new-centos6-64) failed: -1 (Operation not permitted)
131027 17:51:36 [Note] WSREP: Shifting DONOR/DESYNCED -> JOINED (TO: 0)
131027 17:51:36 [Note] WSREP: Member 0 (jhc-new-centos6-64) synced with group.
131027 17:51:36 [Note] WSREP: Shifting JOINED -> SYNCED (TO: 0)
131027 17:51:36 [Note] WSREP: Synchronized with group, ready for connections
131027 17:51:36 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
131027 17:51:37 [Note] WSREP: Node 68420293-3f30-11e3-af27-1659788962dc state prim
131027 17:51:37 [Note] WSREP: view(view_id(PRIM,68420293-3f30-11e3-af27-1659788962dc,3) memb {
 68420293-3f30-11e3-af27-1659788962dc,
} joined {
} left {
} partitioned {
 69d5393d-3f30-11e3-9bbe-3fab1280f8c2,
})
131027 17:51:37 [Note] WSREP: forgetting 69d5393d-3f30-11e3-9bbe-3fab128...

[Shahriyar Rzayev (rzayev-sehriyar)]

Percona now uses JIRA for bug reports so this bug report is migrated to: https://jira.percona.com/browse/PXC-1420