Mailing-List: contact issues-help@cxf.apache.org; run by ezmlm
Precedence: bulk
Reply-To: dev@cxf.apache.org
Date: Thu, 23 Mar 2017 17:09:41 +0000 (UTC)
From: "Daniel Kulp (JIRA)" <jira@apache.org>
To: issues@cxf.apache.org
Message-ID: <JIRA.12705990.1396368067000.103767.1490288981896@Atlassian.JIRA>
In-Reply-To: <JIRA.12705990.1396368067000@Atlassian.JIRA>
References: <JIRA.12705990.1396368067000@Atlassian.JIRA> <JIRA.12705990.1396368067577@jira-lw-us.apache.org>
Subject: [jira] [Resolved] (CXF-5663) IllegalStateException using
 AsyncHTTPConduit
MIME-Version: 1.0
Content-Type: text/plain; charset=utf-8
Content-Transfer-Encoding: quoted-printable
archived-at: Thu, 23 Mar 2017 17:09:49 -0000


     [ https://issues.apache.org/jira/browse/CXF-5663?page=3Dcom.atlassian.=
jira.plugin.system.issuetabpanels:all-tabpanel ]

Daniel Kulp resolved CXF-5663.
------------------------------
       Resolution: Fixed
    Fix Version/s: 3.1.10


Suspect that this is already fixed, request for confirmation unanswered.=20

