This turned out to be an issue with rsync-3.1.0, and fixed in rsync-3.1.1:
- Fixed a bug in the early daemon protocol where a timeout failed to be
honored (e.g. if the remote side fails to send us the initial protocol
greeting).
Thanks,
Steve
From: stunnel-users [mailto:[email protected]] On Behalf Of
Polyack, Steve
Sent: Wednesday, October 22, 2014 12:36 PM
To: [email protected]
Cc: Saathoff, Graham
Subject: [stunnel-users] stunnel service leaves stale connections to rsync on
the server side
Hi,
We've been running a rsync service over stunnel for some time now. After
upgrading our environment, which involved moving from an old version of Linux
to FreeBSD 9.3, and from stunnel-4.29 to stunnel-5.06, we've had a problem pop
up.
Ever since switching over, we see that rsync daemon processes slowly build up
over time on our server, each consuming 100% CPU. The vast majority of our
clients are working just fine, and the problematic rsync processes just seem to
have been dead/aborted connections from the clients (which are using wireless
aircard, so connectivity can be shotty).
A quick 'truss' on the process shows they are doing nothing but sitting there
and read()'ing in a loop indefinitely:
# truss -p 14689 | head
read(6,0x7fffffff8240,1) = 0
(0x0)
read(6,0x7fffffff8240,1) = 0
(0x0)
read(6,0x7fffffff8240,1) = 0
(0x0)
read(6,0x7fffffff8240,1) = 0
(0x0)
read(6,0x7fffffff8240,1) = 0
(0x0)
read(6,0x7fffffff8240,1) = 0
(0x0)
Furthermore, the connection appears to be closed:
# sockstat -4 | grep 14689
root rsync 14689 3 tcp4 127.0.0.1:873 127.0.0.1:27724
netstat -an | grep 27724
netstat: kvm not available: /dev/mem: No such file or directory
tcp4 0 0 127.0.0.1.873 127.0.0.1.27724 CLOSED
Looking through the stunnel logs, it looks like no data was ever really passed
(perhaps the client gave up?):
2014.10.22 10:45:52 LOG7[34384941056]: Service [rsync] started
2014.10.22 10:45:52 LOG5[34384941056]: Service [rsync] accepted connection from
1.1.1.1:63095
2014.10.22 10:45:52 LOG7[34384941056]: SSL state (accept): before/accept
initialization
2014.10.22 10:45:52 LOG7[34384941056]: SSL state (accept): SSLv3 read client
hello A
2014.10.22 10:45:52 LOG7[34384941056]: SSL state (accept): SSLv3 write server
hello A
2014.10.22 10:45:52 LOG7[34384941056]: SSL state (accept): SSLv3 write
certificate A
2014.10.22 10:45:52 LOG7[34384941056]: SSL state (accept): SSLv3 write server
done A
2014.10.22 10:45:52 LOG7[34384941056]: SSL state (accept): SSLv3 flush data
2014.10.22 10:45:52 LOG7[34384941056]: SSL state (accept): SSLv3 read client
key exchange A
2014.10.22 10:45:52 LOG7[34384941056]: SSL state (accept): SSLv3 read finished A
2014.10.22 10:45:52 LOG7[34384941056]: SSL state (accept): SSLv3 write change
cipher spec A
2014.10.22 10:45:52 LOG7[34384941056]: SSL state (accept): SSLv3 write finished
A
2014.10.22 10:45:52 LOG7[34384941056]: SSL state (accept): SSLv3 flush data
2014.10.22 10:45:52 LOG7[34384941056]: 41 items in the session cache
2014.10.22 10:45:52 LOG7[34384941056]: 0 client connects (SSL_connect())
2014.10.22 10:45:52 LOG7[34384941056]: 0 client connects that finished
2014.10.22 10:45:52 LOG7[34384941056]: 0 client renegotiations requested
2014.10.22 10:45:52 LOG7[34384941056]: 110 server connects (SSL_accept())
2014.10.22 10:45:52 LOG7[34384941056]: 107 server connects that finished
2014.10.22 10:45:52 LOG7[34384941056]: 0 server renegotiations requested
2014.10.22 10:45:52 LOG7[34384941056]: 66 session cache hits
2014.10.22 10:45:52 LOG7[34384941056]: 0 external session cache hits
2014.10.22 10:45:52 LOG7[34384941056]: 32 session cache misses
2014.10.22 10:45:52 LOG7[34384941056]: 0 session cache timeouts
2014.10.22 10:45:52 LOG6[34384941056]: No peer certificate received
2014.10.22 10:45:52 LOG6[34384941056]: SSL accepted: new session negotiated
2014.10.22 10:45:52 LOG6[34384941056]: Negotiated SSLv3 ciphersuite AES256-SHA
(256-bit encryption)
2014.10.22 10:45:52 LOG6[34384941056]: Compression: null, expansion: null
2014.10.22 10:45:52 LOG6[34384941056]: s_connect: connecting 127.0.0.1:873
2014.10.22 10:45:52 LOG5[34384941056]: s_connect: connected 127.0.0.1:873
2014.10.22 10:45:52 LOG5[34384941056]: Service [rsync] connected remote server
from 127.0.0.1:27724
2014.10.22 10:45:52 LOG7[34384941056]: Remote socket (FD=11) initialized
2014.10.22 11:01:12 LOG3[34384941056]: SSL_read: Connection reset by peer (54)
2014.10.22 11:01:12 LOG5[34384941056]: Connection reset: 56 byte(s) sent to
SSL, 56 byte(s) sent to socket
2014.10.22 11:01:12 LOG7[34384941056]: Remote socket (FD=11) closed
2014.10.22 11:01:12 LOG7[34384941056]: Local socket (FD=10) closed
2014.10.22 11:01:12 LOG7[34384941056]: Service [rsync] finished (4 left)
The clients are generally field units running stunnel versions in the 4.x
range. Unfortunately, updating them is not an easy task and is not really
under my control. Either way, this seems like a server side issue, and
possibly an issue with rsync (we're running 3.1.0).
Has anyone run into anything like this before? Does anyone have any
suggestions for additional debugging we can do to try to pinpoint the problem?
We are going to try rolling back to stunnel-4.29 to see if the problem still
occurs there on the new system.
Thanks,
Steve
_______________________________________________
stunnel-users mailing list
[email protected]
https://www.stunnel.org/cgi-bin/mailman/listinfo/stunnel-users
