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: > [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] > --------------------------------------------------------------------- To unsubscribe, e-mail: [email protected] For additional commands, e-mail: [email protected]
