[stunnel-users] Stunnel Session Hangs

Zachariah K Zachariah zkzac at stanford.edu
Sat Oct 29 00:24:06 CEST 2005 

Hi folks,

I use stunnel-4.12 with openssl-0.9.7g to tunnel my CVS-pserver protocols. I
have set up the local stunnel client to listen to port 22400 and to forward
any connections on it to the cvs server that has the server side stunnel
listening on port 22401 forwarding connections to the cvs-pserver on port
2401.

Having set up thus, I can do a cvs login just fine. I can watch the
negotiation happening using tcpdump. However when I try to check out a
module from the repository, I see some files coming through but only to
eventually hang. If I <Ctrl C> and try again, more files come in but hangs
before the transaction is complete. I have to do this several time in order
to download all the files to my local workspace.

Upon checking the logs, I find that the hang occurs immediately after the
message:

2005.10.28 14:21:53 LOG7[15095:67]: SSL_read returned WANT_READ: retrying
2005.10.28 14:21:53 LOG7[15095:67]: SSL_write returned WANT_WRITE: retrying
2005.10.28 14:21:53 LOG7[15095:67]: SSL_read returned WANT_READ: retrying

I have included a snippet of the log file for reference. I have also
included my stunnel.conf file. Sorry for the voluminous output. Can some
one help me here? Thanks in advance.

-ZZ
===============================STUNNEL.LOG==================================
The full log file reads:

