All,
I'm hoping that someone can assist with this.
I'm using Stunnel on 2 different systems: Mac and FC 13 to front-end my web server for a custom database system. It works flawlessly except for uploading large binary files.
The problem comes when trying to upload say a 2.5MB image file. The number of bytes actually transferred to the exec program is usually under 1K or right at about 33K. Using Firefox on Windows works all the time. I can observe the transfer by watching the stunnel.log file. When the data is piped into the openSSL engine, the number of bytes written to socket is being picked up by the exec program and processed so the loss is between the browser and the output side of Stunnel.
The message itself is a multi-part message that is not mime-encoded. The part with the image is set in the boundary properly and contains the JPEG binary. (Thanks to HTTPwatch!)
My Stunnel Version is:
[root@linux log]# stunnel -version stunnel 4.33 on i386-redhat-linux-gnu with OpenSSL 1.0.0a-fips 1 Jun 2010 Threading:PTHREAD SSL:ENGINE Sockets:POLL,IPv6 Auth:LIBWRAP
Global options debug = daemon.notice pid = /var/run/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
My configuration file on the Linux box is:
cert = /etc/stunnel/server.crt key = /etc/stunnel/server.key debug = 7 output = /var/log/stunnel.log ;socket = l:SO_LINGER=1:60 ;socket = r:TCP_NODELAY=1 client = no sslVersion = SSLv3 [https] libwrap = no accept = 443 exec = /usr/qmsys/bin/qm execargs = /usr/qmsys/bin/qm -b7 -quiet -aPAVUK "P.HTTP" options = DONT_INSERT_EMPTY_FRAGMENTS TIMEOUTidle = 30 TIMEOUTbusy = 5 TIMEOUTclose = 0
*** A RANDOM SUCCESSFUL TRANSFER *** 2010.10.15 10:03:12 LOG7[946:3078133552]: Service https accepted FD=0 from 24.171.161.99:1998 2010.10.15 10:03:12 LOG7[946:3078241136]: Service https started 2010.10.15 10:03:12 LOG7[946:3078241136]: FD=0 in non-blocking mode 2010.10.15 10:03:12 LOG5[946:3078241136]: Service https accepted connection from 24.171.161.99:1998 2010.10.15 10:03:12 LOG7[946:3078241136]: SSL state (accept): before accept initialization 2010.10.15 10:03:12 LOG7[946:3078241136]: SSL state (accept): SSLv3 read client hello A 2010.10.15 10:03:12 LOG7[946:3078241136]: SSL state (accept): SSLv3 write server hello A 2010.10.15 10:03:12 LOG7[946:3078241136]: SSL state (accept): SSLv3 write change cipher spec A 2010.10.15 10:03:12 LOG7[946:3078241136]: SSL state (accept): SSLv3 write finished A 2010.10.15 10:03:12 LOG7[946:3078241136]: SSL state (accept): SSLv3 flush data 2010.10.15 10:03:12 LOG7[946:3078241136]: SSL state (accept): SSLv3 read finished A 2010.10.15 10:03:12 LOG7[946:3078241136]: 8 items in the session cache 2010.10.15 10:03:12 LOG7[946:3078241136]: 0 client connects (SSL_connect()) 2010.10.15 10:03:12 LOG7[946:3078241136]: 0 client connects that finished 2010.10.15 10:03:12 LOG7[946:3078241136]: 0 client renegotiations requested 2010.10.15 10:03:12 LOG7[946:3078241136]: 35 server connects (SSL_accept()) 2010.10.15 10:03:12 LOG7[946:3078241136]: 35 server connects that finished 2010.10.15 10:03:12 LOG7[946:3078241136]: 0 server renegotiations requested 2010.10.15 10:03:12 LOG7[946:3078241136]: 27 session cache hits
2010.10.15 10:03:12 LOG7[946:3078241136]: 0 external session cache hits 2010.10.15 10:03:12 LOG7[946:3078241136]: 0 session cache misses 2010.10.15 10:03:12 LOG7[946:3078241136]: 0 session cache timeouts 2010.10.15 10:03:12 LOG6[946:3078241136]: SSL accepted: previous session reused 2010.10.15 10:03:12 LOG6[946:3078241136]: Local mode child started (PID=1179) 2010.10.15 10:03:12 LOG7[946:3078241136]: Remote FD=13 initialized 2010.10.15 10:03:13 LOG7[946:3078241136]: Socket closed on read 2010.10.15 10:03:13 LOG7[946:3078241136]: SSL write shutdown 2010.10.15 10:03:13 LOG7[946:3078241136]: SSL alert (write): warning: close notify 2010.10.15 10:03:13 LOG6[946:3078241136]: SSL_shutdown successfully sent close_notify 2010.10.15 10:03:13 LOG6[946:3078241136]: s_poll_wait timeout: connection close 2010.10.15 10:03:13 LOG5[946:3078241136]: Connection closed: 2895 bytes sent to SSL, 2469539 bytes sent to socket 2010.10.15 10:03:13 LOG7[946:3078241136]: Service https finished (0 left) 2010.10.15 10:03:13 LOG7[946:3078133552]: Cleaning up the signal pipe 2010.10.15 10:03:13 LOG6[946:3078133552]: Child process 1179 finished with code 0 2010.10.15 10:03:13 LOG7[946:3078133552]: Signal pipe is empty
*** MOST OF THE TIME - AN UNSUCCESSFUL TRANSFER ***
2010.10.15 10:05:01 LOG7[946:3078133552]: Service https accepted FD=0 from 24.171.161.99:1985 2010.10.15 10:05:01 LOG7[946:3077921648]: Service https started 2010.10.15 10:05:01 LOG7[946:3077921648]: FD=0 in non-blocking mode 2010.10.15 10:05:01 LOG5[946:3077921648]: Service https accepted connection from 24.171.161.99:1985 2010.10.15 10:05:01 LOG7[946:3077921648]: SSL state (accept): before/ accept initialization 2010.10.15 10:05:01 LOG7[946:3077921648]: SSL state (accept): SSLv3 read client hello A 2010.10.15 10:05:01 LOG7[946:3077921648]: SSL state (accept): SSLv3 write server hello A 2010.10.15 10:05:01 LOG7[946:3077921648]: SSL state (accept): SSLv3 write change cipher spec A 2010.10.15 10:05:01 LOG7[946:3077921648]: SSL state (accept): SSLv3 write finished A 2010.10.15 10:05:01 LOG7[946:3077921648]: SSL state (accept): SSLv3 flush data 2010.10.15 10:05:01 LOG7[946:3077921648]: SSL state (accept): SSLv3 read finished A 2010.10.15 10:05:01 LOG7[946:3077921648]: 9 items in the session cache 2010.10.15 10:05:01 LOG7[946:3077921648]: 0 client connects (SSL_connect()) 2010.10.15 10:05:01 LOG7[946:3077921648]: 0 client connects that finished 2010.10.15 10:05:01 LOG7[946:3077921648]: 0 client renegotiations requested 2010.10.15 10:05:01 LOG7[946:3077921648]: 44 server connects (SSL_accept()) 2010.10.15 10:05:01 LOG7[946:3077921648]: 44 server connects that finished 2010.10.15 10:05:01 LOG7[946:3077921648]: 0 server renegotiations requested 2010.10.15 10:05:01 LOG7[946:3077921648]: 35 session cache hits 2010.10.15 10:05:01 LOG7[946:3077921648]: 0 external session cache hits 2010.10.15 10:05:01 LOG7[946:3077921648]: 0 session cache misses 2010.10.15 10:05:01 LOG7[946:3077921648]: 0 session cache timeouts 2010.10.15 10:05:01 LOG6[946:3077921648]: SSL accepted: previous session reused 2010.10.15 10:05:01 LOG6[946:3077921648]: Local mode child started (PID=1213) 2010.10.15 10:05:01 LOG7[946:3077921648]: Remote FD=13 initialized 2010.10.15 10:05:04 LOG7[946:3077921648]: Socket closed on read 2010.10.15 10:05:04 LOG7[946:3077921648]: SSL write shutdown 2010.10.15 10:05:04 LOG7[946:3077921648]: SSL alert (write): warning: close notify 2010.10.15 10:05:04 LOG6[946:3077921648]: SSL_shutdown successfully sent close_notify 2010.10.15 10:05:04 LOG6[946:3077921648]: s_poll_wait timeout: connection close 2010.10.15 10:05:04 LOG5[946:3077921648]: Connection closed: 2895 bytes sent to SSL, 66703 bytes sent to socket 2010.10.15 10:05:04 LOG7[946:3077921648]: Service https finished (0 left) 2010.10.15 10:05:04 LOG7[946:3078133552]: Cleaning up the signal pipe 2010.10.15 10:05:04 LOG6[946:3078133552]: Child process 1213 finished with code 0 2010.10.15 10:05:04 LOG7[946:3078133552]: Signal pipe is empty
***
All test cases are the same upload of the same image file. In all tests the number of bytes sent to socket matches what the exec program is receiving in its pipe.
My feeling is that there is a connection issue between the browser and Stunnel. The successful upload of the test occurs sometimes with all browsers and appears to always work with Firefox for Windows. It has a 90% failure rate on Safari for Windows, Safari for Mac, Opera for Windows, Opera for Mac, etc.
In all cases of testing, the number of bytes "sent to socket" is received by my exec program and consists of a truncated message from the browser. It appears that the data is simply being truncated somewhere in the Stunnel process.
Any help is always appreciated! If there are more tests to be run to track down the problem, please advise and I will run them.
Regards,
Bill
Bill Crowell, President Pavuk Technologies, LLC PO Box 33097 Charlotte, NC 28233-3097 Office +1 704.248.0024 Mobile +1 704.607.6077 Skype pavuk.com
Bill Crowell wrote:
TIMEOUTidle = 30
TIMEOUTbusy = 5 TIMEOUTclose = 0
So for some strange reason you decided to drop any buffered data on close (TIMEOUTclose = 0) ...
2010.10.15 10:05:04 LOG7[946:3077921648]: Socket closed on read 2010.10.15 10:05:04 LOG7[946:3077921648]: SSL write shutdown 2010.10.15 10:05:04 LOG7[946:3077921648]: SSL alert (write): warning: close notify 2010.10.15 10:05:04 LOG6[946:3077921648]: SSL_shutdown successfully sent close_notify 2010.10.15 10:05:04 LOG6[946:3077921648]: s_poll_wait timeout: connection close
... and that's exactly what stunnel did.
Mike