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,
Most importantly I forgot:
stunnel 4.33 on x86_64-unknown-linux-gnu with OpenSSL 1.0.0a 1 Jun 2010 Threading:PTHREAD SSL:ENGINE Sockets:POLL,IPv6 Auth:LIBWRAP
Global options debug = daemon.notice pid = /var/run/stunnel/stunnel.pid RNDbytes = 64 RNDfile = /dev/urandom RNDoverwrite = yes
Service-level options cert = /etc/stunnel/stunnel.pem ciphers = ALL:!aNULL:!eNULL:!SSLv2 session = 300 seconds stack = 65536 bytes sslVersion = SSLv3 for client, all for server TIMEOUTbusy = 300 seconds TIMEOUTclose = 60 seconds TIMEOUTconnect = 10 seconds TIMEOUTidle = 43200 seconds verify = none
Yclept Nemo wrote:
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)
Well... Apache detected an incorrect request and closed its connection to stunnel. That's perfectly normal.
I guess there's something wrong with your client sending incorrect (maybe already encrypted?) requests.
Mike
-
Michal Trojnara -
Yclept Nemo