[stunnel-users] stunnel and mod_gnutls

Sun Aug 15 10:37:53 CEST 2010

I run a mod_gnutls (0.5.5)<->apache (2.2.8) webserver which behaves
perfectly normally outside of stunnel:
GnuTLSEnable on
GnuTLSPriorities SECURE256
GnuTLSExportCertificates on
..
When a connection is closed and apache signals the mod_gnutls process
to quit, the log records:
GnuTLS: Handshake Failed (-8) 'A record packet with illegal version
was received.'
Invalid method in request NS * HTTP/1.0
::1 - - [15/Aug/2010:03:31:26 -0400] "NS * HTTP/1.0" 501 512 "-"
"Apache/2.2.8 (Ubuntu) ... (internal dummy connection)"
This lets me easily identify apache2 process turnovers

However, when I connect to this server through stunnel, I receive
random dropouts. For example, if I were to upload 200 test files to
this server, on average 15 transfers would fail.
Stunnel logs (excerpt):
2010.08.15 04:11:25 LOG5[29287:3074030448]: Connection reset: 94 bytes
sent to SSL, 523 bytes sent to socket
2010.08.15 04:12:21 LOG5[29287:3074448240]: Connection reset: 94 bytes
sent to SSL, 523 bytes sent to socket
2010.08.15 04:12:34 LOG5[29287:3074030448]: Connection reset: 94 bytes
sent to SSL, 523 bytes sent to socket
And my apache2 logs are flooded with:
Invalid method in request \x16\x03\x01    # ... over and over and over
...
Invalid method in request \x16\x03\x01    # ... this is a tls hello
sequence, as though the webserver were not running mod_gnutls
::1 - - [15/Aug/2010:03:31:26 -0400] "NS * HTTP/1.0" 501 512 "-"
"Apache/2.2.8 (Ubuntu) ... (internal dummy connection)"
The apache logs show new apache2 processes / new ssl connections being
created every 2-5 seconds. A normal connections lasts much longer.

stunnel configuration
debug=7
foreground=yes
client=yes
syslog=no
pid=/absolute/path/to/stunnel.pid
libwrap=no
[https]
accept=127.0.0.1:11111
connect=my.website.net:myport
sslVersion=TLSv1

