hc-httpclient-users mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Oleg Kalnichevski <ol...@apache.org>
Subject RE: HttpClient with PoolingClientConnectionManager throws read time out
Date Wed, 17 Oct 2012 14:11:22 GMT
On Wed, 2012-10-17 at 10:07 -0400, Mark Claassen wrote:
> A quick check using an online too shows that that 9223372036854775807 is
> 111111111111111111111111111111111111111111111111111111111111111 in binary.  
> 

Yeah, it is just bad logging. Basically that value means keep alive
indefinitely. I thought I had fixed all the instances of that problem.
Apparently not.

Oleg

> -----Original Message-----
> From: Jose Escobar [mailto:eb.jose@gmail.com] 
> Sent: Wednesday, October 17, 2012 5:24 AM
> To: HttpClient User Discussion
> Subject: Re: HttpClient with PoolingClientConnectionManager throws read time out
> 
> 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(Abs
> >> >>> tractSessionInputBuffer.java:166) at 
> >> >>> org.apache.http.impl.io.SocketInputBuffer.fillBuffer(SocketInputB
> >> >>> uffer.java:90) at 
> >> >>> org.apache.http.impl.io.AbstractSessionInputBuffer.readLine(Abstr
> >> >>> actSessionInputBuffer.java:281) at 
> >> >>> org.apache.http.impl.conn.DefaultHttpResponseParser.parseHead(Def
> >> >>> aultHttpResponseParser.java:92) at 
> >> >>> org.apache.http.impl.conn.DefaultHttpResponseParser.parseHead(Def
> >> >>> aultHttpResponseParser.java:61) at 
> >> >>> org.apache.http.impl.io.AbstractMessageParser.parse(AbstractMessa
> >> >>> geParser.java:254) at 
> >> >>> org.apache.http.impl.AbstractHttpClientConnection.receiveResponse
> >> >>> Header(AbstractHttpClientConnection.java:289)
> >> >>> at 
> >> >>> org.apache.http.impl.conn.DefaultClientConnection.receiveResponse
> >> >>> Header(DefaultClientConnection.java:252)
> >> >>> at 
> >> >>> org.apache.http.impl.conn.ManagedClientConnectionImpl.receiveResp
> >> >>> onseHeader(ManagedClientConnectionImpl.java:191)
> >> >>> at 
> >> >>> org.apache.http.protocol.HttpRequestExecutor.doReceiveResponse(Ht
> >> >>> tpRequestExecutor.java:300) at 
> >> >>> org.apache.http.protocol.HttpRequestExecutor.execute(HttpRequestE
> >> >>> xecutor.java:127) at 
> >> >>> org.apache.http.impl.client.DefaultRequestDirector.tryExecute(Def
> >> >>> aultRequestDirector.java:713) at 
> >> >>> org.apache.http.impl.client.DefaultRequestDirector.execute(Defaul
> >> >>> tRequestDirector.java:518) at 
> >> >>> org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHt
> >> >>> tpClient.java:906) at 
> >> >>> org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHt
> >> >>> tpClient.java:805) at 
> >> >>> com.edicom.edicomnet.asxserver.logic.as2.impl.As2MessageSenderImp
> >> >>> l.sendMessage(As2MessageSenderImpl.java:117)
> >> >>> at sun.reflect.GeneratedMethodAccessor575.invoke(Unknown Source)

> >> >>> at 
> >> >>> sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodA
> >> >>> ccessorImpl.java:25) at 
> >> >>> java.lang.reflect.Method.invoke(Method.java:597)
> >> >>> at 
> >> >>> org.springframework.aop.support.AopUtils.invokeJoinpointUsingRefl
> >> >>> ection(AopUtils.java:309) at 
> >> >>> org.springframework.aop.framework.ReflectiveMethodInvocation.invo
> >> >>> keJoinpoint(ReflectiveMethodInvocation.java:183)
> >> >>> at 
> >> >>> org.springframework.aop.framework.ReflectiveMethodInvocation.proc
> >> >>> eed(ReflectiveMethodInvocation.java:150)
> >> >>> at 
> >> >>> org.springframework.transaction.interceptor.TransactionIntercepto
> >> >>> r.invoke(TransactionInterceptor.java:110)
> >> >>> at 
> >> >>> org.springframework.aop.framework.ReflectiveMethodInvocation.proc
> >> >>> eed(ReflectiveMethodInvocation.java:172)
> >> >>> at 
> >> >>> org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDy
> >> >>> namicAopProxy.java:202) at $Proxy52.sendMessage(Unknown Source)

> >> >>> at 
> >> >>> com.edicom.edicomnet.asxserver.businessServices.impl.MessageSende
> >> >>> rImpl.sendCreatedAS2Message(MessageSenderImpl.java:119)
> >> >>> at sun.reflect.GeneratedMethodAccessor551.invoke(Unknown Source)

> >> >>> at 
> >> >>> sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodA
> >> >>> ccessorImpl.java:25) at 
> >> >>> java.lang.reflect.Method.invoke(Method.java:597)
> >> >>> at 
> >> >>> org.springframework.aop.support.AopUtils.invokeJoinpointUsingRefl
> >> >>> ection(AopUtils.java:309) at 
> >> >>> org.springframework.aop.framework.ReflectiveMethodInvocation.invo
> >> >>> keJoinpoint(ReflectiveMethodInvocation.java:183)
> >> >>> at 
> >> >>> org.springframework.aop.framework.ReflectiveMethodInvocation.proc
> >> >>> eed(ReflectiveMethodInvocation.java:150)
> >> >>> at 
> >> >>> org.springframework.aop.interceptor.AsyncExecutionInterceptor$1.c
> >> >>> all(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(ThreadPool
> >> >>> Executor.java:886) at 
> >> >>> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExec
> >> >>> utor.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
> 
> 
> ---------------------------------------------------------------------
> 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