[
https://issues.apache.org/jira/browse/CXF-5762?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14246335#comment-14246335
]
P Roy commented on CXF-5762:
----------------------------
Finally we figured out the steps to replicate similar issue in any development
environment. Here are the steps that we followed:-
1) Set read-timeout = 5000ms, SoapUI mock service response delay = 4900ms,
select interval as default i.e. 1000ms
2) With above settings when we triggered several requests, we noticed behavior
as follows -
a) Once request is sent successfully, it waits for a response and after
around 4800ms AsyncHTTPConduit shuts shared input/output buffer down and throws
a SocketTimeoutException. Incidentally, connection and associated IOSession are
still active at that time and are waiting to be closed by timeout check
initiated by IOReactor.
b) At around 4900ms, IODispatcher receives the 1st slice of chunk response
and as response is not fully arrived yet, it makes ChunkDecoder's complete flag
as 'false'.
c) Then it invokes SharedInputBuffer.consumeContent() to read contents
from ContentDecoder to buffer. But it finds that buffer is already down and so
it shuts the connection down and return from the method.
if (this.shutdown) {
89 //something bad happened, we need to shutdown the connection
90 //as we're not going to read the data at all and we
91 //don't want to keep getting read notices and such
92 ioc.shutdown();
93 return -1;
94 }
d) Control returns to HttpAsyncRequestExecutor.inputReady() where it checks if
decoder.isCompleted() = true and if yes then calls processResponse which in
turn releases the connection. But as the complete ContentDecoder.complete =
false, in given case code never executes processResponse and therefore releases
connection back to pool.
To resolve this issue, we just updated below 'IF' check in
HttpAsyncRequestExecutor.inputReady() to add a verification on connection as
follows -
if (decoder.isCompleted() || !conn.isOpen()) {
processResponse(conn, state, handler);
}
Same has been done for HttpAsyncRequestExecutor.outputReady method.
Post change we see that connection is gracefully released even for above race
condition and it doesn't introduce connection pool lock any more.
> Connection leak after SocketTimeoutException using Asynchronous Client HTTP
> Transport
> -------------------------------------------------------------------------------------
>
> Key: CXF-5762
> URL: https://issues.apache.org/jira/browse/CXF-5762
> Project: CXF
> Issue Type: Bug
> Components: Transports
> Affects Versions: 2.7.11
> Environment: SunOS 5.10 Generic_147440-25 sun4v sparc
> SUNW,SPARC-Enterprise-T5120, 64bit
> Reporter: Przemysław Ołtarzewski
>
> We are using CXF with Async HTTP Transport to call web services of another
> system (about 15000 requests per day). Some messages sent each day end in
> SocketTimeoutException. About 15-30 out of them cause connection leak (logs
> provided below).
> {noformat}
> 2014.05.23 08:27:26.801
> org.apache.cxf.services.SubscriberLineManagerPortTypeService.SubscriberLineManagerPortTypePort.SubscriberLineManagerPortType
> INFO [HLAPI-68] AbstractLoggingInterceptor:239 Outbound Message
> ---------------------------
> ID: 277
> Address:
> http://10.250.32.140:8082/HighLevelApiWS-2.4/services/SubscriberLineManager
> Encoding: UTF-8
> Http-Method: POST
> Content-Type: text/xml
> Headers: {Accept=[*/*], Connection=[Keep-Alive], SOAPAction=["urn:getAll"]}
> Payload: <?xml version="1.0" encoding="UTF-8"?>
> <soap:Envelope xmlns:soap="http://schemas.xmlsoap.org/soap/envelope/";>
> <soap:Body>
> <ns2:getAll
> xmlns="http://pojo.web.api.icc.services.osp.in.alcatel.com/xsd";
> xmlns:ns2="http://implementation.web.api.icc.services.osp.in.alcatel.com";
> xmlns:ns3="http://web.api.icc.services.osp.in.alcatel.com/xsd";
> xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance";>
> <ns2:subscriberLineId>
> <ceSepGroupName xsi:nil="true"/>
> <communityId xsi:nil="true"/>
> <platformName xsi:nil="true"/>
> <serviceRetailerName>HEYAH</serviceRetailerName>
> <subscriberLineId>0048888522289</subscriberLineId>
> <subscriberLineIdType>1</subscriberLineIdType>
> <validityDate xsi:nil="true"/>
> </ns2:subscriberLineId>
> <ns2:additionalParameters>
> <chargingCommand xsi:nil="true"/>
> <depth>1</depth>
> <extCorrelationIdentifier>71001465||</extCorrelationIdentifier>
> </ns2:additionalParameters>
> </ns2:getAll>
> </soap:Body>
> </soap:Envelope>
> --------------------------------------
> 2014.05.23 08:27:26.802
> org.apache.cxf.transport.http.asyncclient.AsyncHTTPConduitFactory$3 DEBUG
> [HLAPI-68] DefaultAsyncRequestDirector:208 [exchange: 277] start execution
> 2014.05.23 08:27:26.803
> org.apache.cxf.transport.http.asyncclient.AsyncHTTPConduitFactory$3 DEBUG
> [HLAPI-68] DefaultAsyncRequestDirector:625 [exchange: 277] Request connection
> for {}->http://10.250.32.140:8082
> 2014.05.23 08:27:26.804
> org.apache.cxf.transport.http.asyncclient.AsyncHTTPConduitFactory$2 DEBUG
> [HLAPI-68] PoolingClientAsyncConnectionManager:172 Connection request:
> [route: {}->http://10.250.32.140:8082][total kept alive: 2; route allocated:
> 2 of 1000; total allocated: 2 of 5000]
> 2014.05.23 08:27:26.805
> org.apache.cxf.transport.http.asyncclient.AsyncHTTPConduitFactory$2 DEBUG
> [HLAPI-68] PoolingClientAsyncConnectionManager$InternalPoolEntryCallback:297
> Connection leased: [id: 72][route: {}->http://10.250.32.140:8082][total kept
> alive: 1; route allocated: 2 of 1000; total allocated: 2 of 5000]
> 2014.05.23 08:27:26.805
> org.apache.cxf.transport.http.asyncclient.AsyncHTTPConduitFactory$3 DEBUG
> [HLAPI-68] DefaultAsyncRequestDirector:558 [exchange: 277] Connection
> allocated: [id:72][route:{}->http://10.250.32.140:8082][state:null]
> 2014.05.23 08:27:46.838 org.apache.cxf.phase.PhaseInterceptorChain WARN
> [HLAPI-68] LogUtils:452 Interceptor for
> {http://implementation.web.api.icc.services.osp.in.alcatel.com}SubscriberLineM
> anagerPortTypeService#{http://implementation.web.api.icc.services.osp.in.alcatel.com}getAll
> has thrown exception, unwinding now
> org.apache.cxf.interceptor.Fault: Could not send Message.
> at
> org.apache.cxf.interceptor.MessageSenderInterceptor$MessageSenderEndingInterceptor.handleMessage(MessageSenderInterceptor.java:64)
> at
> org.apache.cxf.phase.PhaseInterceptorChain.doIntercept(PhaseInterceptorChain.java:272)
> at org.apache.cxf.endpoint.ClientImpl.doInvoke(ClientImpl.java:570)
> at org.apache.cxf.endpoint.ClientImpl.invoke(ClientImpl.java:479)
> at org.apache.cxf.endpoint.ClientImpl.invoke(ClientImpl.java:382)
> at org.apache.cxf.endpoint.ClientImpl.invoke(ClientImpl.java:335)
> at org.apache.cxf.frontend.ClientProxy.invokeSync(ClientProxy.java:96)
> at
> org.apache.cxf.jaxws.JaxWsClientProxy.invoke(JaxWsClientProxy.java:135)
> at $Proxy88.getAll(Unknown Source)
> at sun.reflect.GeneratedMethodAccessor42.invoke(Unknown Source)
> at
> sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
> at java.lang.reflect.Method.invoke(Method.java:597)
> at
> pl.infovide.inconfig.bep.backend.hlapi.HlapiCommunicator.send(HlapiCommunicator.java:212)
> at
> pl.infovide.inconfig.bep.backend.hlapi.HlapiBackend.send(HlapiBackend.java:26)
> at
> pl.infovide.inconfig.bep.backend.unified.UnifiedBackendImpl.forwardRequest(UnifiedBackendImpl.java:230)
> at
> pl.infovide.inconfig.bep.backend.unified.UnifiedBackendImpl.access$000(UnifiedBackendImpl.java:34)
> at
> pl.infovide.inconfig.bep.backend.unified.UnifiedBackendImpl$SenderTask.run(UnifiedBackendImpl.java:316)
> 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)
> Caused by: java.net.SocketTimeoutException: SocketTimeoutException invoking
> http://10.250.32.140:8082/HighLevelApiWS-2.4/services/SubscriberLineManager:
> Read Timeout
> at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native
> Method)
> at
> sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:39)
> at
> sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:27)
> at java.lang.reflect.Constructor.newInstance(Constructor.java:513)
> at
> org.apache.cxf.transport.http.HTTPConduit$WrappedOutputStream.mapException(HTTPConduit.java:1347)
> at
> org.apache.cxf.transport.http.HTTPConduit$WrappedOutputStream.close(HTTPConduit.java:1331)
> at
> org.apache.cxf.transport.http.asyncclient.AsyncHTTPConduit$AsyncWrappedOutputStream.close(AsyncHTTPConduit.java:383)
> at
> org.apache.cxf.io.CacheAndWriteOutputStream.postClose(CacheAndWriteOutputStream.java:56)
> at
> org.apache.cxf.io.CachedOutputStream.close(CachedOutputStream.java:223)
> at
> org.apache.cxf.transport.AbstractConduit.close(AbstractConduit.java:56)
> at
> org.apache.cxf.transport.http.HTTPConduit.close(HTTPConduit.java:632)
> at
> org.apache.cxf.interceptor.MessageSenderInterceptor$MessageSenderEndingInterceptor.handleMessage(MessageSenderInterceptor.java:62)
> ... 19 common frames omitted
> Caused by: java.net.SocketTimeoutException: Read Timeout
> at
> org.apache.cxf.transport.http.asyncclient.AsyncHTTPConduit$AsyncWrappedOutputStream.getHttpResponse(AsyncHTTPConduit.java:583)
> at
> org.apache.cxf.transport.http.asyncclient.AsyncHTTPConduit$AsyncWrappedOutputStream.getResponseCode(AsyncHTTPConduit.java:674)
> at
> org.apache.cxf.transport.http.HTTPConduit$WrappedOutputStream.handleResponseInternal(HTTPConduit.java:1543)
> at
> org.apache.cxf.transport.http.HTTPConduit$WrappedOutputStream.handleResponse(HTTPConduit.java:1513)
> at
> org.apache.cxf.transport.http.HTTPConduit$WrappedOutputStream.close(HTTPConduit.java:1318)
> ... 25 common frames omitted
> {noformat}
> The connection allocated (id: 72) is never released to the connection pool.
> The main detail about scenario that causes the connection leak is no further
> activity during the exchange after connection allocation. In particular,
> there is no indication that the request processing has even started - the
> following line is missing from log (copied from correct exchange):
> {noformat}
> 2014.05.23 12:15:32.372
> org.apache.cxf.transport.http.asyncclient.AsyncHTTPConduitFactory$3 DEBUG
> [I/O dispatcher 18] DefaultAsyncRequestDirector:313 [exchange: 5144] Attempt
> 1 to execute request
> {noformat}
> In other cases with the same exception, there are some bytes sent / events
> set on the exchange etc. and the connection is correctly aborted afterwards,
> but in this specific case the connection just leaks silently. Leaked
> connections accumulate in the pool and after some time make it unusable.
> Relevant configuration parameters:
> ReceiveTimeout=20000
> ConnectionTimeout=20000
> use.async.http.conduit=true
> Keep-alive time is 5000 ms.
> The problem is critical since with pool size of 1000 connections per route
> and using a single route, we are forced to restart our service every 1-2
> months and are unable to provide high availability requested by our business
> client.
> A workaround for us would be to use the default, synchronous HTTP Transport,
> however we have noticed that sometimes it attempts to send a request via a
> connection that is already half-closed by the server side. Has this issue
> been diagnosed / fixed?
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