2005.10.28 14:20:44 LOG6[15095:64]: SSL accepted: previous session reused
2005.10.28 14:20:44 LOG7[15095:64]: FD 1 in non-blocking mode
2005.10.28 14:20:44 LOG7[15095:64]: smd-pserver connecting 127.0.0.1:2401
2005.10.28 14:20:44 LOG7[15095:64]: Remote FD=1 initialized
2005.10.28 14:20:44 LOG7[15095:64]: SSL_read returned WANT_READ: retrying
2005.10.28 14:20:44 LOG7[15095:64]: SSL_write returned WANT_WRITE: retrying
2005.10.28 14:20:44 LOG7[15095:64]: SSL_read returned WANT_READ: retrying
2005.10.28 14:20:50 LOG7[15095:64]: SSL alert (read): warning: close notify
2005.10.28 14:20:50 LOG7[15095:64]: SSL closed on SSL_read
2005.10.28 14:20:50 LOG7[15095:64]: Socket write shutdown
2005.10.28 14:20:50 LOG7[15095:64]: SSL write shutdown
2005.10.28 14:20:50 LOG7[15095:64]: SSL alert (write): warning: close notify
2005.10.28 14:20:50 LOG6[15095:64]: SSL_shutdown successfully sent
close_notify
2005.10.28 14:20:50 LOG5[15095:64]: Connection closed: 73224 bytes sent to
SSL, 4724 bytes sent to socket
2005.10.28 14:20:50 LOG7[15095:64]: smd-pserver finished (0 left)
2005.10.28 14:20:50 LOG5[15095:64]: stack_info: size=65536, current=5004
(7%), maximum=5004 (7%)
2005.10.28 14:20:50 LOG7[15095:64]: Context 64 closed
2005.10.28 14:20:51 LOG7[15095:1]: Context set: 64 (dropped) -> 1
2005.10.28 14:20:51 LOG7[15095:1]: Current context: 1
2005.10.28 14:20:51 LOG7[15095:1]: Releasing context 64
2005.10.28 14:20:51 LOG7[15095:1]: smd-pserver accepted FD=0 from
171.65.79.143:65521
2005.10.28 14:20:51 LOG7[15095:1]: Creating a new context
2005.10.28 14:20:51 LOG7[15095:1]: Context 65 created
2005.10.28 14:20:51 LOG7[15095:65]: Context swap: 1 -> 65
2005.10.28 14:20:51 LOG7[15095:65]: smd-pserver started
2005.10.28 14:20:51 LOG7[15095:65]: FD 0 in non-blocking mode
2005.10.28 14:20:51 LOG5[15095:65]: smd-pserver connected from
171.65.79.143:65521
2005.10.28 14:20:51 LOG7[15095:65]: SSL state (accept): before/accept
initialization
2005.10.28 14:20:51 LOG7[15095:65]: SSL state (accept): SSLv3 read client
hello A
2005.10.28 14:20:51 LOG7[15095:65]: SSL state (accept): SSLv3 write server
hello A
2005.10.28 14:20:51 LOG7[15095:65]: SSL state (accept): SSLv3 write change
cipher spec A
2005.10.28 14:20:51 LOG7[15095:65]: SSL state (accept): SSLv3 write finished
A
2005.10.28 14:20:51 LOG7[15095:65]: SSL state (accept): SSLv3 flush data
2005.10.28 14:20:51 LOG7[15095:65]: SSL state (accept): SSLv3 read finished
A
2005.10.28 14:20:51 LOG7[15095:65]:    6 items in the session cache
2005.10.28 14:20:51 LOG7[15095:65]:    0 client connects (SSL_connect())
2005.10.28 14:20:51 LOG7[15095:65]:    0 client connects that finished
2005.10.28 14:20:51 LOG7[15095:65]:    0 client renegotiatations requested
2005.10.28 14:20:51 LOG7[15095:65]:   64 server connects (SSL_accept())
2005.10.28 14:20:51 LOG7[15095:65]:   55 server connects that finished
2005.10.28 14:20:51 LOG7[15095:65]:    0 server renegotiatiations requested
2005.10.28 14:20:51 LOG7[15095:65]:   38 session cache hits
2005.10.28 14:20:51 LOG7[15095:65]:    0 session cache misses
2005.10.28 14:20:51 LOG7[15095:65]:   11 session cache timeouts
2005.10.28 14:20:51 LOG6[15095:65]: SSL accepted: previous session reused
2005.10.28 14:20:51 LOG7[15095:65]: FD 1 in non-blocking mode
2005.10.28 14:20:51 LOG7[15095:65]: smd-pserver connecting 127.0.0.1:2401
2005.10.28 14:20:51 LOG7[15095:65]: Remote FD=1 initialized
2005.10.28 14:20:51 LOG7[15095:65]: SSL_read returned WANT_READ: retrying
2005.10.28 14:20:51 LOG7[15095:65]: SSL_write returned WANT_WRITE: retrying
2005.10.28 14:20:51 LOG7[15095:65]: SSL_read returned WANT_READ: retrying
2005.10.28 14:20:57 LOG7[15095:65]: SSL alert (read): warning: close notify
2005.10.28 14:20:57 LOG7[15095:65]: SSL closed on SSL_read
2005.10.28 14:20:57 LOG7[15095:65]: Socket write shutdown
2005.10.28 14:20:57 LOG7[15095:65]: SSL write shutdown
2005.10.28 14:20:57 LOG7[15095:65]: SSL alert (write): warning: close notify
2005.10.28 14:20:57 LOG6[15095:65]: SSL_shutdown successfully sent
close_notify
2005.10.28 14:20:57 LOG5[15095:65]: Connection closed: 73224 bytes sent to
SSL, 4724 bytes sent to socket
2005.10.28 14:20:57 LOG7[15095:65]: smd-pserver finished (0 left)
2005.10.28 14:20:57 LOG5[15095:65]: stack_info: size=65536, current=5004
(7%), maximum=5004 (7%)
2005.10.28 14:20:57 LOG7[15095:65]: Context 65 closed
2005.10.28 14:20:58 LOG7[15095:1]: Context set: 65 (dropped) -> 1
2005.10.28 14:20:58 LOG7[15095:1]: Current context: 1
2005.10.28 14:20:58 LOG7[15095:1]: Releasing context 65
2005.10.28 14:20:58 LOG7[15095:1]: smd-pserver accepted FD=0 from
171.65.79.143:65523
2005.10.28 14:20:58 LOG7[15095:1]: Creating a new context
2005.10.28 14:20:58 LOG7[15095:1]: Context 66 created
2005.10.28 14:20:58 LOG7[15095:66]: Context swap: 1 -> 66
2005.10.28 14:20:58 LOG7[15095:66]: smd-pserver started
2005.10.28 14:20:58 LOG7[15095:66]: FD 0 in non-blocking mode
2005.10.28 14:20:58 LOG5[15095:66]: smd-pserver connected from
171.65.79.143:65523
2005.10.28 14:20:58 LOG7[15095:66]: SSL state (accept): before/accept
initialization
2005.10.28 14:20:58 LOG7[15095:66]: SSL state (accept): SSLv3 read client
hello A
2005.10.28 14:20:58 LOG7[15095:66]: SSL state (accept): SSLv3 write server
hello A
2005.10.28 14:20:58 LOG7[15095:66]: SSL state (accept): SSLv3 write change
cipher spec A
2005.10.28 14:20:58 LOG7[15095:66]: SSL state (accept): SSLv3 write finished
A
2005.10.28 14:20:58 LOG7[15095:66]: SSL state (accept): SSLv3 flush data
2005.10.28 14:20:58 LOG7[15095:66]: SSL state (accept): SSLv3 read finished
A
2005.10.28 14:20:58 LOG7[15095:66]:    6 items in the session cache
2005.10.28 14:20:58 LOG7[15095:66]:    0 client connects (SSL_connect())
2005.10.28 14:20:58 LOG7[15095:66]:    0 client connects that finished
2005.10.28 14:20:58 LOG7[15095:66]:    0 client renegotiatations requested
2005.10.28 14:20:58 LOG7[15095:66]:   65 server connects (SSL_accept())
2005.10.28 14:20:58 LOG7[15095:66]:   56 server connects that finished
2005.10.28 14:20:58 LOG7[15095:66]:    0 server renegotiatiations requested
2005.10.28 14:20:58 LOG7[15095:66]:   39 session cache hits
2005.10.28 14:20:58 LOG7[15095:66]:    0 session cache misses
2005.10.28 14:20:58 LOG7[15095:66]:   11 session cache timeouts
2005.10.28 14:20:58 LOG6[15095:66]: SSL accepted: previous session reused
2005.10.28 14:20:58 LOG7[15095:66]: FD 1 in non-blocking mode
2005.10.28 14:20:58 LOG7[15095:66]: smd-pserver connecting 127.0.0.1:2401
2005.10.28 14:20:58 LOG7[15095:66]: Remote FD=1 initialized
2005.10.28 14:20:58 LOG7[15095:66]: SSL_read returned WANT_READ: retrying
2005.10.28 14:20:58 LOG7[15095:66]: SSL_write returned WANT_WRITE: retrying
2005.10.28 14:20:58 LOG7[15095:66]: SSL_read returned WANT_READ: retrying
2005.10.28 14:21:50 LOG7[15095:66]: SSL alert (read): warning: close notify
2005.10.28 14:21:50 LOG7[15095:66]: SSL closed on SSL_read
2005.10.28 14:21:50 LOG7[15095:66]: Socket write shutdown
2005.10.28 14:21:50 LOG7[15095:66]: SSL write shutdown
2005.10.28 14:21:50 LOG7[15095:66]: SSL alert (write): warning: close notify
2005.10.28 14:21:50 LOG6[15095:66]: SSL_shutdown successfully sent
close_notify
2005.10.28 14:21:50 LOG5[15095:66]: Connection closed: 73224 bytes sent to
SSL, 4724 bytes sent to socket
2005.10.28 14:21:50 LOG7[15095:66]: smd-pserver finished (0 left)
2005.10.28 14:21:50 LOG5[15095:66]: stack_info: size=65536, current=5004
(7%), maximum=5004 (7%)
2005.10.28 14:21:50 LOG7[15095:66]: Context 66 closed
2005.10.28 14:21:52 LOG7[15095:1]: Context set: 66 (dropped) -> 1
2005.10.28 14:21:52 LOG7[15095:1]: Current context: 1
2005.10.28 14:21:52 LOG7[15095:1]: Releasing context 66
2005.10.28 14:21:52 LOG7[15095:1]: smd-pserver accepted FD=0 from
171.65.79.143:65525
2005.10.28 14:21:52 LOG7[15095:1]: Creating a new context
2005.10.28 14:21:52 LOG7[15095:1]: Context 67 created
2005.10.28 14:21:52 LOG7[15095:67]: Context swap: 1 -> 67
2005.10.28 14:21:52 LOG7[15095:67]: smd-pserver started
2005.10.28 14:21:52 LOG7[15095:67]: FD 0 in non-blocking mode
2005.10.28 14:21:52 LOG5[15095:67]: smd-pserver connected from
171.65.79.143:65525
2005.10.28 14:21:52 LOG7[15095:67]: SSL state (accept): before/accept
initialization
2005.10.28 14:21:52 LOG7[15095:67]: SSL state (accept): SSLv3 read client
hello A
2005.10.28 14:21:52 LOG7[15095:67]: SSL state (accept): SSLv3 write server
hello A
2005.10.28 14:21:52 LOG7[15095:67]: SSL state (accept): SSLv3 write change
cipher spec A
2005.10.28 14:21:52 LOG7[15095:67]: SSL state (accept): SSLv3 write finished
A
2005.10.28 14:21:52 LOG7[15095:67]: SSL state (accept): SSLv3 flush data
2005.10.28 14:21:52 LOG7[15095:67]: SSL state (accept): SSLv3 read finished
A
2005.10.28 14:21:52 LOG7[15095:67]:    6 items in the session cache
2005.10.28 14:21:52 LOG7[15095:67]:    0 client connects (SSL_connect())
2005.10.28 14:21:52 LOG7[15095:67]:    0 client connects that finished
2005.10.28 14:21:52 LOG7[15095:67]:    0 client renegotiatations requested
2005.10.28 14:21:52 LOG7[15095:67]:   66 server connects (SSL_accept())
2005.10.28 14:21:52 LOG7[15095:67]:   57 server connects that finished
2005.10.28 14:21:52 LOG7[15095:67]:    0 server renegotiatiations requested
2005.10.28 14:21:52 LOG7[15095:67]:   40 session cache hits
2005.10.28 14:21:52 LOG7[15095:67]:    0 session cache misses
2005.10.28 14:21:52 LOG7[15095:67]:   11 session cache timeouts
2005.10.28 14:21:52 LOG6[15095:67]: SSL accepted: previous session reused
2005.10.28 14:21:52 LOG7[15095:67]: FD 1 in non-blocking mode
2005.10.28 14:21:52 LOG7[15095:67]: smd-pserver connecting 127.0.0.1:2401
2005.10.28 14:21:52 LOG7[15095:67]: Remote FD=1 initialized
2005.10.28 14:21:53 LOG7[15095:67]: SSL_read returned WANT_READ: retrying
2005.10.28 14:21:53 LOG7[15095:67]: SSL_write returned WANT_WRITE: retrying
2005.10.28 14:21:53 LOG7[15095:67]: SSL_read returned WANT_READ: retrying
==========================================================================
=========================STUNNEL.CONF======================================

