[stunnel-users] Stunnel HTTPS Client Issue

Salar Madadi smadadi at latestdevelopments.ca
Fri Aug 19 03:15:04 CEST 2005


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







More information about the stunnel-users mailing list