[
https://issues.apache.org/jira/browse/CXF-5763?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14020791#comment-14020791
]
Anthony Communier commented on CXF-5763:
----------------------------------------
Since I have changed the UseAsyncPolicy to NEVER I do see this error anymore.
It seems that it occurs only when Apache HttpAsyncClient.(4.0.1) is used.
It occurs when response is sent back to the client.
In the log, the request has the id 75 (pattern in log => ID: 75)
The request is sent at 14:03:40.928. The response is sent back at 14:03:40.934 :
14:03:40.934 [default-workqueue-3] INFO o.a.c.i.LoggingInInterceptor - Inbound
Message
----------------------------
ID: 75
Address: http://localhost:41446/amp-interface/unsubscribe
Http-Method: POST
Content-Type: text/plain
Headers: {Accept=[application/xml], Content-Type=[text/plain],
Connection=[Keep-Alive]}
--------------------------------------
14:03:40.934 [default-workqueue-3] DEBUG o.a.cxf.phase.PhaseInterceptorChain -
Invoking handleMessage on interceptor
org.apache.cxf.jaxrs.client.spec.ClientResponseFilterInterceptor@ef09ea4
14:03:40.934 [I/O dispatcher 2] DEBUG
o.a.h.i.n.c.ManagedNHttpClientConnectionImpl - http-outgoing-19
127.0.0.1:58580<->127.0.0.1:41446[ACTIVE][rw:rw]: Shutdown
14:03:40.934 [default-workqueue-3] DEBUG o.a.cxf.phase.PhaseInterceptorChain -
Invoking handleMessage on interceptor
org.apache.cxf.jaxrs.client.WebClient$ClientAsyncResponseInterceptor@1fa68516
14:03:40.935 [I/O dispatcher 2] DEBUG o.a.h.i.n.c.InternalHttpAsyncClient -
[exchange: 53] connection aborted
14:03:40.935 [I/O dispatcher 2] DEBUG
o.a.h.i.n.c.PoolingNHttpClientConnectionManager - Releasing connection: [id:
http-outgoing-19][route: {}->http://localhost:41446][total kept alive: 1; route
allocated: 1 of 1000; total allocated: 2 of 5000]
14:03:40.935 [default-workqueue-3] INFO c.c.c.techstats.TechStatRepository -
Counter ready to be closed : AMP_UNSUBSCRIBE_REQUEST
14:03:40.935 [I/O dispatcher 2] DEBUG
o.a.h.i.n.c.PoolingNHttpClientConnectionManager - Connection released: [id:
http-outgoing-19][route: {}->http://localhost:41446][total kept alive: 1; route
allocated: 0 of 1000; total allocated: 1 of 5000]
14:03:40.935 [I/O dispatcher 2] DEBUG o.a.h.n.p.HttpAsyncRequestExecutor -
http-outgoing-19 [CLOSED]: Disconnected
It seems that 2 threads are processing the request at the same time : [I/O
dispatcher 2] and [default-workqueue-3].
On HttpAsync side the http flow is identified by pattern : exchange: 53
1760: 14:03:40.928 [AMP-1] DEBUG o.a.h.impl.nio.client.MainClientExec -
[exchange: 53] start execution
1763: 14:03:40.929 [AMP-1] DEBUG o.a.h.i.n.c.InternalHttpAsyncClient -
[exchange: 53] Request connection for {}->http://localhost:41446
1766: 14:03:40.929 [AMP-1] DEBUG o.a.h.i.n.c.InternalHttpAsyncClient -
[exchange: 53] Connection allocated: http-outgoing-19 [ACTIVE]
1770: 14:03:40.931 [I/O dispatcher 2] DEBUG
o.a.h.impl.nio.client.MainClientExec - [exchange: 53] Attempt 1 to execute
request
1783: 14:03:40.931 [I/O dispatcher 2] DEBUG
o.a.h.impl.nio.client.MainClientExec - [exchange: 53] produce content
1827: 14:03:40.935 [I/O dispatcher 2] DEBUG o.a.h.i.n.c.InternalHttpAsyncClient
- [exchange: 53] connection aborted
There is another flow that worked : pattern => exchange: 52 and pattern ID: 74
1597: 14:03:40.900 [AMP-1] DEBUG o.a.h.impl.nio.client.MainClientExec -
[exchange: 52] start execution
1600: 14:03:40.900 [AMP-1] DEBUG o.a.h.i.n.c.InternalHttpAsyncClient -
[exchange: 52] Request connection for {}->http://localhost:41446
1603: 14:03:40.903 [I/O dispatcher 2] DEBUG o.a.h.i.n.c.InternalHttpAsyncClient
- [exchange: 52] Connection allocated: http-outgoing-19 [ACTIVE]
1611: 14:03:40.904 [I/O dispatcher 2] DEBUG
o.a.h.impl.nio.client.MainClientExec - [exchange: 52] Attempt 1 to execute
request
1624: 14:03:40.905 [I/O dispatcher 2] DEBUG
o.a.h.impl.nio.client.MainClientExec - [exchange: 52] produce content
1625: 14:03:40.905 [I/O dispatcher 2] DEBUG
o.a.h.impl.nio.client.MainClientExec - [exchange: 52] Request completed
1657: 14:03:40.912 [I/O dispatcher 2] DEBUG
o.a.h.impl.nio.client.MainClientExec - [exchange: 52] Response received
HTTP/1.1 200 OK
1659: 14:03:40.912 [I/O dispatcher 2] DEBUG
o.a.h.impl.nio.client.MainClientExec - [exchange: 52] Consume content
1660: 14:03:40.913 [I/O dispatcher 2] DEBUG
o.a.h.impl.nio.client.MainClientExec - [exchange: 52] Connection can be kept
alive indefinitely
1662: 14:03:40.913 [I/O dispatcher 2] DEBUG
o.a.h.impl.nio.client.MainClientExec - [exchange: 52] Response processed
1663: 14:03:40.913 [I/O dispatcher 2] DEBUG o.a.h.i.n.c.InternalHttpAsyncClient
- [exchange: 52] releasing connection
The difference is that the the connection was aborted.
> ClassCast Exception in AsyncHTTPConduit$AsyncWrappedOutputStream.close()
> method when using async and HttpAsyncClient
> ---------------------------------------------------------------------------------------------------------------------
>
> Key: CXF-5763
> URL: https://issues.apache.org/jira/browse/CXF-5763
> Project: CXF
> Issue Type: Bug
> Components: Transports
> Affects Versions: 3.0.0
> Environment: Linux
> Java 7
> Reporter: Anthony Communier
> Assignee: Daniel Kulp
> Attachments: TestUnsubscribeSM-output.txt
>
>
> Sometimes there is an error on connection close when using async client
> javax.ws.rs.ProcessingException: java.lang.ClassCastException:
> org.apache.cxf.transport.http.asyncclient.AsyncHTTPConduit$AsyncWrappedOutputStream$1
> cannot be cast to org.apache.cxf.io.CachedOutputStream
> at
> org.apache.cxf.jaxrs.client.WebClient.handleAsyncResponse(WebClient.java:1010)
> [cxf-rt-rs-client-3.0.0.jar:3.0.0]
> at org.apache.cxf.jaxrs.client.WebClient.access$100(WebClient.java:81)
> [cxf-rt-rs-client-3.0.0.jar:3.0.0]
> at
> org.apache.cxf.jaxrs.client.WebClient$ClientAsyncResponseInterceptor.handleMessage(WebClient.java:1298)
> ~[cxf-rt-rs-client-3.0.0.jar:3.0.0]
> at
> org.apache.cxf.phase.PhaseInterceptorChain.doIntercept(PhaseInterceptorChain.java:307)
> ~[cxf-core-3.0.0.jar:3.0.0]
> at
> org.apache.cxf.jaxrs.client.ClientMessageObserver.onMessage(ClientMessageObserver.java:56)
> ~[cxf-rt-rs-client-3.0.0.jar:3.0.0]
> at
> org.apache.cxf.transport.http.HTTPConduit$WrappedOutputStream$1.run(HTTPConduit.java:1154)
> ~[cxf-rt-transports-http-3.0.0.jar:3.0.0]
> at
> org.apache.cxf.workqueue.AutomaticWorkQueueImpl$3.run(AutomaticWorkQueueImpl.java:428)
> ~[cxf-core-3.0.0.jar:3.0.0]
> at
> java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
> ~[na:1.7.0_25]
> at
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
> ~[na:1.7.0_25]
> at
> org.apache.cxf.workqueue.AutomaticWorkQueueImpl$AWQThreadFactory$1.run(AutomaticWorkQueueImpl.java:353)
> ~[cxf-core-3.0.0.jar:3.0.0]
> at java.lang.Thread.run(Thread.java:724) ~[na:1.7.0_25]
> Caused by: java.lang.ClassCastException:
> org.apache.cxf.transport.http.asyncclient.AsyncHTTPConduit$AsyncWrappedOutputStream$1
> cannot be cast to org.apache.cxf.io.CachedOutputStream
> at
> org.apache.cxf.transport.http.asyncclient.AsyncHTTPConduit$AsyncWrappedOutputStream.close(AsyncHTTPConduit.java:397)
> ~[cxf-rt-transports-http-hc-3.0.0.jar:3.0.0]
> at
> org.apache.cxf.transport.AbstractConduit.close(AbstractConduit.java:56)
> ~[cxf-core-3.0.0.jar:3.0.0]
> at
> org.apache.cxf.transport.http.HTTPConduit.close(HTTPConduit.java:638)
> ~[cxf-rt-transports-http-3.0.0.jar:3.0.0]
> at
> org.apache.cxf.endpoint.AbstractConduitSelector.complete(AbstractConduitSelector.java:209)
> ~[cxf-core-3.0.0.jar:3.0.0]
> at
> org.apache.cxf.jaxrs.client.AbstractClient.preProcessResult(AbstractClient.java:534)
> ~[cxf-rt-rs-client-3.0.0.jar:3.0.0]
> at
> org.apache.cxf.jaxrs.client.WebClient.handleAsyncResponse(WebClient.java:1005)
> [cxf-rt-rs-client-3.0.0.jar:3.0.0]
> ... 10 common frames omitted
--
This message was sent by Atlassian JIRA
(v6.2#6252)