; Sample stunnel configuration file by Michal Trojnara 2002-2005
; Some options used here may not be adequate for your particular
configuration
; Please make sure you understand them (especially the effect of chroot
jail)
;Delay DNS Lookups
delay = yes
; Certificate/key is needed in server mode and optional in client mode
cert = /tools/stunnel/4.12/etc/stunnel/stunnel.pem
;key = /tools/stunnel/4.12/etc/stunnel/mail.pem

; Some security enhancements for UNIX systems - comment them out on Win32
chroot = /tools/stunnel/4.12/var/stunnel/
setuid = cvsadmin
setgid = cvs
; PID is created inside chroot jail
pid = /stunnel.pid

; Some performance tunings
socket = l:TCP_NODELAY=1
socket = r:TCP_NODELAY=1
;compression = rle

; Workaround for Eudora bug
;options = DONT_INSERT_EMPTY_FRAGMENTS

; Authentication stuff
;verify = 2
; Don't forget to c_rehash CApath;  CApath is located inside chroot jail:
;CApath = /certs
; It's often easier to use CAfile:
;CAfile = /tools/stunnel/4.12/etc/stunnel/certs.pem
; Don't forget to c_rehash CRLpath;  CRLpath is located inside chroot jail:
;CRLpath = /crls
; Alternatively you can use CRLfile:
;CRLfile = /tools/stunnel/4.12/etc/stunnel/crls.pem

; Some debugging stuff useful for troubleshooting
debug = 7
output = /tools/stunnel/current/var/stunnel/stunnel.log

; Use it for client mode
;client = yes

; Service-level configuration

;[pop3s]
;accept  = 995
;connect = 110

;[imaps]
;accept  = 993
;connect = 143

;[ssmtp]
;accept  = 465
;connect = 25

[pserver]
accept  = 22401
connect = 2401
TIMEOUTclose = 30

; vim:ft=dosini

More information about the stunnel-users mailing list