> IllegalStateException using AsyncHTTPConduit
> --------------------------------------------
>
>                 Key: CXF-5663
>                 URL: https://issues.apache.org/jira/browse/CXF-5663
>             Project: CXF
>          Issue Type: Bug
>          Components: Transports
>    Affects Versions: 2.7.10
>         Environment: SunOS 5.10 Generic_147440-25 sun4v sparc SUNW,SPARC-=
Enterprise-T5120, 64bit
>            Reporter: Przemys=C5=82aw O=C5=82tarzewski
>            Assignee: Freeman Fang
>             Fix For: 3.1.10
>
>
> We are using CXF with Async HTTP Transport to call web services of anothe=
r system. Every once in a while an attempt to send request ends in IllegalS=
tateException - Buffer already closed for writing (logs provided below).
> {noformat}
> 2014.04.01 10:47:22.601 org.apache.cxf.transport.http.asyncclient.AsyncHT=
TPConduitFactory$3 DEBUG [HLAPI-47] DefaultAsyncRequestDirector:208 [exchan=
ge: 5663] start execution
> 2014.04.01 10:47:22.601 org.apache.cxf.transport.http.asyncclient.AsyncHT=
TPConduitFactory$3 DEBUG [HLAPI-47] DefaultAsyncRequestDirector:625 [exchan=
ge: 5663] Request connection for {}->http://10.250.32.140:8082
> 2014.04.01 10:47:22.602 org.apache.cxf.transport.http.asyncclient.AsyncHT=
TPConduitFactory$2 DEBUG [HLAPI-47] PoolingClientAsyncConnectionManager:172=
 Connection request: [route: {}->http://10.250.32.140:8082][total kept aliv=
e: 2; route allocated: 2 of 1000; total allocated: 2 of 5000]
> 2014.04.01 10:47:22.603 org.apache.cxf.transport.http.asyncclient.AsyncHT=
TPConduitFactory$2 DEBUG [HLAPI-47] PoolingClientAsyncConnectionManager$Int=
ernalPoolEntryCallback:297 Connection leased: [id: 1746][route: {}->http://=
10.250.32.140:8082][total kept alive: 1; route allocated: 2 of 1000; total =
allocated: 2 of 5000]
> 2014.04.01 10:47:22.604 org.apache.cxf.transport.http.asyncclient.AsyncHT=
TPConduitFactory$3 DEBUG [HLAPI-47] DefaultAsyncRequestDirector:558 [exchan=
ge: 5663] Connection allocated: [id:1746][route:{}->http://10.250.32.140:80=
82][state:null]
> 2014.04.01 10:47:22.625 org.apache.http.impl.nio.reactor.IOSessionImpl DE=
BUG [I/O dispatcher 18] LoggingIOSession$LoggingByteChannel:189 http-outgoi=
ng-1746 10.252.152.177:65127<->10.250.32.140:8082[ACTIVE][r:r]: -1 bytes re=
ad
> 2014.04.01 10:47:22.625 org.apache.http.impl.nio.reactor.IOSessionImpl DE=
BUG [HLAPI-47] LoggingIOSession:167 http-outgoing-1746 10.252.152.177:65127=
<->10.250.32.140:8082[ACTIVE][r:r]: Set attribute http.nio.exchange-handler
> 2014.04.01 10:47:22.626 org.apache.http.impl.nio.reactor.IOSessionImpl DE=
BUG [I/O dispatcher 18] LoggingIOSession:118 http-outgoing-1746 10.252.152.=
177:65127<->10.250.32.140:8082[ACTIVE][r:r]: Close
> 2014.04.01 10:47:22.626 org.apache.http.impl.nio.reactor.IOSessionImpl DE=
BUG [HLAPI-47] LoggingIOSession:105 http-outgoing-1746 10.252.152.177:65127=
<->10.250.32.140:8082[CLOSED][]: Event set [w]
> 2014.04.01 10:47:22.628 org.apache.cxf.transport.http.asyncclient.AsyncHT=
TPConduitFactory$3 DEBUG [HLAPI-47] DefaultAsyncRequestDirector:185 [exchan=
ge: 5663] aborting connection [id:1746][route:{}->http://10.250.32.140:8082=
][state:null]
> 2014.04.01 10:47:22.629 org.apache.http.impl.nio.reactor.IOSessionImpl DE=
BUG [HLAPI-47] LoggingIOSession:133 http-outgoing-1746 [CLOSED][]: Shutdown
> 2014.04.01 10:47:22.629 org.apache.http.impl.nio.reactor.IOSessionImpl DE=
BUG [HLAPI-47] LoggingIOSession:133 http-outgoing-1746 [CLOSED][]: Shutdown
> 2014.04.01 10:47:22.630 org.apache.cxf.transport.http.asyncclient.AsyncHT=
TPConduitFactory$2 DEBUG [HLAPI-47] PoolingClientAsyncConnectionManager:236=
 Connection released: [id: 1746][route: {}->http://10.250.32.140:8082][tota=
l kept alive: 1; route allocated: 1 of 1000; total allocated: 1 of 5000]
> 2014.04.01 10:47:22.642 org.apache.cxf.phase.PhaseInterceptorChain WARN  =
[HLAPI-47] LogUtils:452 Interceptor for {http://implementation.web.api.icc.=
services.osp.in.alcatel.com}SubscriberLineManagerPortTypeService#{http://im=
plementation.web.api.icc.services.osp.in.alcatel.com}getAll has thrown exce=
ption, unwinding now
> java.lang.IllegalStateException: IllegalStateException invoking http://10=
.250.32.140:8082/HighLevelApiWS-2.4/services/SubscriberLineManager: Buffer =
already closed for writing
>         at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native =
Method)
>         at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeCo=
nstructorAccessorImpl.java:39)
>         at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(Dele=
gatingConstructorAccessorImpl.java:27)
>         at java.lang.reflect.Constructor.newInstance(Constructor.java:513=
)
>         at org.apache.cxf.transport.http.HTTPConduit$WrappedOutputStream.=
mapException(HTTPConduit.java:1339)
>         at org.apache.cxf.transport.http.HTTPConduit$WrappedOutputStream.=
close(HTTPConduit.java:1328)
>         at org.apache.cxf.transport.http.asyncclient.AsyncHTTPConduit$Asy=
ncWrappedOutputStream.close(AsyncHTTPConduit.java:381)
>         at org.apache.cxf.io.CacheAndWriteOutputStream.postClose(CacheAnd=
WriteOutputStream.java:50)
>         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.ja=
va:628)
>         at org.apache.cxf.interceptor.MessageSenderInterceptor$MessageSen=
derEndingInterceptor.handleMessage(MessageSenderInterceptor.java:62)
>         at org.apache.cxf.phase.PhaseInterceptorChain.doIntercept(PhaseIn=
terceptorChain.java:272)
>         at org.apache.cxf.endpoint.ClientImpl.doInvoke(ClientImpl.java:56=
5)
>         at org.apache.cxf.endpoint.ClientImpl.invoke(ClientImpl.java:474)
>         at org.apache.cxf.endpoint.ClientImpl.invoke(ClientImpl.java:377)
>         at org.apache.cxf.endpoint.ClientImpl.invoke(ClientImpl.java:330)
>         at org.apache.cxf.frontend.ClientProxy.invokeSync(ClientProxy.jav=
a:96)
>         at org.apache.cxf.jaxws.JaxWsClientProxy.invoke(JaxWsClientProxy.=
java:135)
>         at $Proxy89.getAll(Unknown Source)
>         at sun.reflect.GeneratedMethodAccessor38.invoke(Unknown Source)
>         at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMeth=
odAccessorImpl.java:25)
>         at java.lang.reflect.Method.invoke(Method.java:597)
>         at pl.infovide.inconfig.bep.backend.hlapi.HlapiCommunicator.send(=
HlapiCommunicator.java:236)
>         at pl.infovide.inconfig.bep.backend.hlapi.HlapiBackend.send(Hlapi=
Backend.java:26)
>         at pl.infovide.inconfig.bep.backend.unified.UnifiedBackendImpl.fo=
rwardRequest(UnifiedBackendImpl.java:194)
>         at pl.infovide.inconfig.bep.backend.unified.UnifiedBackendImpl.ac=
cess$000(UnifiedBackendImpl.java:29)
>         at pl.infovide.inconfig.bep.backend.unified.UnifiedBackendImpl$Se=
nderTask.run(UnifiedBackendImpl.java:276)
>         at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadP=
oolExecutor.java:886)
>         at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolE=
xecutor.java:908)
>         at java.lang.Thread.run(Thread.java:662)
> Caused by: java.lang.IllegalStateException: Buffer already closed for wri=
ting
>         at org.apache.cxf.transport.http.asyncclient.SharedOutputBuffer.w=
rite(SharedOutputBuffer.java:231)
>         at org.apache.cxf.transport.http.asyncclient.AsyncHTTPConduit$Asy=
ncWrappedOutputStream$1.write(AsyncHTTPConduit.java:397)
>         at org.apache.cxf.io.AbstractWrappedOutputStream.write(AbstractWr=
appedOutputStream.java:51)
>         at org.apache.cxf.io.AbstractThresholdOutputStream.write(Abstract=
ThresholdOutputStream.java:69)
>         at org.apache.cxf.transport.http.HTTPConduit$WrappedOutputStream.=
close(HTTPConduit.java:1296)
>         ... 25 common frames omitted
> {noformat}
> We are unable to provide a test-case since the problem is indeterministic=
. Roughly 10-20 out of ~14000 requests a day end this way.
> We will probably apply a workaround by catching the exception and retryin=
g the request, however CXF's behavior in this case doesn't seem to be valid=
.


--
This message was sent by Atlassian JIRA
(v6.3.15#6346)