ports/81162: stunnel-4.10 is broken on 5.4-RELEASE-p1 (4.09 works)

Tue May 17 14:20:07 UTC 2005

>Number:         81162
>Category:       ports
>Synopsis:       stunnel-4.10 is broken on 5.4-RELEASE-p1 (4.09 works)
>Confidential:   no
>Severity:       non-critical
>Priority:       medium
>Responsible:    freebsd-ports-bugs
>State:          open
>Quarter:        
>Keywords:       
>Date-Required:
>Class:          sw-bug
>Submitter-Id:   current-users
>Arrival-Date:   Tue May 17 14:20:01 GMT 2005
>Closed-Date:
>Last-Modified:
>Originator:     Niels Bakker
>Release:        FreeBSD 5.4-RELEASE-p1 i386
>Organization:
>Environment:
System: FreeBSD snowcrash 5.4-RELEASE-p1 FreeBSD 5.4-RELEASE-p1 #79: Fri May 13 20:20:29 CEST 2005 niels at snowcrash.tpb.net:/usr/obj/usr/src/sys/SNOWCRASH i386

SMP system (dual Pentium II).

>Description:
ports/security/stunnel 4.10 fails to work.

www.stunnel.org notes "test thoroughly before using in production
environments. See changelog" about version 4.10.  Having this in ports
seems unadvisable.

stunnel is configured to run from inetd as follows:

---
snowcrash:ttyp0 402 # grep stun /etc/inetd.conf 
pop3s   stream  tcp     nowait/10/6     root    /usr/local/sbin/stunnel stunnel /usr/local/etc/stunnel/pop3s.conf
pop3s   stream  tcp6    nowait/10/6     root    /usr/local/sbin/stunnel stunnel /usr/local/etc/stunnel/pop3s.conf
---

This is /usr/local/etc/stunnel/pop3s.conf:
---
cert = /usr/local/etc/stunnel/pop3s.pem
pid = /var/run/stunnel-pop3.pid
exec = /usr/local/libexec/popa3d
execargs = popa3d
debug = 7
foreground = yes
output = /tmp/s.log
TIMEOUTidle = 10
---

For a non-working session /tmp/s.log contains:
---
2005.05.17 15:00:54 LOG5[18148:1]: stunnel 4.10 on i386-unknown-freebsd5.4 UCONTEXT+POLL+IPv4+LIBWRAP with OpenSSL 0.9.7e 25 Oct 2004
2005.05.17 15:00:54 LOG7[18148:1]: RAND_status claims sufficient entropy for the PRNG
2005.05.17 15:00:54 LOG6[18148:1]: PRNG seeded successfully
2005.05.17 15:00:54 LOG7[18148:1]: Certificate: /usr/local/etc/stunnel/pop3s.pem
2005.05.17 15:00:54 LOG7[18148:1]: Key file: /usr/local/etc/stunnel/pop3s.pem
2005.05.17 15:00:54 LOG7[18148:1]: stunnel started
2005.05.17 15:00:54 LOG7[18148:1]: FD 0 in non-blocking mode
2005.05.17 15:00:54 LOG7[18148:1]: FD 1 in non-blocking mode
2005.05.17 15:00:54 LOG5[18148:1]: stunnel connected from x.y.z.a:59722
2005.05.17 15:00:54 LOG7[18148:1]: SSL state (accept): before/accept initialization
2005.05.17 15:00:54 LOG7[18148:1]: SSL state (accept): SSLv3 read client hello A
2005.05.17 15:00:54 LOG7[18148:1]: SSL state (accept): SSLv3 write server hello A
2005.05.17 15:00:54 LOG7[18148:1]: SSL state (accept): SSLv3 write certificate A
2005.05.17 15:00:54 LOG7[18148:1]: SSL state (accept): SSLv3 write server done A
2005.05.17 15:00:54 LOG7[18148:1]: SSL state (accept): SSLv3 flush data
2005.05.17 15:00:54 LOG7[18148:0]: Waiting 300 second(s) for 1 file descriptor(s)
2005.05.17 15:07:20 LOG5[18148:0]: Received signal 15; terminating
---
(I killed it when it had become apparent that the process had
 effectively died)

>How-To-Repeat:
Try to use stunnel as described above.  Using Apple Mail.app to attempt
to retrieve mail.

Compiling with or without IPv6 has no influence.

>Fix:
Downgrading from 4.10 to 4.09 fixes the problem.

