hc-httpclient-users mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Jose Escobar <eb.j...@gmail.com>
Subject Re: HttpClient with PoolingClientConnectionManager throws read time out
Date Tue, 16 Oct 2012 15:58:28 GMT
Finally I've captured the wire log of the anomalous situation. There
are multiple executors (threads) trying to send different http posts
to the same url and all get the same exception:

2012-16-10_17:30:30.668 [myExecutor-45] INFO
c.e.e.a.l.a.i.As2MessageBuilderImpl - AƱadir messageid:
O12101617294288169@xxx.xxxxxxxx.com
2012-16-10_17:30:30.766 [myExecutor-45] INFO
c.e.e.a.l.a.i.As2MessageSenderImpl - Enviando mensaje HTTP POST
2012-16-10_17:30:30.766 [myExecutor-45] DEBUG
o.a.h.i.c.PoolingClientConnectionManager - Connection request: [route:
{}->http://yyyyyy.com][total kept alive: 52; route allocated: 44 of
75; total allocated: 96 of 400]
2012-16-10_17:30:30.766 [myExecutor-45] DEBUG
o.a.h.i.c.PoolingClientConnectionManager - Connection leased: [id:
220][route: {}->http://yyyyyy.com][total kept alive: 52; route
allocated: 45 of 75; total allocated: 97 of 400]
2012-16-10_17:30:30.766 [myExecutor-45] DEBUG
o.a.h.i.c.DefaultClientConnectionOperator - Connecting to
yyyyyy.com:80
2012-16-10_17:30:30.766 [myExecutor-45] INFO
c.e.e.a.c.CustomPlainSocketFactory - Tratando de conseguir un socket
de salida con puerto 52926
2012-16-10_17:30:30.801 [myExecutor-45] DEBUG
o.a.h.c.protocol.RequestAddCookies - CookieSpec selected: best-match
2012-16-10_17:30:30.801 [myExecutor-45] DEBUG
o.a.h.c.protocol.RequestAddCookies - Cookie [version: 0][name:
ASP.NET_SessionId][value: cd5gazy1mzkrx2arlbpqyfe5][domain:
yyyyyy.com][path: /][expiry: null] match [yyyyyy.com:80/var/foo.aspx]
2012-16-10_17:30:30.801 [myExecutor-45] DEBUG
o.a.h.c.protocol.RequestAuthCache - Auth cache not set in the context
2012-16-10_17:30:30.801 [myExecutor-45] DEBUG
o.a.h.c.p.RequestTargetAuthentication - Target auth state:
UNCHALLENGED
2012-16-10_17:30:30.801 [myExecutor-45] DEBUG
o.a.h.c.p.RequestProxyAuthentication - Proxy auth state: UNCHALLENGED
2012-16-10_17:30:30.801 [myExecutor-45] DEBUG
o.a.h.impl.client.DefaultHttpClient - Attempt 1 to execute request
2012-16-10_17:30:30.801 [myExecutor-45] DEBUG
o.a.h.i.conn.DefaultClientConnection - Sending request: POST
/var/foo.aspx HTTP/1.1
2012-16-10_17:30:30.802 [myExecutor-45] DEBUG org.apache.http.headers
- >> POST /var/foo.aspx HTTP/1.1
2012-16-10_17:30:30.802 [myExecutor-45] DEBUG org.apache.http.headers
- >> MIME-Version: 1.0
2012-16-10_17:30:30.802 [myExecutor-45] DEBUG org.apache.http.headers
- >> Content-Type: application/pkcs7-mime; name="smime.p7m";
smime-type=enveloped-data
2012-16-10_17:30:30.802 [myExecutor-45] DEBUG org.apache.http.headers
- >> Content-Transfer-Encoding: binary
2012-16-10_17:30:30.802 [myExecutor-45] DEBUG org.apache.http.headers
- >> Content-Disposition: attachment; filename="smime.p7m"
2012-16-10_17:30:30.802 [myExecutor-45] DEBUG org.apache.http.headers
- >> Content-Description: S/MIME Encrypted Message
2012-16-10_17:30:30.802 [myExecutor-45] DEBUG org.apache.http.headers
- >> Content-Length: 12459
2012-16-10_17:30:30.802 [myExecutor-45] DEBUG org.apache.http.headers
- >> Host: yyyyyy.com
2012-16-10_17:30:30.802 [myExecutor-45] DEBUG org.apache.http.headers
- >> Connection: Keep-Alive
2012-16-10_17:30:30.802 [myExecutor-45] DEBUG org.apache.http.headers
- >> User-Agent: Apache-HttpClient/4.2 (java 1.5)
2012-16-10_17:30:30.802 [myExecutor-45] DEBUG org.apache.http.headers
- >> Cookie: ASP.NET_SessionId=cd5gazy1mzkrx2arlbpqyfe5
2012-16-10_17:30:30.802 [myExecutor-45] DEBUG org.apache.http.headers
- >> Cookie2: $Version=1
...
2012-16-10_17:31:30.821 [myExecutor-45] DEBUG
o.a.h.i.conn.DefaultClientConnection - Connection
0.0.0.0:52926<->xxx.xxx.xxx.xxx closed
2012-16-10_17:31:30.821 [myExecutor-45] DEBUG
o.a.h.impl.client.DefaultHttpClient - Closing the connection.
2012-16-10_17:31:30.821 [myExecutor-45] DEBUG
o.a.h.i.conn.DefaultClientConnection - Connection
0.0.0.0:52926<->xxx.xxx.xxx.xxx closed
2012-16-10_17:31:30.821 [myExecutor-45] DEBUG
o.a.h.i.conn.DefaultClientConnection - Connection
0.0.0.0:52926<->xxx.xxx.xxx.xxx shut down
2012-16-10_17:31:30.821 [myExecutor-45] DEBUG
o.a.h.i.c.PoolingClientConnectionManager - Connection [id: 220][route:
{}->http://yyyyyy.com] can be kept alive for 9223372036854775807
MILLISECONDS
2012-16-10_17:31:30.821 [myExecutor-45] DEBUG
o.a.h.i.conn.DefaultClientConnection - Connection
0.0.0.0:52926<->xxx.xxx.xxx.xxx closed
2012-16-10_17:31:30.821 [myExecutor-45] DEBUG
o.a.h.i.c.PoolingClientConnectionManager - Connection released: [id:
220][route: {}->http://yyyyyy.com][total kept alive: 52; route
allocated: 48 of 75; total allocated: 100 of 400]
2012-16-10_17:31:30.821 [myExecutor-45] INFO
c.e.e.a.l.a.i.As2MessageSenderImpl - Enviado mensaje hacia
http://yyyyyy.com/var/foo.aspx pero ocurriĆ³ un error: Read timed out




I don't think that external server is just too slow to respond because
almost every time it tooks less than 4 seconds to respond.

2012/10/16 Jose Escobar <eb.jose@gmail.com>:
> Murphy's law, since I activated wire log there's no timeout errors...
>
> As soon as I get an error I'll mail it
>
>
> 2012/10/15 William Speirs <wspeirs@apache.org>:
>> Do you have the wire logs?
>>
>> Bill-
>>
>> On Mon, Oct 15, 2012 at 7:23 AM, Jose Escobar <eb.jose@gmail.com> wrote:
>>> Hello,
>>>
>>> I'm using httpclient on a spring aplication to send http posts.
>>> I have a shared singleton bean instance of DefaultHttpClient that I
>>> use to execute httpPost, this DefaultHttpClient have a
>>> PoolingClientConnectionManager and it's configured as show :
>>>
>>> ...
>>> PoolingClientConnectionManager connectionManager=new
>>> PoolingClientConnectionManager(schemeRegistry, 65,
>>> java.util.concurrent.TimeUnit.SECONDS);
>>>
>>> // Increase max total connection to 100
>>> connectionManager.setMaxTotal(100);
>>> // Increase default max connection per route to 15
>>> connectionManager.setDefaultMaxPerRoute(25);
>>> // Increase max connections for localhost:80 to 50
>>> HttpHost localhost = new HttpHost("locahost", 80);
>>> connectionManager.setMaxPerRoute(new HttpRoute(localhost), 50);
>>>
>>> ...
>>>
>>> @Bean
>>> public DefaultHttpClient httpClient(){
>>> DefaultHttpClient httpClient=new DefaultHttpClient(connectionManager());
>>> //httpClient.setParams(params)
>>>
>>> HttpParams params = httpClient.getParams();
>>> HttpConnectionParams.setConnectionTimeout(params, HTTPCLIENT_TIMEOUT);
>>> HttpConnectionParams.setSoTimeout(params, HTTPCLIENT_TIMEOUT);
>>>
>>> return httpClient;
>>> }
>>>
>>>
>>>
>>> It works correctly until the aplication have to send multiple post at
>>> same time to the same route. It start to throws readTimeOut Exception
>>>
>>> java.net.SocketTimeoutException: Read timed out
>>> at java.net.SocketInputStream.socketRead0(Native Method)
>>> at java.net.SocketInputStream.read(SocketInputStream.java:129)
>>> at org.apache.http.impl.io.AbstractSessionInputBuffer.fillBuffer(AbstractSessionInputBuffer.java:166)
>>> at org.apache.http.impl.io.SocketInputBuffer.fillBuffer(SocketInputBuffer.java:90)
>>> at org.apache.http.impl.io.AbstractSessionInputBuffer.readLine(AbstractSessionInputBuffer.java:281)
>>> at org.apache.http.impl.conn.DefaultHttpResponseParser.parseHead(DefaultHttpResponseParser.java:92)
>>> at org.apache.http.impl.conn.DefaultHttpResponseParser.parseHead(DefaultHttpResponseParser.java:61)
>>> at org.apache.http.impl.io.AbstractMessageParser.parse(AbstractMessageParser.java:254)
>>> at org.apache.http.impl.AbstractHttpClientConnection.receiveResponseHeader(AbstractHttpClientConnection.java:289)
>>> at org.apache.http.impl.conn.DefaultClientConnection.receiveResponseHeader(DefaultClientConnection.java:252)
>>> at org.apache.http.impl.conn.ManagedClientConnectionImpl.receiveResponseHeader(ManagedClientConnectionImpl.java:191)
>>> at org.apache.http.protocol.HttpRequestExecutor.doReceiveResponse(HttpRequestExecutor.java:300)
>>> at org.apache.http.protocol.HttpRequestExecutor.execute(HttpRequestExecutor.java:127)
>>> at org.apache.http.impl.client.DefaultRequestDirector.tryExecute(DefaultRequestDirector.java:713)
>>> at org.apache.http.impl.client.DefaultRequestDirector.execute(DefaultRequestDirector.java:518)
>>> at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:906)
>>> at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:805)
>>> at com.edicom.edicomnet.asxserver.logic.as2.impl.As2MessageSenderImpl.sendMessage(As2MessageSenderImpl.java:117)
>>> at sun.reflect.GeneratedMethodAccessor575.invoke(Unknown Source)
>>> at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
>>> at java.lang.reflect.Method.invoke(Method.java:597)
>>> at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:309)
>>> at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:183)
>>> at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:150)
>>> at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:110)
>>> at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
>>> at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:202)
>>> at $Proxy52.sendMessage(Unknown Source)
>>> at com.edicom.edicomnet.asxserver.businessServices.impl.MessageSenderImpl.sendCreatedAS2Message(MessageSenderImpl.java:119)
>>> at sun.reflect.GeneratedMethodAccessor551.invoke(Unknown Source)
>>> at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
>>> at java.lang.reflect.Method.invoke(Method.java:597)
>>> at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:309)
>>> at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:183)
>>> at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:150)
>>> at org.springframework.aop.interceptor.AsyncExecutionInterceptor$1.call(AsyncExecutionInterceptor.java:80)
>>> at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303)
>>> at java.util.concurrent.FutureTask.run(FutureTask.java:138)
>>> at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
>>> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
>>> at java.lang.Thread.run(Thread.java:662)
>>>
>>>
>>> I hope you can help me with this problem (maybe something about concurrency?)
>>>
>>>
>>> Thank you!
>>>
>>> ---------------------------------------------------------------------
>>> To unsubscribe, e-mail: httpclient-users-unsubscribe@hc.apache.org
>>> For additional commands, e-mail: httpclient-users-help@hc.apache.org
>>>
>>
>> ---------------------------------------------------------------------
>> To unsubscribe, e-mail: httpclient-users-unsubscribe@hc.apache.org
>> For additional commands, e-mail: httpclient-users-help@hc.apache.org
>>

---------------------------------------------------------------------
To unsubscribe, e-mail: httpclient-users-unsubscribe@hc.apache.org
For additional commands, e-mail: httpclient-users-help@hc.apache.org


Mime
View raw message