[
https://issues.apache.org/jira/browse/CXF-5762?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14251784#comment-14251784
]
Oleg Kalnichevski commented on CXF-5762:
----------------------------------------
Nothing I could think of. I am not sure what might be causing the exception
below though but it appears to be related to state management in
SharedOutputBuffer, which looks CXF specific to me.
{noformat}
java.lang.IllegalStateException: Buffer already closed for writing
at
org.apache.cxf.transport.http.asyncclient.SharedOutputBuffer.write(SharedOutputBuffer.java:231)
at
org.apache.cxf.transport.http.asyncclient.AsyncHTTPConduit$AsyncWrappedOutputStream$1.write(AsyncHTTPConduit.java:397)
at java.io.ByteArrayOutputStream.writeTo(ByteArrayOutputStream.java:154)
at
org.apache.cxf.io.CachedOutputStream.writeCacheTo(CachedOutputStream.java:312)
at
org.apache.cxf.transport.http.asyncclient.AsyncHTTPConduit$AsyncWrappedOutputStream.close(AsyncHTTPConduit.java:379)
{noformat}
Oleg
> 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)
