Hello,
We are having a problem with our application using STUNNEL and are stuck. I have detailed the issue below with more detailed info about our setup. I am not very familiar with the SSL protocol so I am having trouble identifying the differences between the log samples I posted to determine what the issue may be. Any help would be greatly appreciated.
Thanks,
Salar Madadi - Latest Developments Inc.
Problem Description ************************************
We are using Stunnel to provide an HTTPS client for use with the UPS ShipXML service. Our application is an xBase++ 1.82 service using the XB2.NET library, running on a windows 2003 server. The application opens a connection to stunnel, which then connects to the UPS https server to send and retrieve an xml response with shipping data. UPS made a change to their service last week related to load balancing and our application has not worked since then. When we send an XML document to UPS we receive the exact same XML document back as if it has been bounced instead of the proper response. Our setup was working until they made the change and they have no idea what is going on.
Stunnel Version *****************************************
The problem initially happened with stunnel v. 4.05 and openSSL v. 0.9.7c. I have also tried it with stunnel v. 4.11 and openSSL v. 0.9.7f and the same result occurs.
Stunnel.conf settings ***********************************
#Stunnel server configuration file key=stunnel.pem
#up this number to 7 to get full log details #leave it at 3 to just get critical error messages debug=7 output=test.log
client=yes verify=0 [psuedo-https] accept = 8080 connect = www.ups.com:443 TIMEOUTclose = 0
Stunnel log samples **************************************
Here are some log samples. The first is a log sample of when it was working. The second is one when it stopped working and the third is from when it was still not working using the latest version of stunnel/openssl.
LOG 1 - Working
2005.05.24 23:37:39 LOG7[184:2796]: psuedo-https accepted FD=216 from 127.0.0.1:3349 2005.05.24 23:37:39 LOG7[184:2796]: FD 216 in non-blocking mode 2005.05.24 23:37:39 LOG7[184:2796]: Creating a new thread 2005.05.24 23:37:39 LOG7[184:2796]: New thread created 2005.05.24 23:37:39 LOG7[184:1840]: psuedo-https started 2005.05.24 23:37:39 LOG5[184:1840]: psuedo-https connected from 127.0.0.1:3349 2005.05.24 23:37:39 LOG7[184:1840]: FD 208 in non-blocking mode 2005.05.24 23:37:39 LOG7[184:1840]: psuedo-https connecting 153.2.228.50:443 2005.05.24 23:37:39 LOG7[184:1840]: remote connect #1: EWOULDBLOCK: retrying 2005.05.24 23:37:39 LOG7[184:1840]: waitforsocket: FD=208, DIR=write 2005.05.24 23:37:39 LOG7[184:1840]: waitforsocket: ok 2005.05.24 23:37:39 LOG7[184:1840]: Remote FD=208 initialized 2005.05.24 23:37:39 LOG7[184:1840]: SSL state (connect): before/connect initialization 2005.05.24 23:37:39 LOG7[184:1840]: SSL state (connect): SSLv3 write client hello A 2005.05.24 23:37:39 LOG7[184:1840]: waitforsocket: FD=208, DIR=read 2005.05.24 23:37:39 LOG7[184:1840]: waitforsocket: ok 2005.05.24 23:37:39 LOG7[184:1840]: SSL state (connect): SSLv3 read server hello A 2005.05.24 23:37:39 LOG5[184:1840]: VERIFY IGNORE: depth=1, /C=US/O=RSA Data Security, Inc./OU=Secure Server Certification Authority 2005.05.24 23:37:39 LOG5[184:1840]: VERIFY IGNORE: depth=1, /C=US/O=RSA Data Security, Inc./OU=Secure Server Certification Authority 2005.05.24 23:37:39 LOG5[184:1840]: VERIFY IGNORE: depth=0, /C=US/ST=New Jersey/L=Mahwah/O=United Parcel Service/OU=Internet Systems/CN=www.ups.com 2005.05.24 23:37:39 LOG7[184:1840]: SSL state (connect): SSLv3 read server certificate A 2005.05.24 23:37:39 LOG7[184:1840]: SSL state (connect): SSLv3 read server done A 2005.05.24 23:37:39 LOG7[184:1840]: SSL state (connect): SSLv3 write client key exchange A 2005.05.24 23:37:39 LOG7[184:1840]: SSL state (connect): SSLv3 write change cipher spec A 2005.05.24 23:37:39 LOG7[184:1840]: SSL state (connect): SSLv3 write finished A 2005.05.24 23:37:39 LOG7[184:1840]: SSL state (connect): SSLv3 flush data 2005.05.24 23:37:39 LOG7[184:1840]: waitforsocket: FD=208, DIR=read 2005.05.24 23:37:39 LOG7[184:1840]: waitforsocket: ok 2005.05.24 23:37:39 LOG7[184:1840]: SSL state (connect): SSLv3 read finished A 2005.05.24 23:37:39 LOG7[184:1840]: 3 items in the session cache 2005.05.24 23:37:39 LOG7[184:1840]: 3 client connects (SSL_connect()) 2005.05.24 23:37:39 LOG7[184:1840]: 3 client connects that finished 2005.05.24 23:37:39 LOG7[184:1840]: 0 client renegotiatations requested 2005.05.24 23:37:39 LOG7[184:1840]: 0 server connects (SSL_accept()) 2005.05.24 23:37:39 LOG7[184:1840]: 0 server connects that finished 2005.05.24 23:37:39 LOG7[184:1840]: 0 server renegotiatiations requested 2005.05.24 23:37:39 LOG7[184:1840]: 0 session cache hits 2005.05.24 23:37:39 LOG7[184:1840]: 0 session cache misses 2005.05.24 23:37:39 LOG7[184:1840]: 0 session cache timeouts 2005.05.24 23:37:39 LOG6[184:1840]: Negotiated ciphers: RC4-SHA SSLv3 Kx=RSA Au=RSA Enc=RC4(128) Mac=SHA1 2005.05.24 23:37:40 LOG7[184:1840]: SSL alert (read): warning: close notify 2005.05.24 23:37:40 LOG7[184:1840]: SSL closed on SSL_read 2005.05.24 23:37:40 LOG7[184:1840]: SSL write shutdown (output buffer empty) 2005.05.24 23:37:40 LOG7[184:1840]: Socket write shutdown (output buffer empty) 2005.05.24 23:37:40 LOG7[184:1840]: SSL alert (write): warning: close notify 2005.05.24 23:37:40 LOG6[184:1840]: SSL_shutdown successfully sent close_notify 2005.05.24 23:37:40 LOG7[184:1840]: Socket closed on read 2005.05.24 23:37:40 LOG5[184:1840]: Connection closed: 726 bytes sent to SSL, 648 bytes sent to socket 2005.05.24 23:37:40 LOG7[184:1840]: psuedo-https finished (0 left)
LOG 2 - NOT WORKING
2005.08.15 15:46:07 LOG7[2636:3432]: psuedo-https accepted FD=180 from 127.0.0.1:3141 2005.08.15 15:46:07 LOG7[2636:3432]: FD 180 in non-blocking mode 2005.08.15 15:46:07 LOG7[2636:3432]: Creating a new thread 2005.08.15 15:46:07 LOG7[2636:3432]: New thread created 2005.08.15 15:46:07 LOG7[2636:1316]: psuedo-https started 2005.08.15 15:46:07 LOG5[2636:1316]: psuedo-https connected from 127.0.0.1:3141 2005.08.15 15:46:07 LOG7[2636:1316]: FD 172 in non-blocking mode 2005.08.15 15:46:07 LOG7[2636:1316]: psuedo-https connecting 65.171.127.243:443 2005.08.15 15:46:07 LOG7[2636:1316]: remote connect #1: EWOULDBLOCK: retrying 2005.08.15 15:46:07 LOG7[2636:1316]: waitforsocket: FD=172, DIR=write 2005.08.15 15:46:07 LOG7[2636:1316]: waitforsocket: ok 2005.08.15 15:46:07 LOG7[2636:1316]: remote connect #2: EINVAL: ok 2005.08.15 15:46:07 LOG7[2636:1316]: Remote FD=172 initialized 2005.08.15 15:46:07 LOG7[2636:1316]: SSL state (connect): before/connect initialization 2005.08.15 15:46:07 LOG7[2636:1316]: SSL state (connect): SSLv3 write client hello A 2005.08.15 15:46:07 LOG7[2636:1316]: waitforsocket: FD=172, DIR=read 2005.08.15 15:46:12 LOG7[2636:1316]: waitforsocket: ok 2005.08.15 15:46:12 LOG7[2636:1316]: SSL state (connect): SSLv3 read server hello A 2005.08.15 15:46:12 LOG7[2636:1316]: SSL state (connect): SSLv3 read finished A 2005.08.15 15:46:12 LOG7[2636:1316]: SSL state (connect): SSLv3 write change cipher spec A 2005.08.15 15:46:12 LOG7[2636:1316]: SSL state (connect): SSLv3 write finished A 2005.08.15 15:46:12 LOG7[2636:1316]: SSL state (connect): SSLv3 flush data 2005.08.15 15:46:12 LOG7[2636:1316]: 17 items in the session cache 2005.08.15 15:46:12 LOG7[2636:1316]: 230 client connects (SSL_connect()) 2005.08.15 15:46:12 LOG7[2636:1316]: 230 client connects that finished 2005.08.15 15:46:12 LOG7[2636:1316]: 0 client renegotiatations requested 2005.08.15 15:46:12 LOG7[2636:1316]: 0 server connects (SSL_accept()) 2005.08.15 15:46:12 LOG7[2636:1316]: 0 server connects that finished 2005.08.15 15:46:12 LOG7[2636:1316]: 0 server renegotiatiations requested 2005.08.15 15:46:12 LOG7[2636:1316]: 213 session cache hits 2005.08.15 15:46:12 LOG7[2636:1316]: 0 session cache misses 2005.08.15 15:46:12 LOG7[2636:1316]: 0 session cache timeouts 2005.08.15 15:46:12 LOG6[2636:1316]: Negotiated ciphers: AES256-SHA SSLv3 Kx=RSA Au=RSA Enc=AES(256) Mac=SHA1 2005.08.15 15:46:14 LOG7[2636:1316]: SSL_read returned WANT_: retrying 2005.08.15 15:46:14 LOG7[2636:1316]: SSL_read returned WANT_: retrying 2005.08.15 15:46:14 LOG7[2636:1316]: SSL alert (read): warning: close notify 2005.08.15 15:46:14 LOG7[2636:1316]: SSL closed on SSL_read 2005.08.15 15:46:14 LOG7[2636:1316]: SSL write shutdown (output buffer empty) 2005.08.15 15:46:14 LOG7[2636:1316]: Socket write shutdown (output buffer empty) 2005.08.15 15:46:14 LOG7[2636:1316]: SSL alert (write): warning: close notify 2005.08.15 15:46:14 LOG6[2636:1316]: SSL_shutdown successfully sent close_notify 2005.08.15 15:46:14 LOG5[2636:1316]: Connection closed: 738 bytes sent to SSL, 5754 bytes sent to socket 2005.08.15 15:46:14 LOG7[2636:1316]: psuedo-https finished (0 left)
LOG 3 - NOT WORKING WITH LATEST VERSION OF STUNNEL/OPENSSL
2005.08.18 20:45:13 LOG7[2212:3324]: psuedo-https accepted FD=164 from 127.0.0.1:1076 2005.08.18 20:45:13 LOG7[2212:3324]: Creating a new thread 2005.08.18 20:45:13 LOG7[2212:3324]: New thread created 2005.08.18 20:45:13 LOG7[2212:3388]: psuedo-https started 2005.08.18 20:45:13 LOG7[2212:3388]: FD 164 in non-blocking mode 2005.08.18 20:45:13 LOG5[2212:3388]: psuedo-https connected from 127.0.0.1:1076 2005.08.18 20:45:13 LOG7[2212:3388]: FD 188 in non-blocking mode 2005.08.18 20:45:13 LOG7[2212:3388]: psuedo-https connecting 153.2.228.50:443 2005.08.18 20:45:13 LOG7[2212:3388]: connect_wait: waiting 10 seconds 2005.08.18 20:45:13 LOG7[2212:3388]: connect_wait: connected 2005.08.18 20:45:13 LOG7[2212:3388]: Remote FD=188 initialized 2005.08.18 20:45:16 LOG5[2212:3388]: VERIFY IGNORE: depth=1, /C=US/O=RSA Data Security, Inc./OU=Secure Server Certification Authority 2005.08.18 20:45:16 LOG5[2212:3388]: VERIFY IGNORE: depth=1, /C=US/O=RSA Data Security, Inc./OU=Secure Server Certification Authority 2005.08.18 20:45:16 LOG5[2212:3388]: VERIFY IGNORE: depth=0, /C=US/ST=New Jersey/L=Mahwah/O=United Parcel Service/OU=Internet System/OU=Terms of use at www.verisign.com/rpa (c)05/CN=www.ups.com 2005.08.18 20:45:17 LOG6[2212:3388]: SSL connected: new session negotiated 2005.08.18 20:45:17 LOG6[2212:3388]: Negotiated ciphers: RC4-SHA SSLv3 Kx=RSA Au=RSA Enc=RC4(128) Mac=SHA1 2005.08.18 20:45:20 LOG7[2212:3388]: SSL_read returned WANT_READ: retrying 2005.08.18 20:45:20 LOG7[2212:3388]: SSL_read returned WANT_READ: retrying 2005.08.18 20:45:20 LOG7[2212:3388]: SSL closed on SSL_read 2005.08.18 20:45:20 LOG7[2212:3388]: Socket write shutdown 2005.08.18 20:45:20 LOG7[2212:3388]: SSL write shutdown 2005.08.18 20:45:20 LOG6[2212:3388]: SSL_shutdown successfully sent close_notify 2005.08.18 20:45:20 LOG5[2212:3388]: Connection closed: 738 bytes sent to SSL, 8248 bytes sent to socket 2005.08.18 20:45:20 LOG7[2212:3388]: psuedo-https finished (0 left)
Output of stunnel.exe -version *************************************
stunnel 4.11 on x86-pc-mingw32-gnu WIN32+IPv6 with OpenSSL 0.9.7f 22 Mar 2005
Global options cert = stunnel.pem ciphers = ALL:!ADH:+RC4:@STRENGTH debug = 5 key = stunnel.pem RNDbytes = 64 RNDoverwrite = yes service = stunnel session = 300 seconds taskbar = yes verify = none
Service-level options TIMEOUTbusy = 300 seconds TIMEOUTclose = 60 seconds TIMEOUTconnect = 10 seconds TIMEOUTidle = 43200 seconds
2005.08.18 21:06:04 LOG3[2508:3100]: Server is down