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.
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.