Hello HttpClient users!
I have a Spring Web Application that makes a mutual authentication SSL call to
a web service. My application currently uses httpclient-4.2.5, httpcore-4.2.4.
It is set up using the PoolingClientConnectionManager. My problem is the
PoolingClientConnectionManager does not seem to be re-using the persistence
connections. I have http components debugging and javax.net.debug=ssl
debugging and see a connection handshake every time a connection request is
made.
I have another setup with commons-httpclient-3.1 and re-using persistence
connection works perfectly, but we wanted to upgrade to httpclient v4 to keep
up with technology. Any help with solving this issue is greatly appreciated.
Thanks in advance!
Spring configuration:
--
<bean id="httpParams"
class="org.apache.http.params.SyncBasicHttpParams" />
<bean id="httpConnectionManagerParams"
class="org.apache.http.params.HttpConnectionParamBean">
<constructor-arg ref="HttpParams" />
<property name="connectionTimeout" value="20000" />
<property name="soTimeout" value="20000" />
</bean>
<bean id="httpClientParams"
class="org.apache.http.client.params.ClientParamBean">
<constructor-arg ref="httpParams" />
<property name="connectionManagerTimeout" value="20000" />
<property name="cookiePolicy"><util:constant
static-field="org.apache.http.client.params.CookiePolicy.IGNORE_COOKIES"
/></property>
</bean>
<bean id="httpConnectionManager"
class="org.apache.http.impl.conn.PoolingClientConnectionManager" >
<constructor-arg ref="schemeRegistry" />
<property name="defaultMaxPerRoute" value="5" />
<property name="maxTotal" value="5" />
</bean>
<bean id="httpClient"
class="org.apache.http.impl.client.DefaultHttpClient" >
<constructor-arg ref="httpConnectionManager" />
<property name="params" ref="HttpParams" />
</bean>
--
Logs Snippet:
---
2013-08-15 10:07:21,671 DEBUG
[org.apache.http.impl.conn.DefaultClientConnectionOperator] - <Connecting to
webservice.host.com:543>
main, setSoTimeout(20000) called
Allow unsafe renegotiation: false
Allow legacy hello messages: true
Is initial handshake: true
Is secure renegotiation: false
..
***
main, WRITE: TLSv1 Handshake, length = 181
main, READ: TLSv1 Handshake, length = 81
*** ServerHello, TLSv1
RandomCookie: GMT: 1376509849 bytes = { 197, 204, 18, 136, 99, 193, 97, 245,
181, 112, 172, 80, 113, 11, 242, 104, 91, 169, 153, 21, 111, 90, 41, 149, 54,
155, 17, 143 }
Session ID: {82, 12, 224, 151, 142, 196, 251, 80, 31, 171, 60, 40, 195, 192,
178, 112, 241, 247, 229, 208, 58, 224, 221, 58, 20, 236, 11, 215, 109, 156,
146, 93}
Cipher Suite: TLS_RSA_WITH_AES_128_CBC_SHA
Compression Method: 0
Extension renegotiation_info, renegotiated_connection: <empty>
***
CONNECTION KEYGEN:
..
main, READ: TLSv1 Change Cipher Spec, length = 1
main, READ: TLSv1 Handshake, length = 48
*** Finished
verify_data: { 92, 165, 233, 53, 188, 249, 252, 215, 15, 64, 255, 208 }
***
main, WRITE: TLSv1 Change Cipher Spec, length = 1
*** Finished
verify_data: { 200, 157, 126, 133, 154, 157, 153, 16, 6, 202, 135, 12 }
***
main, WRITE: TLSv1 Handshake, length = 48
main, setSoTimeout(20000) called
2013-08-15 10:07:22,218 DEBUG
[org.apache.http.client.protocol.RequestAddCookies] - <CookieSpec selected:
ignoreCookies>
2013-08-15 10:07:22,218 DEBUG
[org.apache.http.client.protocol.RequestAuthCache] - <Auth cache not set in the
context>
2013-08-15 10:07:22,218 DEBUG
[org.apache.http.client.protocol.RequestTargetAuthentication] - <Target auth
state: UNCHALLENGED>
2013-08-15 10:07:22,218 DEBUG
[org.apache.http.client.protocol.RequestProxyAuthentication] - <Proxy auth
state: UNCHALLENGED>
2013-08-15 10:07:22,218 DEBUG [org.apache.http.impl.client.DefaultHttpClient] -
<Attempt 1 to execute request>
2013-08-15 10:07:22,218 DEBUG
[org.apache.http.impl.conn.DefaultClientConnection] - <Sending request: POST
/best/dist HTTP/1.1>
2013-08-15 10:07:22,218 DEBUG [org.apache.http.wire] - <>> "POST /best/dist
HTTP/1.1[\r][\n]">
2013-08-15 10:07:22,218 DEBUG [org.apache.http.wire] - <>> "Accept-Encoding:
gzip[\r][\n]">
2013-08-15 10:07:22,218 DEBUG [org.apache.http.wire] - <>> "Accept: text/xml,
text/html, image/gif, image/jpeg, *; q=.2, */*; q=.2[\r][\n]">
2013-08-15 10:07:22,218 DEBUG [org.apache.http.wire] - <>> "SOAPAction:
""[\r][\n]">
2013-08-15 10:07:22,218 DEBUG [org.apache.http.wire] - <>> "Content-Type:
text/xml; charset=utf-8[\r][\n]">
2013-08-15 10:07:22,218 DEBUG [org.apache.http.wire] - <>> "Content-Length:
1908[\r][\n]">
2013-08-15 10:07:22,218 DEBUG [org.apache.http.wire] - <>> "Host:
webservice.host.com:543[\r][\n]">
2013-08-15 10:07:22,218 DEBUG [org.apache.http.wire] - <>> "Connection:
Keep-Alive[\r][\n]">
2013-08-15 10:07:22,218 DEBUG [org.apache.http.wire] - <>> "[\r][\n]">
2013-08-15 10:07:22,218 DEBUG [org.apache.http.headers] - <>> POST /best/dist
HTTP/1.1>
2013-08-15 10:07:22,218 DEBUG [org.apache.http.headers] - <>> Accept-Encoding:
gzip>
2013-08-15 10:07:22,218 DEBUG [org.apache.http.headers] - <>> Accept: text/xml,
text/html, image/gif, image/jpeg, *; q=.2, */*; q=.2>
2013-08-15 10:07:22,218 DEBUG [org.apache.http.headers] - <>> SOAPAction: "">
2013-08-15 10:07:22,218 DEBUG [org.apache.http.headers] - <>> Content-Type:
text/xml; charset=utf-8>
2013-08-15 10:07:22,218 DEBUG [org.apache.http.headers] - <>> Content-Length:
1908>
2013-08-15 10:07:22,218 DEBUG [org.apache.http.headers] - <>> Host:
webservice.host.com:543>
2013-08-15 10:07:22,218 DEBUG [org.apache.http.headers] - <>> Connection:
Keep-Alive>
main, WRITE: TLSv1 Application Data, length = 288
main, WRITE: TLSv1 Application Data, length = 32
main, WRITE: TLSv1 Application Data, length = 1936
2013-08-15 10:07:22,218 DEBUG [org.apache.http.wire] - <>> "<SOAP-ENV:Envelope
xmlns:SOAP-ENV="http://schemas.xmlsoap.org/soap/envelope>REQUEST
XML</SOAP-ENV:Envelope>">
main, READ: TLSv1 Application Data, length = 3584
2013-08-15 10:07:22,608 DEBUG [org.apache.http.wire] - <<< "HTTP/1.1 200
OK[\r][\n]">
2013-08-15 10:07:22,608 DEBUG [org.apache.http.wire] - <<< "Server:
Apache-Coyote/1.1[\r][\n]">
2013-08-15 10:07:22,608 DEBUG [org.apache.http.wire] - <<< "Content-Type:
text/xml;charset=utf-8[\r][\n]">
2013-08-15 10:07:22,608 DEBUG [org.apache.http.wire] - <<< "Content-Length:
3405[\r][\n]">
2013-08-15 10:07:22,608 DEBUG [org.apache.http.wire] - <<< "Date: Thu, 15 Aug
2013 14:07:21 GMT[\r][\n]">
2013-08-15 10:07:22,608 DEBUG [org.apache.http.wire] - <<< "[\r][\n]">
2013-08-15 10:07:22,608 DEBUG
[org.apache.http.impl.conn.DefaultClientConnection] - <Receiving response:
HTTP/1.1 200 OK>
2013-08-15 10:07:22,608 DEBUG [org.apache.http.headers] - <<< HTTP/1.1 200 OK>
2013-08-15 10:07:22,608 DEBUG [org.apache.http.headers] - <<< Server:
Apache-Coyote/1.1>
2013-08-15 10:07:22,608 DEBUG [org.apache.http.headers] - <<< Content-Type:
text/xml;charset=utf-8>
2013-08-15 10:07:22,608 DEBUG [org.apache.http.headers] - <<< Content-Length:
3405>
2013-08-15 10:07:22,608 DEBUG [org.apache.http.headers] - <<< Date: Thu, 15 Aug
2013 14:07:21 GMT>
2013-08-15 10:07:22,608 DEBUG [org.apache.http.impl.client.DefaultHttpClient] -
<Connection can be kept alive indefinitely>
2013-08-15 10:07:22,608 DEBUG [org.apache.http.wire] - <<< "<?xml version="1.0"
encoding="utf-8"?><SOAP-ENV:Envelope>Response.XML</SOAP-ENV:Envelope>[\n]">
2013-08-15 10:07:22,608 DEBUG
[org.apache.http.impl.conn.PoolingClientConnectionManager] - <Connection [id:
1][route: {s}->https://webservice.host.com:543][state: XX] can be kept alive
indefinitely>
2013-08-15 10:07:22,608 DEBUG
[org.apache.http.impl.conn.PoolingClientConnectionManager] - <Connection
released: [id: 1][route: {s}->https://webservice.host.com:543][state:
XXX][total kept alive: 2; route allocated: 2 of 5; total allocated: 2 of 5]>
============================== Get Customer #1, executionTime[953]
===========================
// First connection ends
2013-08-15 10:07:22,639 DEBUG
[org.apache.http.impl.conn.PoolingClientConnectionManager] - <Connection
request: [route: {s}->https://webservice.host.com:543][total kept alive: 2;
route allocated: 2 of 5; total allocated: 2 of 5]>
2013-08-15 10:07:22,639 DEBUG
[org.apache.http.impl.conn.PoolingClientConnectionManager] - <Connection
leased: [id: 2][route: {s}->https://webservice.host.com:543][total kept alive:
2; route allocated: 3 of 5; total allocated: 3 of 5]>
2013-08-15 10:07:22,639 DEBUG
[org.apache.http.impl.conn.DefaultClientConnectionOperator] - <Connecting to
webservice.host.com:543>
main, setSoTimeout(20000) called
Allow unsafe renegotiation: false
Allow legacy hello messages: true
Is initial handshake: true
Is secure renegotiation: false
%% Client cached [Session-1, TLS_RSA_WITH_AES_128_CBC_SHA]
%% Try resuming [Session-1, TLS_RSA_WITH_AES_128_CBC_SHA] from port 56073
*** ClientHello, TLSv1
...
...
2013-08-15 10:07:23,592 DEBUG
[org.apache.http.impl.conn.PoolingClientConnectionManager] - <Connection [id:
2][route: {s}->https://webservice.host.com:543][state: XX] can be kept alive
indefinitely>
2013-08-15 10:07:23,592 DEBUG
[org.apache.http.impl.conn.PoolingClientConnectionManager] - <Connection
released: [id: 2][route: {s}->https://webservice.host.com:543][state: XX][total
kept alive: 3; route allocated: 3 of 5; total allocated: 3 of 5]>
============================== Get Customer #2, executionTime[983]
===========================
// 2nd connection ends
--
LOG SNIPPETS END
Somath Nao
