You are viewing a plain text version of this content. The canonical link for it is here.
Posted to user@synapse.apache.org by J Bouck <bo...@gmail.com> on 2008/03/12 21:42:21 UTC
Using SSL between Apache proxy and Synapse causes consistent 10 second delay in SSL handshake
I am looking for some ideas at what might be causing a problem. I am
using Synapse 1.1.1 on HP-UX 11.23 with JDK1.6.
I am trying to configure an Apache 2.0 web server to sit in front of
Synapse (ProxyPass and ProxyPassReverse). Mod_proxy to proxy requests
to synapse. Mod_ssl to secure the apache->synapse communication.
There are 2 proxy services defined in synapse. One for http and one
for https, but they are both proxying the sample stock quote service
from the synapse samples. I use SOAPUI to send SOAP requests to
apache which proxies them to the http or https synapse port. Synapse
works for either http or https, with or without the apache proxy.
It's just when SSL is used between apache and synapse that there is
some sort of 10 second SSL handshake delay. I have also configured
the apache to proxy to other servers with self-signed certificates and
there is no delay. It seems to be related to the SSL implementation
in the Axis2, but I am not sure.
I see that when I secure the apache to synapse connection with ssl I
get about 10 seconds of errors (about 2 per second) in the synapse log
that indicate that the ssl is not handshaking quickly and causing a
delay:
Synapse log:
2008-03-12 13:25:06,072 [xx.x.x.xx-xxxxxxx] [I/O dispatcher 7] TRACE
ServerHandler New incoming connection
2008-03-12 13:25:06,093 [xx.x.x.xx-xxxxxxx] [I/O dispatcher 7] DEBUG
SSLIOSession I/O session 19 [interested ops: [rw]; ready ops: [w]][SSL
handshake status: NOT_HANDSHAKING][0][0][53][0]: Clear event [w]
2008-03-12 13:25:06,093 [xx.x.x.xx-xxxxxxx] [I/O dispatcher 7] DEBUG
ServerHandler HTTP connection [localhost/127.0.0.1:63557]: Response
ready
2008-03-12 13:25:06,094 [xx.x.x.xx-xxxxxxx] [I/O dispatcher 7] DEBUG
SSLIOSession I/O session 19 [interested ops: [r]; ready ops: [r]][SSL
handshake status: NOT_HANDSHAKING][1490][0][0][0]: 39 bytes read
2008-03-12 13:25:06,094 [xx.x.x.xx-xxxxxxx] [I/O dispatcher 7] DEBUG
SSLIOSession I/O session 19 [interested ops: [r]; ready ops: [r]][SSL
handshake status: NOT_HANDSHAKING][1490][0][0][0]: 0 bytes read
2008-03-12 13:25:06,094 [xx.x.x.xx-xxxxxxx] [I/O dispatcher 7] DEBUG
SSLIOSession I/O session 19 [interested ops: [r]; ready ops: [r]][SSL
handshake status: NOT_HANDSHAKING][1421][0][0][0]: 35 bytes read
2008-03-12 13:25:06,094 [xx.x.x.xx-xxxxxxx] [I/O dispatcher 7] DEBUG
SSLIOSession I/O session 19 [interested ops: [r]; ready ops: [r]][SSL
handshake status: NOT_HANDSHAKING][1421][0][0][0]: 0 bytes read
2008-03-12 13:25:07,091 [xx.x.x.xx-xxxxxxx] [I/O dispatcher 7] DEBUG
SSLIOSession I/O session 19 [interested ops: [r]; ready ops: [r]][SSL
handshake status: NOT_HANDSHAKING][1320][0][0][0]: 72 bytes read
2008-03-12 13:25:07,091 [xx.x.x.xx-xxxxxxx] [I/O dispatcher 7] DEBUG
SSLIOSession I/O session 19 [interested ops: [r]; ready ops: [r]][SSL
handshake status: NOT_HANDSHAKING][1320][0][0][0]: 0 bytes read
2008-03-12 13:25:08,091 [xx.x.x.xx-xxxxxxx] [I/O dispatcher 7] DEBUG
SSLIOSession I/O session 19 [interested ops: [r]; ready ops: [r]][SSL
handshake status: NOT_HANDSHAKING][1235][0][0][0]: 46 bytes read
2008-03-12 13:25:08,091 [xx.x.x.xx-xxxxxxx] [I/O dispatcher 7] DEBUG
SSLIOSession I/O session 19 [interested ops: [r]; ready ops: [r]][SSL
handshake status: NOT_HANDSHAKING][1235][0][0][0]: 0 bytes read
2008-03-12 13:25:09,091 [xx.x.x.xx-xxxxxxx] [I/O dispatcher 7] DEBUG
SSLIOSession I/O session 19 [interested ops: [r]; ready ops: [r]][SSL
handshake status: NOT_HANDSHAKING][1182][0][0][0]: 18 bytes read
2008-03-12 13:25:09,091 [xx.x.x.xx-xxxxxxx] [I/O dispatcher 7] DEBUG
SSLIOSession I/O session 19 [interested ops: [r]; ready ops: [r]][SSL
handshake status: NOT_HANDSHAKING][1182][0][0][0]: 0 bytes read
2008-03-12 13:25:10,091 [xx.x.x.xx-xxxxxxx] [I/O dispatcher 7] DEBUG
SSLIOSession I/O session 19 [interested ops: [r]; ready ops: [r]][SSL
handshake status: NOT_HANDSHAKING][1113][0][0][0]: 31 bytes read
2008-03-12 13:25:10,091 [xx.x.x.xx-xxxxxxx] [I/O dispatcher 7] DEBUG
SSLIOSession I/O session 19 [interested ops: [r]; ready ops: [r]][SSL
handshake status: NOT_HANDSHAKING][1113][0][0][0]: 0 bytes read
2008-03-12 13:25:11,091 [xx.x.x.xx-xxxxxxx] [I/O dispatcher 7] DEBUG
SSLIOSession I/O session 19 [interested ops: [r]; ready ops: [r]][SSL
handshake status: NOT_HANDSHAKING][1028][0][0][0]: 47 bytes read
2008-03-12 13:25:11,091 [xx.x.x.xx-xxxxxxx] [I/O dispatcher 7] DEBUG
SSLIOSession I/O session 19 [interested ops: [r]; ready ops: [r]][SSL
handshake status: NOT_HANDSHAKING][1028][0][0][0]: 0 bytes read
2008-03-12 13:25:12,091 [xx.x.x.xx-xxxxxxx] [I/O dispatcher 7] DEBUG
SSLIOSession I/O session 19 [interested ops: [r]; ready ops: [r]][SSL
handshake status: NOT_HANDSHAKING][943][0][0][0]: 49 bytes read
2008-03-12 13:25:12,091 [xx.x.x.xx-xxxxxxx] [I/O dispatcher 7] DEBUG
SSLIOSession I/O session 19 [interested ops: [r]; ready ops: [r]][SSL
handshake status: NOT_HANDSHAKING][943][0][0][0]: 0 bytes read
2008-03-12 13:25:13,091 [xx.x.x.xx-xxxxxxx] [I/O dispatcher 7] DEBUG
SSLIOSession I/O session 19 [interested ops: [r]; ready ops: [r]][SSL
handshake status: NOT_HANDSHAKING][890][0][0][0]: 21 bytes read
2008-03-12 13:25:13,091 [xx.x.x.xx-xxxxxxx] [I/O dispatcher 7] DEBUG
SSLIOSession I/O session 19 [interested ops: [r]; ready ops: [r]][SSL
handshake status: NOT_HANDSHAKING][890][0][0][0]: 0 bytes read
2008-03-12 13:25:14,091 [xx.x.x.xx-xxxxxxx] [I/O dispatcher 7] DEBUG
SSLIOSession I/O session 19 [interested ops: [r]; ready ops: [r]][SSL
handshake status: NOT_HANDSHAKING][853][0][0][0]: 2 bytes read
2008-03-12 13:25:14,091 [xx.x.x.xx-xxxxxxx] [I/O dispatcher 7] DEBUG
ServerHandler HTTP connection [localhost/127.0.0.1:63557]: POST
/soap/StockQuoteComplex HTTP/1.1
2008-03-12 13:25:14,092 [xx.x.x.xx-xxxxxxx] [I/O dispatcher 7] DEBUG
headers >> POST /soap/StockQuoteComplex HTTP/1.1
Apache log:
[Wed Mar 12 13:25:06 2008] [debug] ssl_engine_kernel.c(1835): OpenSSL:
Loop: SSLv3 read finished A
[Wed Mar 12 13:25:06 2008] [debug] ssl_engine_kernel.c(1831): OpenSSL:
Handshake: done
[Wed Mar 12 13:25:06 2008] [info] Connection: Client IP: 127.0.0.1,
Protocol: TLSv1, Cipher: DHE-RSA-AES256-SHA (256/256 bits)
[Wed Mar 12 13:25:10 2008] [info] Connection to child 4 established
(server xx.x.x.xxx:443, client xx.x.x.xxx)
[Wed Mar 12 13:25:10 2008] [info] Seeding PRNG with 144 bytes of entropy
[Wed Mar 12 13:25:10 2008] [debug] ssl_engine_kernel.c(1827): OpenSSL:
Handshake: start
[Wed Mar 12 13:25:10 2008] [debug] ssl_engine_kernel.c(1835): OpenSSL:
Loop: before/accept initialization
[Wed Mar 12 13:25:10 2008] [debug] ssl_engine_io.c(1703): OpenSSL: I/O
error, 11 bytes expected to read on BIO#600000000049d020 [mem:
6000000000580020]
[Wed Mar 12 13:25:10 2008] [debug] ssl_engine_kernel.c(1864): OpenSSL:
Exit: error in SSLv2/v3 read client hello A
[Wed Mar 12 13:25:10 2008] [info] (232)Connection reset by peer: SSL
handshake interrupted by system [Hint: Stop button pressed in
browser?!]
[Wed Mar 12 13:25:10 2008] [info] Connection to child 4 closed with
abortive shutdown(server xx.x.x.xxx:443, client xx.x.x.xxx)
[Wed Mar 12 13:25:15 2008] [info] Connection to child 73 established
(server xx.x.x.xxx:443, client xx.x.x.xxx)
[Wed Mar 12 13:25:15 2008] [info] Seeding PRNG with 144 bytes of entropy
[Wed Mar 12 13:25:15 2008] [debug] ssl_engine_kernel.c(1827): OpenSSL:
Handshake: start
[Wed Mar 12 13:25:15 2008] [debug] ssl_engine_kernel.c(1835): OpenSSL:
Loop: before/accept initialization
[Wed Mar 12 13:25:15 2008] [debug] ssl_engine_io.c(1703): OpenSSL: I/O
error, 11 bytes expected to read on BIO#6000000000628aa0 [mem:
60000000006a0020]
[Wed Mar 12 13:25:15 2008] [debug] ssl_engine_kernel.c(1864): OpenSSL:
Exit: error in SSLv2/v3 read client hello A
[Wed Mar 12 13:25:15 2008] [info] (232)Connection reset by peer: SSL
handshake interrupted by system [Hint: Stop button pressed in
browser?!]
[Wed Mar 12 13:25:15 2008] [info] Connection to child 73 closed with
abortive shutdown(server xx.x.x.xxx:443, client xx.x.x.xxx)
[Wed Mar 12 13:25:19 2008] [debug] ssl_engine_io.c(1692): OpenSSL:
read 5/5 bytes from BIO#600000000045d140 [mem: 6000000000655c80] (BIO
dump follows)
Any ideas what is causing the SSL delay for synapse? I can confirm
that apache likes the synapse certificate cipher, that openssl
supports the cipher, and that apache accepts the certificate. I am
not sure what else I can look at.
~john
RE: Using SSL between Apache proxy and Synapse causes consistent 10 second delay in SSL handshake
Posted by Kim Horn <ki...@icsglobal.net>.
We use 1.2. I will try trunk
Thanks so much
Kim
-----Original Message-----
From: Asankha Perera [mailto:asankha.apache@gmail.com] On Behalf Of
Asankha C. Perera
Sent: Thursday, 12 March 2009 9:51 PM
To: user@synapse.apache.org
Subject: Re: Using SSL between Apache proxy and Synapse causes
consistent 10 second delay in SSL handshake
Hi Kim
Can you tell me if you are seeing this with Synapse 1.2 or with a
nightly build off the trunk? I remember fixing this or a similar issue
around September '08
Also, if you can get the logs with the system property
-Djavax.net/debug=all set, send it to me privately for a full analysis.
Please always be careful when posting logs publicly
cheers
asankha
--
Asankha C. Perera
AdroitLogic, http://adroitlogic.org
http://esbmagic.blogspot.com
Re: Using SSL between Apache proxy and Synapse causes consistent
10 second delay in SSL handshake
Posted by "Asankha C. Perera" <as...@apache.org>.
Hi Kim
Can you tell me if you are seeing this with Synapse 1.2 or with a
nightly build off the trunk? I remember fixing this or a similar issue
around September '08
Also, if you can get the logs with the system property
-Djavax.net/debug=all set, send it to me privately for a full analysis.
Please always be careful when posting logs publicly
cheers
asankha
--
Asankha C. Perera
AdroitLogic, http://adroitlogic.org
http://esbmagic.blogspot.com
RE: Using SSL between Apache proxy and Synapse causes consistent 10 second delay in SSL handshake
Posted by Kim Horn <ki...@icsglobal.net>.
I do not think this is the issue, this would just slow things down. The
Problem we have is that the calls never return. Our apps do not
need reverse look up, so we are getting this set up to see if it an
issue for
Synapse.
Thanks
Kim
-----Original Message-----
From: Asankha Perera [mailto:asankha.apache@gmail.com] On Behalf Of
Asankha C. Perera
Sent: Thursday, 12 March 2009 9:59 PM
To: user@synapse.apache.org
Subject: Re: Using SSL between Apache proxy and Synapse causes
consistent 10 second delay in SSL handshake
Hi Kim
Check if reverse DNS lookups are the same for both production and
stating/integration. The 10 second delays are usually caused by reverse
lookups when accepting connections, since we try to get the hostname for
logging.
Also, is your backend hosted on Weblogic servers by any chance?
cheers
asankha
--
Asankha C. Perera
AdroitLogic, http://adroitlogic.org
http://esbmagic.blogspot.com
Re: Using SSL between Apache proxy and Synapse causes consistent
10 second delay in SSL handshake
Posted by "Asankha C. Perera" <as...@apache.org>.
Hi Kim
> Despite hitting the destination. Connection is closed on the response.
> So watching the logs they don't get back even 30 minutes later....
>
Ah.. I was so sure I fixed this sometime towards the end of last year
like I said :-) , but forgot exactly when and under which JIRA.. This
seems most definitely like http://issues.apache.org/jira/browse/SYNAPSE-462
For your successful case, the logs shows:
2009-03-12 13:03:41,934 [192.168.0.204-icsws-kh] [I/O dispatcher 1]
DEBUG headers << HTTP/1.1 200 OK
2009-03-12 13:03:41,934 [192.168.0.204-icsws-kh] [I/O dispatcher 1]
DEBUG headers << Date: Thu, 12 Mar 2009 02:04:10 GMT
2009-03-12 13:03:41,934 [192.168.0.204-icsws-kh] [I/O dispatcher 1]
DEBUG headers << Content-Type: text/xml;charset=UTF-8
2009-03-12 13:03:41,934 [192.168.0.204-icsws-kh] [I/O dispatcher 1]
DEBUG headers << Keep-Alive: timeout=15, max=100
2009-03-12 13:03:41,934 [192.168.0.204-icsws-kh] [I/O dispatcher 1]
DEBUG headers << Connection: Keep-Alive
2009-03-12 13:03:41,934 [192.168.0.204-icsws-kh] [I/O dispatcher 1]
DEBUG headers << Transfer-Encoding: chunked
And for the failure case:
2009-03-12 12:16:53,798 [192.168.16.133-icslt-dr2] [I/O dispatcher 1]
DEBUG headers << HTTP/1.1 200 OK
2009-03-12 12:16:53,798 [192.168.16.133-icslt-dr2] [I/O dispatcher 1]
DEBUG headers << Date: Thu, 12 Mar 2009 01:17:12 GMT
2009-03-12 12:16:53,798 [192.168.16.133-icslt-dr2] [I/O dispatcher 1]
DEBUG headers << Content-Type: text/xml;charset=UTF-8
2009-03-12 12:16:53,798 [192.168.16.133-icslt-dr2] [I/O dispatcher 1]
DEBUG headers << Connection: close
2009-03-12 12:16:53,798 [192.168.16.133-icslt-dr2] [I/O dispatcher 1]
DEBUG headers << Transfer-Encoding: chunked
Note that the connection close event was incorrectly processed with
Synapse 1.2, and was later fixed to read in whats already in the buffers
(in this case you seem to have data in the buffers too)
Please try the latest nightly from
http://hudson.zones.apache.org/hudson/job/Synapse - Trunk/lastStableBuild/
cheers
asankha
--
Asankha C. Perera
AdroitLogic, http://adroitlogic.org
http://esbmagic.blogspot.com
Re: Using SSL between Apache proxy and Synapse causes consistent
10 second delay in SSL handshake
Posted by "Asankha C. Perera" <as...@apache.org>.
Hi Kim
> Despite hitting the destination. Connection is closed on the response.
> So watching the logs they don't get back even 30 minutes later....
>
This was due to HTTPCORE-193. I will include the binary patch for this
into Synapse, until such time we switch over to HttpCore 4.1
cheers
asankha
--
Asankha C. Perera
AdroitLogic, http://adroitlogic.org
http://esbmagic.blogspot.com
RE: Using SSL between Apache proxy and Synapse causes consistent 10 second delay in SSL handshake
Posted by Kim Horn <ki...@icsglobal.net>.
We use Apache/Tomcat ... Everything we use is Open Source, no products
here.
We got the reverse lookup configured and no difference.
So Note that the issue is not the delay but the requests never, ever
complete;
Despite hitting the destination. Connection is closed on the response.
So watching the logs they don't get back even 30 minutes later....
Thanks
Kim
-----Original Message-----
From: Asankha Perera [mailto:asankha.apache@gmail.com] On Behalf Of
Asankha C. Perera
Sent: Thursday, 12 March 2009 9:59 PM
To: user@synapse.apache.org
Subject: Re: Using SSL between Apache proxy and Synapse causes
consistent 10 second delay in SSL handshake
Hi Kim
Check if reverse DNS lookups are the same for both production and
stating/integration. The 10 second delays are usually caused by reverse
lookups when accepting connections, since we try to get the hostname for
logging.
Also, is your backend hosted on Weblogic servers by any chance?
cheers
asankha
--
Asankha C. Perera
AdroitLogic, http://adroitlogic.org
http://esbmagic.blogspot.com
Re: Using SSL between Apache proxy and Synapse causes consistent
10 second delay in SSL handshake
Posted by "Asankha C. Perera" <as...@apache.org>.
Hi Kim
Check if reverse DNS lookups are the same for both production and
stating/integration. The 10 second delays are usually caused by reverse
lookups when accepting connections, since we try to get the hostname for
logging.
Also, is your backend hosted on Weblogic servers by any chance?
cheers
asankha
--
Asankha C. Perera
AdroitLogic, http://adroitlogic.org
http://esbmagic.blogspot.com
Re: Using SSL between Apache proxy and Synapse causes consistent 10
second delay in SSL handshake
Posted by kimhorn <ki...@icsglobal.net>.
Hello Asanka,
Just wondering if anyone can offer next step suggestions. We will look at
turning on more debugging.
We have a script that runs perfectly against our Integration, web services,
it uses Basic Authentication and HTTPS with self signed certs. We changed
the script to point to our Production web services, these use Verisign
certs, these are chained.
The machine running the Synapse has not changed, we only changed the URLS
and certs in the Identity JKS.
We can see Synapse hit our production Web Service, these are hosted on
Tomcat, running with XFire, Its runs the service, produces a responce, but
this never gets back to Synapse, see connection closed in logs.
I have included some segments of the logs as a starter. I have run the
script pointing to Integration where it works, then at Production where is
fails. The exerts show the difference. I do not believe it is a certificate
problem as the destination Web Service processes the request.
Not really sure where to go next... Unfortunatley we are now limited on
running this on production anymore.
We will see if we can duplicate in Staging. Unfortunatley it runs perfectly
when hitting integration.
Thanks
Kim
http://www.nabble.com/file/p22470471/lognotes.txt lognotes.txt
kimhorn wrote:
>
> Hello Asanka,
>
> just so you know we are getting a similar problem and spent last 8 hours
> trying to work it out. We get multiple NOT_HANDSHAKING issues after a Web
> Service succesfully processes the request (looking at the service server
> logs) but the responce never gets back to Synapse. This only happens on
> our production and staging systems. The Script works fine on Integration.
> We cannot find any differences ? Due to the proxy issue (previous post) we
> had to deploy into a machine within the proxied network as a work around.
> However the next problem is this.... I will post more details later.
>
> Kim
>
>
> asankha wrote:
>>
>> John
>>
>> Whats your exact Java version? Can you share "java -version", can you
>> also just try JDK 1.5.0_13 etc to see if this problem still remains?
>>> Synapse log:
>>> 2008-03-12 13:25:06,072 [xx.x.x.xx-xxxxxxx] [I/O dispatcher 7] TRACE
>>> ServerHandler New incoming connection
>>> 2008-03-12 13:25:*06*,093 [xx.x.x.xx-xxxxxxx] [I/O dispatcher 7] DEBUG
>>> SSLIOSession I/O session 19 [interested ops: [rw]; ready ops: [w]][SSL
>>> handshake status: *NOT_HANDSHAKING*][0][0][53][0]: Clear event [w]
>>> ............
>>> 2008-03-12 13:25:*14*,091 [xx.x.x.xx-xxxxxxx] [I/O dispatcher 7] DEBUG
>>> SSLIOSession I/O session 19 [interested ops: [r]; ready ops: [r]][SSL
>>> handshake status: *NOT_HANDSHAKING*][853][0][0][0]: 2 bytes read
>>> 2008-03-12 13:25:14,091 [xx.x.x.xx-xxxxxxx] [I/O dispatcher 7] DEBUG
>>> ServerHandler HTTP connection [localhost/127.0.0.1:63557]: POST
>>> /soap/StockQuoteComplex HTTP/1.1
>>> 2008-03-12 13:25:14,092 [xx.x.x.xx-xxxxxxx] [I/O dispatcher 7] DEBUG
>>> headers >> POST /soap/StockQuoteComplex HTTP/1.1
>>>
>> Note the time from 13:25:06 to 13:25:14 where Synapse reports this
>> error. Can you also try the debug options at
>> http://java.sun.com/j2se/1.5.0/docs/guide/security/jsse/JSSERefGuide.html#Debug
>> and the -Djavax.net/debug=all in particular, which would dump a lot of
>> handshake information, which may help us to figure out the problem
>>> Apache log:
>>> [Wed Mar 12 13:25:06 2008] [debug] ssl_engine_kernel.c(1835): OpenSSL:
>>> Loop: SSLv3 read finished A
>>> [Wed Mar 12 13:25:06 2008] [debug] ssl_engine_kernel.c(1831): OpenSSL:
>>> Handshake: done
>>> [Wed Mar 12 13:25:06 2008] [info] Connection: Client IP: 127.0.0.1,
>>> Protocol: TLSv1, Cipher: DHE-RSA-AES256-SHA (256/256 bits)
>>> [Wed Mar 12 13:25:*10 2008] [info] Connection to child 4 established
>>> (server xx.x.x.xxx:443, client xx.x.x.xxx)*
>>> [Wed Mar 12 13:25:10 2008] [info] Seeding PRNG with 144 bytes of entropy
>>> [Wed Mar 12 13:25:10 2008] [debug] ssl_engine_kernel.c(1827): OpenSSL:
>>> Handshake: start
>>> [Wed Mar 12 13:25:10 2008] [debug] ssl_engine_kernel.c(1835): OpenSSL:
>>> Loop: before/accept initialization
>>> [Wed Mar 12 13:25:10 2008] [debug] ssl_engine_io.c(1703): OpenSSL: I/O
>>> error, 11 bytes expected to read on BIO#600000000049d020 [mem:
>>> 6000000000580020]
>>> [Wed Mar 12 13:25:10 2008] [debug] ssl_engine_kernel.c(1864): OpenSSL:
>>> Exit: error in SSLv2/v3 read client hello A
>>> [Wed Mar 12 13:25:10 2008] [info] (232)Connection reset by peer: SSL
>>> handshake interrupted by system [Hint: Stop button pressed in
>>> browser?!]
>>> [Wed Mar 12 13:25:*10 2008] [info] Connection to child 4 closed with
>>> abortive shutdown(server xx.x.x.xxx:443, client xx.x.x.xxx)*
>>> [Wed Mar 12 13:25:*15 2008] [info] Connection to child 73 established
>>> (server xx.x.x.xxx:443, client xx.x.x.xxx)*
>>> [Wed Mar 12 13:25:15 2008] [info] Seeding PRNG with 144 bytes of entropy
>>> [Wed Mar 12 13:25:15 2008] [debug] ssl_engine_kernel.c(1827): OpenSSL:
>>> Handshake: start
>>> [Wed Mar 12 13:25:15 2008] [debug] ssl_engine_kernel.c(1835): OpenSSL:
>>> Loop: before/accept initialization
>>> [Wed Mar 12 13:25:15 2008] [debug] ssl_engine_io.c(1703): OpenSSL: I/O
>>> error, 11 bytes expected to read on BIO#6000000000628aa0 [mem:
>>> 60000000006a0020]
>>> [Wed Mar 12 13:25:15 2008] [debug] ssl_engine_kernel.c(1864): OpenSSL:
>>> Exit: error in SSLv2/v3 read client hello A
>>> [Wed Mar 12 13:25:15 2008] [info] (232)Connection reset by peer: SSL
>>> handshake interrupted by system [Hint: Stop button pressed in
>>> browser?!]
>>> [Wed Mar 12 13:25:*15 2008] [info] Connection to child 73 closed with
>>> abortive shutdown(server xx.x.x.xxx:443, client xx.x.x.xxx)*
>>> [Wed Mar 12 13:25:19 2008] [debug] ssl_engine_io.c(1692): OpenSSL:
>>> read 5/5 bytes from BIO#600000000045d140 [mem: 6000000000655c80] (BIO
>>> dump follows)
>>>
>> It seems like Apache opened multiple connections to Synapse? that failed
>> after a few seconds each? Its going to be a bit difficult for me to try
>> to reproduce this as it may take some time to setup Apache etc, and I am
>> scheduled to be traveling for a week from Sunday.. So it would be great
>> for me to have any material that could help me reproduce this issue
>> quickly.. even Apache configs, and any self signed certs etc (which can
>> be shared.. you can mail these directly to me privately
>>
>> asankha
>>
>>
>
>
--
View this message in context: http://www.nabble.com/Using-SSL-between-Apache-proxy-and-Synapse-causes-consistent-10-second-delay-in-SSL-handshake-tp16014406p22470471.html
Sent from the Synapse - User mailing list archive at Nabble.com.
Re: Using SSL between Apache proxy and Synapse causes consistent 10
second delay in SSL handshake
Posted by kimhorn <ki...@icsglobal.net>.
Hello Asanka,
just so you know we are getting a similar problem and spent last 8 hours
trying to work it out. We get multiple NOT_HANDSHAKING issues after a Web
Service succesfully processes the request (looking at the service server
logs) but the responce never gets back to Synapse. This only happens on our
production and staging systems. The Script works fine on Integration. We
cannot find any differences ? Due to the proxy issue (previous post) we had
to deploy into a machine within the proxied network as a work around.
However the next problem is this.... I will post more details later.
Kim
asankha wrote:
>
> John
>
> Whats your exact Java version? Can you share "java -version", can you
> also just try JDK 1.5.0_13 etc to see if this problem still remains?
>> Synapse log:
>> 2008-03-12 13:25:06,072 [xx.x.x.xx-xxxxxxx] [I/O dispatcher 7] TRACE
>> ServerHandler New incoming connection
>> 2008-03-12 13:25:*06*,093 [xx.x.x.xx-xxxxxxx] [I/O dispatcher 7] DEBUG
>> SSLIOSession I/O session 19 [interested ops: [rw]; ready ops: [w]][SSL
>> handshake status: *NOT_HANDSHAKING*][0][0][53][0]: Clear event [w]
>> ............
>> 2008-03-12 13:25:*14*,091 [xx.x.x.xx-xxxxxxx] [I/O dispatcher 7] DEBUG
>> SSLIOSession I/O session 19 [interested ops: [r]; ready ops: [r]][SSL
>> handshake status: *NOT_HANDSHAKING*][853][0][0][0]: 2 bytes read
>> 2008-03-12 13:25:14,091 [xx.x.x.xx-xxxxxxx] [I/O dispatcher 7] DEBUG
>> ServerHandler HTTP connection [localhost/127.0.0.1:63557]: POST
>> /soap/StockQuoteComplex HTTP/1.1
>> 2008-03-12 13:25:14,092 [xx.x.x.xx-xxxxxxx] [I/O dispatcher 7] DEBUG
>> headers >> POST /soap/StockQuoteComplex HTTP/1.1
>>
> Note the time from 13:25:06 to 13:25:14 where Synapse reports this
> error. Can you also try the debug options at
> http://java.sun.com/j2se/1.5.0/docs/guide/security/jsse/JSSERefGuide.html#Debug
> and the -Djavax.net/debug=all in particular, which would dump a lot of
> handshake information, which may help us to figure out the problem
>> Apache log:
>> [Wed Mar 12 13:25:06 2008] [debug] ssl_engine_kernel.c(1835): OpenSSL:
>> Loop: SSLv3 read finished A
>> [Wed Mar 12 13:25:06 2008] [debug] ssl_engine_kernel.c(1831): OpenSSL:
>> Handshake: done
>> [Wed Mar 12 13:25:06 2008] [info] Connection: Client IP: 127.0.0.1,
>> Protocol: TLSv1, Cipher: DHE-RSA-AES256-SHA (256/256 bits)
>> [Wed Mar 12 13:25:*10 2008] [info] Connection to child 4 established
>> (server xx.x.x.xxx:443, client xx.x.x.xxx)*
>> [Wed Mar 12 13:25:10 2008] [info] Seeding PRNG with 144 bytes of entropy
>> [Wed Mar 12 13:25:10 2008] [debug] ssl_engine_kernel.c(1827): OpenSSL:
>> Handshake: start
>> [Wed Mar 12 13:25:10 2008] [debug] ssl_engine_kernel.c(1835): OpenSSL:
>> Loop: before/accept initialization
>> [Wed Mar 12 13:25:10 2008] [debug] ssl_engine_io.c(1703): OpenSSL: I/O
>> error, 11 bytes expected to read on BIO#600000000049d020 [mem:
>> 6000000000580020]
>> [Wed Mar 12 13:25:10 2008] [debug] ssl_engine_kernel.c(1864): OpenSSL:
>> Exit: error in SSLv2/v3 read client hello A
>> [Wed Mar 12 13:25:10 2008] [info] (232)Connection reset by peer: SSL
>> handshake interrupted by system [Hint: Stop button pressed in
>> browser?!]
>> [Wed Mar 12 13:25:*10 2008] [info] Connection to child 4 closed with
>> abortive shutdown(server xx.x.x.xxx:443, client xx.x.x.xxx)*
>> [Wed Mar 12 13:25:*15 2008] [info] Connection to child 73 established
>> (server xx.x.x.xxx:443, client xx.x.x.xxx)*
>> [Wed Mar 12 13:25:15 2008] [info] Seeding PRNG with 144 bytes of entropy
>> [Wed Mar 12 13:25:15 2008] [debug] ssl_engine_kernel.c(1827): OpenSSL:
>> Handshake: start
>> [Wed Mar 12 13:25:15 2008] [debug] ssl_engine_kernel.c(1835): OpenSSL:
>> Loop: before/accept initialization
>> [Wed Mar 12 13:25:15 2008] [debug] ssl_engine_io.c(1703): OpenSSL: I/O
>> error, 11 bytes expected to read on BIO#6000000000628aa0 [mem:
>> 60000000006a0020]
>> [Wed Mar 12 13:25:15 2008] [debug] ssl_engine_kernel.c(1864): OpenSSL:
>> Exit: error in SSLv2/v3 read client hello A
>> [Wed Mar 12 13:25:15 2008] [info] (232)Connection reset by peer: SSL
>> handshake interrupted by system [Hint: Stop button pressed in
>> browser?!]
>> [Wed Mar 12 13:25:*15 2008] [info] Connection to child 73 closed with
>> abortive shutdown(server xx.x.x.xxx:443, client xx.x.x.xxx)*
>> [Wed Mar 12 13:25:19 2008] [debug] ssl_engine_io.c(1692): OpenSSL:
>> read 5/5 bytes from BIO#600000000045d140 [mem: 6000000000655c80] (BIO
>> dump follows)
>>
> It seems like Apache opened multiple connections to Synapse? that failed
> after a few seconds each? Its going to be a bit difficult for me to try
> to reproduce this as it may take some time to setup Apache etc, and I am
> scheduled to be traveling for a week from Sunday.. So it would be great
> for me to have any material that could help me reproduce this issue
> quickly.. even Apache configs, and any self signed certs etc (which can
> be shared.. you can mail these directly to me privately
>
> asankha
>
>
--
View this message in context: http://www.nabble.com/Using-SSL-between-Apache-proxy-and-Synapse-causes-consistent-10-second-delay-in-SSL-handshake-tp16014406p22470055.html
Sent from the Synapse - User mailing list archive at Nabble.com.
Re: Using SSL between Apache proxy and Synapse causes consistent
10 second delay in SSL handshake
Posted by "Asankha C. Perera" <as...@wso2.com>.
John
Whats your exact Java version? Can you share "java -version", can you
also just try JDK 1.5.0_13 etc to see if this problem still remains?
> Synapse log:
> 2008-03-12 13:25:06,072 [xx.x.x.xx-xxxxxxx] [I/O dispatcher 7] TRACE
> ServerHandler New incoming connection
> 2008-03-12 13:25:*06*,093 [xx.x.x.xx-xxxxxxx] [I/O dispatcher 7] DEBUG
> SSLIOSession I/O session 19 [interested ops: [rw]; ready ops: [w]][SSL
> handshake status: *NOT_HANDSHAKING*][0][0][53][0]: Clear event [w]
> ............
> 2008-03-12 13:25:*14*,091 [xx.x.x.xx-xxxxxxx] [I/O dispatcher 7] DEBUG
> SSLIOSession I/O session 19 [interested ops: [r]; ready ops: [r]][SSL
> handshake status: *NOT_HANDSHAKING*][853][0][0][0]: 2 bytes read
> 2008-03-12 13:25:14,091 [xx.x.x.xx-xxxxxxx] [I/O dispatcher 7] DEBUG
> ServerHandler HTTP connection [localhost/127.0.0.1:63557]: POST
> /soap/StockQuoteComplex HTTP/1.1
> 2008-03-12 13:25:14,092 [xx.x.x.xx-xxxxxxx] [I/O dispatcher 7] DEBUG
> headers >> POST /soap/StockQuoteComplex HTTP/1.1
>
Note the time from 13:25:06 to 13:25:14 where Synapse reports this
error. Can you also try the debug options at
http://java.sun.com/j2se/1.5.0/docs/guide/security/jsse/JSSERefGuide.html#Debug
and the -Djavax.net/debug=all in particular, which would dump a lot of
handshake information, which may help us to figure out the problem
> Apache log:
> [Wed Mar 12 13:25:06 2008] [debug] ssl_engine_kernel.c(1835): OpenSSL:
> Loop: SSLv3 read finished A
> [Wed Mar 12 13:25:06 2008] [debug] ssl_engine_kernel.c(1831): OpenSSL:
> Handshake: done
> [Wed Mar 12 13:25:06 2008] [info] Connection: Client IP: 127.0.0.1,
> Protocol: TLSv1, Cipher: DHE-RSA-AES256-SHA (256/256 bits)
> [Wed Mar 12 13:25:*10 2008] [info] Connection to child 4 established
> (server xx.x.x.xxx:443, client xx.x.x.xxx)*
> [Wed Mar 12 13:25:10 2008] [info] Seeding PRNG with 144 bytes of entropy
> [Wed Mar 12 13:25:10 2008] [debug] ssl_engine_kernel.c(1827): OpenSSL:
> Handshake: start
> [Wed Mar 12 13:25:10 2008] [debug] ssl_engine_kernel.c(1835): OpenSSL:
> Loop: before/accept initialization
> [Wed Mar 12 13:25:10 2008] [debug] ssl_engine_io.c(1703): OpenSSL: I/O
> error, 11 bytes expected to read on BIO#600000000049d020 [mem:
> 6000000000580020]
> [Wed Mar 12 13:25:10 2008] [debug] ssl_engine_kernel.c(1864): OpenSSL:
> Exit: error in SSLv2/v3 read client hello A
> [Wed Mar 12 13:25:10 2008] [info] (232)Connection reset by peer: SSL
> handshake interrupted by system [Hint: Stop button pressed in
> browser?!]
> [Wed Mar 12 13:25:*10 2008] [info] Connection to child 4 closed with
> abortive shutdown(server xx.x.x.xxx:443, client xx.x.x.xxx)*
> [Wed Mar 12 13:25:*15 2008] [info] Connection to child 73 established
> (server xx.x.x.xxx:443, client xx.x.x.xxx)*
> [Wed Mar 12 13:25:15 2008] [info] Seeding PRNG with 144 bytes of entropy
> [Wed Mar 12 13:25:15 2008] [debug] ssl_engine_kernel.c(1827): OpenSSL:
> Handshake: start
> [Wed Mar 12 13:25:15 2008] [debug] ssl_engine_kernel.c(1835): OpenSSL:
> Loop: before/accept initialization
> [Wed Mar 12 13:25:15 2008] [debug] ssl_engine_io.c(1703): OpenSSL: I/O
> error, 11 bytes expected to read on BIO#6000000000628aa0 [mem:
> 60000000006a0020]
> [Wed Mar 12 13:25:15 2008] [debug] ssl_engine_kernel.c(1864): OpenSSL:
> Exit: error in SSLv2/v3 read client hello A
> [Wed Mar 12 13:25:15 2008] [info] (232)Connection reset by peer: SSL
> handshake interrupted by system [Hint: Stop button pressed in
> browser?!]
> [Wed Mar 12 13:25:*15 2008] [info] Connection to child 73 closed with
> abortive shutdown(server xx.x.x.xxx:443, client xx.x.x.xxx)*
> [Wed Mar 12 13:25:19 2008] [debug] ssl_engine_io.c(1692): OpenSSL:
> read 5/5 bytes from BIO#600000000045d140 [mem: 6000000000655c80] (BIO
> dump follows)
>
It seems like Apache opened multiple connections to Synapse? that failed
after a few seconds each? Its going to be a bit difficult for me to try
to reproduce this as it may take some time to setup Apache etc, and I am
scheduled to be traveling for a week from Sunday.. So it would be great
for me to have any material that could help me reproduce this issue
quickly.. even Apache configs, and any self signed certs etc (which can
be shared.. you can mail these directly to me privately
asankha