Re-negotiation handshake failed
am 19.08.2002 06:54:28 von Jules Butcher
Hi All, I have recently upgraded our web server from NT/IIS to
FreeBSD/Apache/ModSSL. Everything is pretty sweet, execpt for one
application. The application (MessagingGW) is written in java using jsse
for the ssl stuff. The app periodically posts base64 encoded data to a
java servlet using http over ssl. MessagingGW seems to work fine when
the payload data is small, but over a certain size (a few kB) it bombs
out.
In this configuration I have Apache handling the SSL handshake, then
passing the request to tomcat via ajp13. Servlets generally seem to be
working fine over https, but in this case the servlet never receives the
request, which makes me think that the problem is between apache and the
client app.
If anyone has any clue about this, I would be very happy to hear from
you.
Server Software:
Apache 1.3.26
mod_ssl 2.8.10-1.3.26
Tomcat 3.3.1
Client Software:
Custom app (jdk1.3.1, jsse 1.0.2)
Below is the ssl_log file from the apache ssl log(I have replaced IP
addresses with [src-IP] and [dest-IP] below for my clients privacy):
[19/Aug/2002 13:04:35 98058] [info] Connection to child 5 established
(server [dest-IP]:443, client [src-IP])
[19/Aug/2002 13:04:35 98058] [info] Seeding PRNG with 0 bytes of
entropy
[19/Aug/2002 13:04:35 98058] [trace] OpenSSL: Handshake: start
[19/Aug/2002 13:04:35 98058] [trace] OpenSSL: Loop: before/accept
initialization
[19/Aug/2002 13:04:35 98058] [trace] OpenSSL: Loop: SSLv3 read client
hello A
[19/Aug/2002 13:04:35 98058] [trace] OpenSSL: Loop: SSLv3 write server
hello A
[19/Aug/2002 13:04:35 98058] [trace] OpenSSL: Loop: SSLv3 write
certificate A
[19/Aug/2002 13:04:35 98058] [trace] OpenSSL: Loop: SSLv3 write server
done A
[19/Aug/2002 13:04:35 98058] [trace] OpenSSL: Loop: SSLv3 flush data
[19/Aug/2002 13:04:37 98058] [trace] OpenSSL: Loop: SSLv3 read client
key exchange A
[19/Aug/2002 13:04:39 98058] [trace] OpenSSL: Loop: SSLv3 read finished
A
[19/Aug/2002 13:04:39 98058] [trace] OpenSSL: Loop: SSLv3 write change
cipher spec A
[19/Aug/2002 13:04:39 98058] [trace] OpenSSL: Loop: SSLv3 write finished
A
[19/Aug/2002 13:04:39 98058] [trace] OpenSSL: Loop: SSLv3 flush data
[19/Aug/2002 13:04:39 98058] [trace] Inter-Process Session Cache (DBM)
Expiry: old: 10, new: 6, removed: 4
[19/Aug/2002 13:04:39 98058] [trace] Inter-Process Session Cache:
request=SET status=OK
id=41131C9DCE1B61E17AF7997E89F58139BC5164A05AA734A9A70A39B06 5725CE0
timeout=596s (session caching)
[19/Aug/2002 13:04:39 98058] [trace] OpenSSL: Handshake: done
[19/Aug/2002 13:04:39 98058] [info] Connection: Client IP: [src-IP],
Protocol: TLSv1, Cipher: RC4-SHA (128/128 bits)
[19/Aug/2002 13:04:41 98058] [info] Initial (No.1) HTTPS request
received for child 5 (server [dest-IP]:443)
[19/Aug/2002 13:04:41 98058] [trace] Changed client verification type
will force renegotiation
[19/Aug/2002 13:04:41 98058] [info] Requesting connection
re-negotiation
[19/Aug/2002 13:04:41 98058] [trace] Performing full renegotiation:
complete handshake protocol
[19/Aug/2002 13:04:41 98058] [trace] I/O: sucked 12556 bytes of input
data from SSL/TLS I/O layer for delayed injection into Apache I/O layer
[19/Aug/2002 13:04:41 98058] [trace] OpenSSL: Handshake: start
[19/Aug/2002 13:04:41 98058] [trace] OpenSSL: Loop: SSL renegotiate
ciphers
[19/Aug/2002 13:04:41 98058] [trace] OpenSSL: Loop: SSLv3 write hello
request A
[19/Aug/2002 13:04:41 98058] [trace] OpenSSL: Loop: SSLv3 flush data
[19/Aug/2002 13:04:41 98058] [trace] OpenSSL: Loop: SSLv3 write hello
request C
[19/Aug/2002 13:04:41 98058] [info] Awaiting re-negotiation handshake
[19/Aug/2002 13:04:41 98058] [trace] OpenSSL: Handshake: start
[19/Aug/2002 13:04:41 98058] [trace] OpenSSL: Loop: before accept
initialization
[19/Aug/2002 13:04:41 98058] [trace] Inter-Process Session Cache:
request=REM status=OK
id=41131C9DCE1B61E17AF7997E89F58139BC5164A05AA734A9A70A39B06 5725CE0
(session dead)
[19/Aug/2002 13:04:41 98058] [trace] OpenSSL: Write: SSLv3 read client
hello B
[19/Aug/2002 13:04:41 98058] [trace] OpenSSL: Exit: error in SSLv3 read
client hello B
[19/Aug/2002 13:04:41 98058] [error] Re-negotiation handshake failed:
Not accepted by client!?
[19/Aug/2002 13:04:41 98058] [trace] I/O: injecting 8192 bytes of
pre-sucked data into Apache I/O layer
[19/Aug/2002 13:04:41 98058] [trace] I/O: injecting 4364 bytes of
pre-sucked data into Apache I/O layer
[19/Aug/2002 13:04:41 98058] [trace] OpenSSL: Write: SSLv3 read client
hello B
[19/Aug/2002 13:04:41 98058] [trace] OpenSSL: Exit: error in SSLv3 read
client hello B
[19/Aug/2002 13:04:41 98058] [error] SSL error on writing data (OpenSSL
library error follows)
[19/Aug/2002 13:04:41 98058] [error] OpenSSL: error:140940F5:SSL
routines:SSL3_READ_BYTES:unexpected record
[19/Aug/2002 13:04:41 98058] [info] Connection to child 5 closed with
standard shutdown (server [dest-IP]:443, client [src-IP])
Regards, Jules Butcher
------------------------------------------------------
Software Developer
Strategic Ecommerce Ltd.
____________________________________________________________ __________
Apache Interface to OpenSSL (mod_ssl) www.modssl.org
User Support Mailing List modssl-users@modssl.org
Automated List Manager majordomo@modssl.org
RE: Re-negotiation handshake failed (still trying)
am 22.08.2002 07:37:40 von Jules Butcher
OK I still havent received any replies about this problem, and I still
haven't managed to solve it by myself. One thing I want to add, is that
I think I have eliminated my java client application as the source of
the problem. I tried accessing my server using openssl s_client instead
of my java app. This is the command I used:
cat postrequest | openssl s_client -connect my.secureserver.com:443
-state
Where postrequest is a textfile which contains:
POST
/MessagingGateway/servlet/com.StrategicEcommerce.StraightSel l.MessagingG
ateway.ReceiveOBIOrder HTTP/1.0
Content-Length: 12577
Content-type: application/x-obi-order
Content-transfer-encoding: base64
AgAAAAAAJLxJU0EdMDAdICAgICAgICAgIB0wMB0gICAgICAgICAgHVpaHTY4 Mzk5MDkwODk0
ICAgIB1aWh03NjQ5Mzg1MTI0OCAgICAdMDIwODIxHTEzMTcdVR0w... (content
truncated for mailing list post)
When I do the above I get the same errors in my apache ssl_log as with
my java app (see my parent post). Judging by the log messages would
people say that this is a mod_ssl configuration issue or a certificate
issue? It seems something may be timing out since it works fine for post
data of size less than a few K, but I don't know what it could be.
-----Original Message-----
From: owner-modssl-users@modssl.org
[mailto:owner-modssl-users@modssl.org] On Behalf Of Jules Butcher
Sent: Monday, 19 August 2002 2:24 PM
To: modssl-users@modssl.org
Subject: Re-negotiation handshake failed
Hi All, I have recently upgraded our web server from NT/IIS to
FreeBSD/Apache/ModSSL. Everything is pretty sweet, execpt for one
application. The application (MessagingGW) is written in java using jsse
for the ssl stuff. The app periodically posts base64 encoded data to a
java servlet using http over ssl. MessagingGW seems to work fine when
the payload data is small, but over a certain size (a few kB) it bombs
out.
In this configuration I have Apache handling the SSL handshake, then
passing the request to tomcat via ajp13. Servlets generally seem to be
working fine over https, but in this case the servlet never receives the
request, which makes me think that the problem is between apache and the
client app.
If anyone has any clue about this, I would be very happy to hear from
you.
Server Software:
Apache 1.3.26
mod_ssl 2.8.10-1.3.26
Tomcat 3.3.1
Client Software:
Custom app (jdk1.3.1, jsse 1.0.2)
Below is the ssl_log file from the apache ssl log(I have replaced IP
addresses with [src-IP] and [dest-IP] below for my clients privacy):
[19/Aug/2002 13:04:35 98058] [info] Connection to child 5 established
(server [dest-IP]:443, client [src-IP])
[19/Aug/2002 13:04:35 98058] [info] Seeding PRNG with 0 bytes of
entropy
[19/Aug/2002 13:04:35 98058] [trace] OpenSSL: Handshake: start
[19/Aug/2002 13:04:35 98058] [trace] OpenSSL: Loop: before/accept
initialization
[19/Aug/2002 13:04:35 98058] [trace] OpenSSL: Loop: SSLv3 read client
hello A
[19/Aug/2002 13:04:35 98058] [trace] OpenSSL: Loop: SSLv3 write server
hello A
[19/Aug/2002 13:04:35 98058] [trace] OpenSSL: Loop: SSLv3 write
certificate A
[19/Aug/2002 13:04:35 98058] [trace] OpenSSL: Loop: SSLv3 write server
done A
[19/Aug/2002 13:04:35 98058] [trace] OpenSSL: Loop: SSLv3 flush data
[19/Aug/2002 13:04:37 98058] [trace] OpenSSL: Loop: SSLv3 read client
key exchange A
[19/Aug/2002 13:04:39 98058] [trace] OpenSSL: Loop: SSLv3 read finished
A
[19/Aug/2002 13:04:39 98058] [trace] OpenSSL: Loop: SSLv3 write change
cipher spec A
[19/Aug/2002 13:04:39 98058] [trace] OpenSSL: Loop: SSLv3 write finished
A
[19/Aug/2002 13:04:39 98058] [trace] OpenSSL: Loop: SSLv3 flush data
[19/Aug/2002 13:04:39 98058] [trace] Inter-Process Session Cache (DBM)
Expiry: old: 10, new: 6, removed: 4
[19/Aug/2002 13:04:39 98058] [trace] Inter-Process Session Cache:
request=SET status=OK
id=41131C9DCE1B61E17AF7997E89F58139BC5164A05AA734A9A70A39B06 5725CE0
timeout=596s (session caching)
[19/Aug/2002 13:04:39 98058] [trace] OpenSSL: Handshake: done
[19/Aug/2002 13:04:39 98058] [info] Connection: Client IP: [src-IP],
Protocol: TLSv1, Cipher: RC4-SHA (128/128 bits)
[19/Aug/2002 13:04:41 98058] [info] Initial (No.1) HTTPS request
received for child 5 (server [dest-IP]:443)
[19/Aug/2002 13:04:41 98058] [trace] Changed client verification type
will force renegotiation
[19/Aug/2002 13:04:41 98058] [info] Requesting connection
re-negotiation
[19/Aug/2002 13:04:41 98058] [trace] Performing full renegotiation:
complete handshake protocol
[19/Aug/2002 13:04:41 98058] [trace] I/O: sucked 12556 bytes of input
data from SSL/TLS I/O layer for delayed injection into Apache I/O layer
[19/Aug/2002 13:04:41 98058] [trace] OpenSSL: Handshake: start
[19/Aug/2002 13:04:41 98058] [trace] OpenSSL: Loop: SSL renegotiate
ciphers
[19/Aug/2002 13:04:41 98058] [trace] OpenSSL: Loop: SSLv3 write hello
request A
[19/Aug/2002 13:04:41 98058] [trace] OpenSSL: Loop: SSLv3 flush data
[19/Aug/2002 13:04:41 98058] [trace] OpenSSL: Loop: SSLv3 write hello
request C
[19/Aug/2002 13:04:41 98058] [info] Awaiting re-negotiation handshake
[19/Aug/2002 13:04:41 98058] [trace] OpenSSL: Handshake: start
[19/Aug/2002 13:04:41 98058] [trace] OpenSSL: Loop: before accept
initialization
[19/Aug/2002 13:04:41 98058] [trace] Inter-Process Session Cache:
request=REM status=OK
id=41131C9DCE1B61E17AF7997E89F58139BC5164A05AA734A9A70A39B06 5725CE0
(session dead)
[19/Aug/2002 13:04:41 98058] [trace] OpenSSL: Write: SSLv3 read client
hello B
[19/Aug/2002 13:04:41 98058] [trace] OpenSSL: Exit: error in SSLv3 read
client hello B
[19/Aug/2002 13:04:41 98058] [error] Re-negotiation handshake failed:
Not accepted by client!?
[19/Aug/2002 13:04:41 98058] [trace] I/O: injecting 8192 bytes of
pre-sucked data into Apache I/O layer
[19/Aug/2002 13:04:41 98058] [trace] I/O: injecting 4364 bytes of
pre-sucked data into Apache I/O layer
[19/Aug/2002 13:04:41 98058] [trace] OpenSSL: Write: SSLv3 read client
hello B
[19/Aug/2002 13:04:41 98058] [trace] OpenSSL: Exit: error in SSLv3 read
client hello B
[19/Aug/2002 13:04:41 98058] [error] SSL error on writing data (OpenSSL
library error follows)
[19/Aug/2002 13:04:41 98058] [error] OpenSSL: error:140940F5:SSL
routines:SSL3_READ_BYTES:unexpected record
[19/Aug/2002 13:04:41 98058] [info] Connection to child 5 closed with
standard shutdown (server [dest-IP]:443, client [src-IP])
Regards, Jules Butcher
------------------------------------------------------
Software Developer
Strategic Ecommerce Ltd.
____________________________________________________________ __________
Apache Interface to OpenSSL (mod_ssl) www.modssl.org
User Support Mailing List modssl-users@modssl.org
Automated List Manager majordomo@modssl.org
____________________________________________________________ __________
Apache Interface to OpenSSL (mod_ssl) www.modssl.org
User Support Mailing List modssl-users@modssl.org
Automated List Manager majordomo@modssl.org