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 Wed, 17 Oct 2012 09:24:22 GMT
I have 60 seconds of timeout, not to aggressive. Maybe it's a limit on
my gnu/linux on outgoing sockets or something like this.

However I found a strange value for keep-alive time on logs:

o.a.h.i.c.PoolingClientConnectionManager - Connection [id: 220][route:
{}->http://yyyyyy.com] can be kept alive for 9223372036854775807
MILLISECONDS

This time wasn't at request header and I have a limit of 15 secs when
no keep-alive time header is received:

httpClient.setKeepAliveStrategy(new DefaultConnectionKeepAliveStrategy() {
		    @Override
		    public long getKeepAliveDuration(
		            HttpResponse response,
		            HttpContext context) {
		        long keepAlive = super.getKeepAliveDuration(response, context);
		        if (keepAlive == -1) {
		            keepAlive = 15000;
		        }
		        return keepAlive;
		    }
		
		});


It's that normal?

2012/10/16 Oleg Kalnichevski <olegk@apache.org>:
> On Tue, 2012-10-16 at 17:58 +0200, Jose Escobar wrote:
>> 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:
>>
>
> Jose
>
> The thing is I/O socket operations as well as socket timeouts are all
> handled by the JRE through native calls. So, essentially, i/o operations
> can only time out when the server fails to send data within the
> specified timeout period. Either your timeout settings are too
> aggressive or something happens on the server side that prevents it from
> serving requests.
>
> Oleg
>
>> 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
>>
>
>
>
> ---------------------------------------------------------------------
> 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