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: [email protected] 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 <[email protected]>: > 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 <[email protected]>: >> Do you have the wire logs? >> >> Bill- >> >> On Mon, Oct 15, 2012 at 7:23 AM, Jose Escobar <[email protected]> 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: [email protected] >>> For additional commands, e-mail: [email protected] >>> >> >> --------------------------------------------------------------------- >> To unsubscribe, e-mail: [email protected] >> For additional commands, e-mail: [email protected] >> --------------------------------------------------------------------- To unsubscribe, e-mail: [email protected] For additional commands, e-mail: [email protected]