an excerpt from the stunnel log:
2010.08.15 04:11:25 LOG6[29287:3074030448]: SSL connected: previous
session reused
2010.08.15 04:11:25 LOG7[29287:3073960816]: Service https started
2010.08.15 04:11:25 LOG7[29287:3073960816]: FD=19 in non-blocking mode
2010.08.15 04:11:25 LOG5[29287:3073960816]: Service https accepted
connection from 127.0.0.1:52674
2010.08.15 04:11:25 LOG7[29287:3073960816]: FD=20 in non-blocking mode
2010.08.15 04:11:25 LOG6[29287:3073960816]: connect_blocking:
connecting 44.205.51.83:12389
2010.08.15 04:11:25 LOG7[29287:3073960816]: connect_blocking:
s_poll_wait 44.205.51.83:12389: waiting 10 seconds
2010.08.15 04:11:25 LOG5[29287:3073960816]: connect_blocking:
connected 44.205.51.83:12389
2010.08.15 04:11:25 LOG5[29287:3073960816]: Service https connected
remote server from 192.168.1.8:51590
2010.08.15 04:11:25 LOG7[29287:3073960816]: Remote FD=20 initialized
2010.08.15 04:11:25 LOG7[29287:3073960816]: SSL state (connect):
before/connect initialization
2010.08.15 04:11:25 LOG7[29287:3073960816]: SSL state (connect): SSLv3
write client hello A
2010.08.15 04:11:25 LOG7[29287:3073960816]: SSL state (connect): SSLv3
read server hello A
2010.08.15 04:11:25 LOG7[29287:3073960816]: SSL state (connect): SSLv3
read finished A
2010.08.15 04:11:25 LOG7[29287:3073960816]: SSL state (connect): SSLv3
write change cipher spec A
2010.08.15 04:11:25 LOG7[29287:3073960816]: SSL state (connect): SSLv3
write finished A
2010.08.15 04:11:25 LOG7[29287:3073960816]: SSL state (connect): SSLv3
flush data
2010.08.15 04:11:25 LOG7[29287:3073960816]:    1 items in the session cache
2010.08.15 04:11:25 LOG7[29287:3073960816]:   42 client connects (SSL_connect())
2010.08.15 04:11:25 LOG7[29287:3073960816]:   42 client connects that finished
2010.08.15 04:11:25 LOG7[29287:3073960816]:    0 client renegotiations requested
2010.08.15 04:11:25 LOG7[29287:3073960816]:    0 server connects (SSL_accept())
2010.08.15 04:11:25 LOG7[29287:3073960816]:    0 server connects that finished
2010.08.15 04:11:25 LOG7[29287:3073960816]:    0 server renegotiations requested
2010.08.15 04:11:25 LOG7[29287:3073960816]:   41 session cache hits
2010.08.15 04:11:25 LOG7[29287:3073960816]:    0 external session cache hits
2010.08.15 04:11:25 LOG7[29287:3073960816]:    0 session cache misses
2010.08.15 04:11:25 LOG7[29287:3073960816]:    0 session cache timeouts
2010.08.15 04:11:25 LOG6[29287:3073960816]: SSL connected: previous
session reused
2010.08.15 04:11:25 LOG3[29287:3074030448]: SSL socket closed on
SSL_read with 7 byte(s) in buffer
2010.08.15 04:11:25 LOG5[29287:3074030448]: Connection reset: 94 bytes
sent to SSL, 523 bytes sent to socket
2010.08.15 04:11:25 LOG7[29287:3074030448]: Service https finished (4 left)
2010.08.15 04:11:25 LOG7[29287:3073960816]: SSL socket closed on SSL_read
2010.08.15 04:11:25 LOG7[29287:3073960816]: Socket write shutdown
2010.08.15 04:11:25 LOG5[29287:3073960816]: Connection closed: 94
bytes sent to SSL, 523 bytes sent to socket
2010.08.15 04:11:25 LOG7[29287:3073960816]: Service https finished (3 left)
2010.08.15 04:11:26 LOG7[29287:3074448240]: SSL socket closed on SSL_read
2010.08.15 04:11:26 LOG7[29287:3074448240]: Socket write shutdown
2010.08.15 04:11:26 LOG5[29287:3074448240]: Connection closed: 1110
bytes sent to SSL, 77962 bytes sent to socket
2010.08.15 04:11:26 LOG7[29287:3074517872]: SSL socket closed on SSL_read
2010.08.15 04:11:26 LOG7[29287:3074517872]: Socket write shutdown
2010.08.15 04:11:26 LOG7[29287:3074448240]: Service https finished (2 left)
2010.08.15 04:11:26 LOG5[29287:3074517872]: Connection closed: 575
bytes sent to SSL, 4889 bytes sent to socket
2010.08.15 04:11:26 LOG7[29287:3074517872]: Service https finished (1 left)
2010.08.15 04:11:26 LOG7[29287:3074378608]: SSL socket closed on SSL_read
2010.08.15 04:11:26 LOG7[29287:3074378608]: Socket write shutdown
2010.08.15 04:11:26 LOG5[29287:3074378608]: Connection closed: 573
bytes sent to SSL, 48787 bytes sent to socket
2010.08.15 04:11:26 LOG7[29287:3074378608]: Service https finished (0 left)
2010.08.15 04:11:26 LOG7[29287:3074520768]: Service https accepted
FD=11 from 127.0.0.1:52676
2010.08.15 04:11:26 LOG7[29287:3074378608]: Service https started
2010.08.15 04:11:26 LOG7[29287:3074378608]: FD=11 in non-blocking mode
2010.08.15 04:11:26 LOG5[29287:3074378608]: Service https accepted
connection from 127.0.0.1:52676
2010.08.15 04:11:26 LOG7[29287:3074378608]: FD=12 in non-blocking mode
2010.08.15 04:11:26 LOG6[29287:3074378608]: connect_blocking:
connecting 44.205.51.83:12389
2010.08.15 04:11:26 LOG7[29287:3074378608]: connect_blocking:
s_poll_wait 44.205.51.83:12389: waiting 10 seconds
2010.08.15 04:11:26 LOG5[29287:3074378608]: connect_blocking:
connected 44.205.51.83:12389
2010.08.15 04:11:26 LOG5[29287:3074378608]: Service https connected
remote server from 192.168.1.8:51592
2010.08.15 04:11:26 LOG7[29287:3074378608]: Remote FD=12 initialized
2010.08.15 04:11:26 LOG7[29287:3074378608]: SSL state (connect):
before/connect initialization
2010.08.15 04:11:26 LOG7[29287:3074378608]: SSL state (connect): SSLv3
write client hello A
2010.08.15 04:11:26 LOG7[29287:3074378608]: SSL state (connect): SSLv3
read server hello A
2010.08.15 04:11:26 LOG7[29287:3074378608]: SSL state (connect): SSLv3
read finished A
2010.08.15 04:11:26 LOG7[29287:3074378608]: SSL state (connect): SSLv3
write change cipher spec A
2010.08.15 04:11:26 LOG7[29287:3074378608]: SSL state (connect): SSLv3
write finished A
2010.08.15 04:11:26 LOG7[29287:3074378608]: SSL state (connect): SSLv3
flush data

My questions are: Why does this happen (why only with stunnel), and
how can I prevent/avoid this?

Sincerely,