Przemysław Ołtarzewski created CXF-5762:
-------------------------------------------
Summary: 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 memory leak is no further
activity during the exchange (see exchange: 277) after connection allocation.
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.2#6252)