The logfile then shows for a connection:
---
2005.05.17 16:02:05 LOG5[32300:134639616]: stunnel 4.09 on i386-unknown-freebsd5.4 PTHREAD+POLL+IPv6+LIBWRAP with OpenSSL 0.9.7e 25 Oct 2004
2005.05.17 16:02:05 LOG7[32300:134639616]: RAND_status claims sufficient entropy for the PRNG
2005.05.17 16:02:05 LOG6[32300:134639616]: PRNG seeded successfully
2005.05.17 16:02:05 LOG7[32300:134639616]: Certificate: /usr/local/etc/stunnel/pop3s.pem
2005.05.17 16:02:05 LOG7[32300:134639616]: Key file: /usr/local/etc/stunnel/pop3s.pem
2005.05.17 16:02:05 LOG7[32300:134639616]: stunnel started
2005.05.17 16:02:05 LOG5[32300:134639616]: stunnel connected from x.y.z.a:59807
2005.05.17 16:02:05 LOG7[32300:134639616]: SSL state (accept): before/accept initialization
2005.05.17 16:02:05 LOG7[32300:134639616]: SSL state (accept): SSLv3 read client hello A
2005.05.17 16:02:05 LOG7[32300:134639616]: SSL state (accept): SSLv3 write server hello A
2005.05.17 16:02:05 LOG7[32300:134639616]: SSL state (accept): SSLv3 write certificate A
2005.05.17 16:02:05 LOG7[32300:134639616]: SSL state (accept): SSLv3 write server done A
2005.05.17 16:02:05 LOG7[32300:134639616]: SSL state (accept): SSLv3 flush data
2005.05.17 16:02:05 LOG7[32300:134639616]: SSL state (accept): SSLv3 read client key exchange A
2005.05.17 16:02:05 LOG7[32300:134639616]: SSL state (accept): SSLv3 read finished A
2005.05.17 16:02:05 LOG7[32300:134639616]: SSL state (accept): SSLv3 write change cipher spec A
2005.05.17 16:02:05 LOG7[32300:134639616]: SSL state (accept): SSLv3 write finished A
2005.05.17 16:02:05 LOG7[32300:134639616]: SSL state (accept): SSLv3 flush data
2005.05.17 16:02:05 LOG7[32300:134639616]:    1 items in the session cache
2005.05.17 16:02:05 LOG7[32300:134639616]:    0 client connects (SSL_connect())
2005.05.17 16:02:05 LOG7[32300:134639616]:    0 client connects that finished
2005.05.17 16:02:05 LOG7[32300:134639616]:    0 client renegotiatations requested
2005.05.17 16:02:05 LOG7[32300:134639616]:    1 server connects (SSL_accept())
2005.05.17 16:02:05 LOG7[32300:134639616]:    1 server connects that finished
2005.05.17 16:02:05 LOG7[32300:134639616]:    0 server renegotiatiations requested
2005.05.17 16:02:05 LOG7[32300:134639616]:    0 session cache hits
2005.05.17 16:02:05 LOG7[32300:134639616]:    0 session cache misses
2005.05.17 16:02:05 LOG7[32300:134639616]:    0 session cache timeouts
2005.05.17 16:02:05 LOG6[32300:134639616]: SSL accepted: new session negotiated
2005.05.17 16:02:05 LOG6[32300:134639616]: Negotiated ciphers: RC4-SHA                 SSLv3 Kx=RSA      Au=RSA  Enc=RC4(128)  Mac=SHA1
2005.05.17 16:02:05 LOG7[32300:134639616]: bind#1: Invalid argument (22)
2005.05.17 16:02:05 LOG7[32300:134639616]: bind#2: Invalid argument (22)
2005.05.17 16:02:05 LOG6[32300:134639616]: Local mode child started (PID=32301)
2005.05.17 16:02:05 LOG7[32300:134639616]: Remote FD=6 initialized
2005.05.17 16:02:10 LOG7[32300:134639616]: Socket closed on read
2005.05.17 16:02:10 LOG7[32300:134639616]: SSL write shutdown
2005.05.17 16:02:10 LOG7[32300:134639616]: SSL alert (write): warning: close notify
2005.05.17 16:02:10 LOG7[32300:134639616]: SSL_shutdown retrying
2005.05.17 16:02:10 LOG7[32300:134639616]: SSL alert (read): warning: close notify
2005.05.17 16:02:10 LOG7[32300:134639616]: SSL closed on SSL_read
2005.05.17 16:02:10 LOG7[32300:134639616]: Socket write shutdown
2005.05.17 16:03:10 LOG6[32300:134639616]: s_poll_wait timeout: connection close
2005.05.17 16:03:10 LOG5[32300:134639616]: Connection closed: 27168 bytes sent to SSL, 178 bytes sent to socket
2005.05.17 16:03:10 LOG7[32300:134639616]: stunnel finished (0 left)
---

Downgrading to 4.09 was accomplished by changing "4.10" to "4.09" in
the port's Makefile and adjusting distinfo accordingly, nothing fancy.
>Release-Note:
>Audit-Trail:
>Unformatted: