[
https://issues.apache.org/jira/browse/CXF-9140?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17953912#comment-17953912
]
Andriy Redko commented on CXF-9140:
-----------------------------------
[~lukexu_infor] thanks for details, do you by any chance have a reproducer for
it? Or if you some hints fe does it happen at random or on first / second call
fe? Thank you
> WebClient.invoke() hang with connection Keep-Alive
> --------------------------------------------------
>
> Key: CXF-9140
> URL: https://issues.apache.org/jira/browse/CXF-9140
> Project: CXF
> Issue Type: Bug
> Components: JAX-RS
> Affects Versions: 4.0.6
> Reporter: Luke Xu
> Priority: Major
>
> Our client got hung after WebClient.invoke() at a rate of around 1%. The
> Allow Chunking option can't workaround the issue. But closing Connection
> Keep-alive can avoid the issue with a performance penalty.
> We use HC5 client binding and have upgraded httpclient5 to 5.4.4 and
> httpcore5 to 5.3.4. This can be related to HTTPCORE-775, CXF-9098, and
> CXF-9093. But it seems the core side hasn't fully resolved the issue.
> The hanging stack, when attached to a debugger, looks like the following.
> There is a wait() without any timeout in
> AsyncHTTPConduit$AsyncWrappedOutputStream that caused the deadlock.
> I know it's not CXF side's fault to lose the callback in an outbound request.
> But deadlock is much worse for a backend application like ours than
> duplicated requests. Besides, developers here seem to be much more familiar
> with HC5 than us to locate what's wrong there and report.
>
> {code:java}
> wait:-1, Object (java.lang)
> wait:-1, Object (java.lang)
> getHttpResponse:684, AsyncHTTPConduit$AsyncWrappedOutputStream
> (org.apache.cxf.transport.http.asyncclient.hc5)
> getResponseCode:784, AsyncHTTPConduit$AsyncWrappedOutputStream
> (org.apache.cxf.transport.http.asyncclient.hc5)
> doProcessResponseCode:1653, HTTPConduit$WrappedOutputStream
> (org.apache.cxf.transport.http)
> handleResponseInternal:1684, HTTPConduit$WrappedOutputStream
> (org.apache.cxf.transport.http)
> handleResponse:1626, HTTPConduit$WrappedOutputStream
> (org.apache.cxf.transport.http)
> close:1420, HTTPConduit$WrappedOutputStream (org.apache.cxf.transport.http)
> close:444, AsyncHTTPConduit$AsyncWrappedOutputStream
> (org.apache.cxf.transport.http.asyncclient.hc5)
> close:77, AbstractWrappedOutputStream (org.apache.cxf.io)
> postClose:56, CacheAndWriteOutputStream (org.apache.cxf.io)
> close:232, CachedOutputStream (org.apache.cxf.io)
> close:56, AbstractConduit (org.apache.cxf.transport)
> close:717, HTTPConduit (org.apache.cxf.transport.http)
> close:261, HttpClientHTTPConduit (org.apache.cxf.transport.http)
> handleMessage:63, MessageSenderInterceptor$MessageSenderEndingInterceptor
> (org.apache.cxf.interceptor)
> doIntercept:307, PhaseInterceptorChain (org.apache.cxf.phase)
> doRunInterceptorChain:717, AbstractClient (org.apache.cxf.jaxrs.client)
> doChainedInvocation:1085, WebClient (org.apache.cxf.jaxrs.client)
> doInvoke:931, WebClient (org.apache.cxf.jaxrs.client)
> doInvoke:900, WebClient (org.apache.cxf.jaxrs.client)
> invoke:460, WebClient (org.apache.cxf.jaxrs.client) {code}
> Common logs we can get with HC5 and JDK before a hang
> {noformat}
> org.apache.cxf.transport.http.HTTPConduit$WrappedOutputStream
> makeTrustDecision:FINE: No Trust Decider for Conduit
> '{https://localhost:18084/FhirServer/baseR4}WebClient.http-conduit'. An
> affirmative Trust Decision is assumed.
> org.apache.hc.client5.http.impl.async.InternalAbstractHttpAsyncClient
> lambda$doExecute$0:FINE: ex-0000000865 preparing request execution
> org.apache.hc.client5.http.impl.async.AsyncProtocolExec internalExecute:FINE:
> ex-0000000865 proxy auth state: UNCHALLENGED
> org.apache.hc.client5.http.impl.async.AsyncConnectExec execute:FINE:
> ex-0000000865 acquiring connection with route
> {s}->https://healthlake.us-east-2.amazonaws.com:443
> org.apache.hc.client5.http.impl.async.InternalHttpAsyncExecRuntime
> acquireEndpoint:FINE: ex-0000000865 acquiring endpoint (60000 MILLISECONDS)
> org.apache.hc.client5.http.impl.nio.PoolingAsyncClientConnectionManager
> lease:FINE: ex-0000000865 endpoint lease request (60000 MILLISECONDS) [route:
> {s}->https://healthlake.us-east-2.amazonaws.com:443][total available: 1;
> route allocated: 1 of 1000; total allocated: 1 of 5000]
> org.apache.hc.client5.http.impl.nio.PoolingAsyncClientConnectionManager$3$1
> leaseCompleted:FINE: ex-0000000865 endpoint leased [route:
> {s}->https://healthlake.us-east-2.amazonaws.com:443][total available: 0;
> route allocated: 1 of 1000; total allocated: 1 of 5000]
> org.apache.hc.client5.http.impl.nio.PoolingAsyncClientConnectionManager$3$1
> leaseCompleted:FINE: ex-0000000865 acquired ep-0000000864
> org.apache.hc.client5.http.impl.async.InternalHttpAsyncExecRuntime$1
> completed:FINE: ex-0000000865 acquired endpoint ep-0000000864
> org.apache.hc.client5.http.impl.async.HttpAsyncMainClientExec execute:FINE:
> ex-0000000865 executing PUT
> /datastore/0c04d492787311f75eda4565b519225c/r4/Observation/123e8b61-14fd-9281-d336-064bfcfbff82
> HTTP/1.1
> org.apache.hc.client5.http.impl.async.InternalHttpAsyncExecRuntime
> execute:FINE: ep-0000000864 start execution ex-0000000865
> org.apache.hc.client5.http.impl.nio.PoolingAsyncClientConnectionManager$InternalConnectionEndpoint
> execute:FINE: ep-0000000864 executing exchange ex-0000000865 over
> c-0000000057
> org.apache.hc.client5.http.impl.nio.DefaultManagedAsyncClientConnection
> submitCommand:FINE: c-0000000057 RequestExecutionCommand with NORMAL priority
> org.apache.hc.client5.http.impl.async.LoggingIOSession clearEvent:FINE:
> c-0000000057[ACTIVE][r:w][ACTIVE][r][NOT_HANDSHAKING][0][0][0] Event cleared
> [w]
> org.apache.hc.client5.http.protocol.RequestAddCookies process:FINE:
> ex-0000000865 Cookie spec selected: strict
> org.apache.hc.client5.http.impl.async.LoggingAsyncClientExchangeHandler
> lambda$produceRequest$0:FINE: ex-0000000865 send request PUT
> /datastore/0c04d492787311f75eda4565b519225c/r4/Observation/123e8b61-14fd-9281-d336-064bfcfbff82
> HTTP/1.1, entity len 668
> org.apache.hc.client5.http.impl.async.HttpAsyncClientProtocolNegotiationStarter$1
> onRequestHead:FINE: c-0000000057 >> PUT
> /datastore/0c04d492787311f75eda4565b519225c/r4/Observation/123e8b61-14fd-9281-d336-064bfcfbff82
> HTTP/1.1
> org.apache.hc.client5.http.impl.async.LoggingIOSession enqueue:FINE:
> c-0000000057[ACTIVE][r:w][ACTIVE][r][NOT_HANDSHAKING][0][0][0] Enqueued
> RequestExecutionCommand with priority IMMEDIATE
> org.apache.hc.client5.http.impl.async.HttpAsyncClientProtocolNegotiationStarter$1
> onRequestHead:FINE: c-0000000057 >> Authorization: <Auth Header manually
> removed>
> org.apache.hc.client5.http.impl.async.HttpAsyncClientProtocolNegotiationStarter$1
> onRequestHead:FINE: c-0000000057 >> User-Agent: Apache CXF 4.0.6
> org.apache.hc.client5.http.impl.async.HttpAsyncClientProtocolNegotiationStarter$1
> onRequestHead:FINE: c-0000000057 >> X-Amz-Date: 20250523T042559Z
> org.apache.hc.client5.http.impl.async.AbstractHttpAsyncClientBase close:FINE:
> Shutdown GRACEFUL
> org.apache.hc.client5.http.impl.async.HttpAsyncClientProtocolNegotiationStarter$1
> onRequestHead:FINE: c-0000000057 >> Host: healthlake.us-east-2.amazonaws.com
> org.apache.hc.client5.http.impl.async.HttpAsyncClientProtocolNegotiationStarter$1
> onRequestHead:FINE: c-0000000057 >> Connection: Keep-Alive
> org.apache.hc.client5.http.impl.async.HttpAsyncClientProtocolNegotiationStarter$1
> onRequestHead:FINE: c-0000000057 >> Accept: */*
> org.apache.hc.client5.http.impl.async.HttpAsyncClientProtocolNegotiationStarter$1
> onRequestHead:FINE: c-0000000057 >> Content-Length: 668
> org.apache.hc.client5.http.impl.async.HttpAsyncClientProtocolNegotiationStarter$1
> onRequestHead:FINE: c-0000000057 >> Content-Type: application/fhir+json
> org.apache.hc.client5.http.impl.async.LoggingIOSession setEvent:FINE:
> c-0000000057[ACTIVE][rw:w][ACTIVE][rw][NOT_HANDSHAKING][0][0][0] Event set [w]
> org.apache.hc.client5.http.impl.async.LoggingAsyncClientExchangeHandler
> produce:FINE: ex-0000000865: produce request data
> org.apache.hc.client5.http.impl.async.LoggingAsyncClientExchangeHandler$1
> write:FINE: ex-0000000865: produce request data, len 668 bytes
> org.apache.hc.client5.http.impl.async.LoggingIOSession setEvent:FINE:
> c-0000000057[ACTIVE][rw:w][ACTIVE][rw][NOT_HANDSHAKING][0][0][0] Event set [w]
> org.apache.hc.client5.http.impl.async.LoggingAsyncClientExchangeHandler$1
> endStream:FINE: ex-0000000865: end of request data
> org.apache.hc.client5.http.impl.async.LoggingIOSession setEvent:FINE:
> c-0000000057[ACTIVE][rw:w][ACTIVE][rw][NOT_HANDSHAKING][0][0][0] Event set [w]
> org.apache.hc.client5.http.impl.async.LoggingIOSession enqueue:FINE:
> c-0000000057[ACTIVE][rw:w][ACTIVE][rw][NOT_HANDSHAKING][0][0][0] Enqueued
> ShutdownCommand with priority IMMEDIATE
> javax.net.ssl|DEBUG|10 00|httpclient-dispatch-1|2025-05-22 23:25:59.053
> CDT|null:-1|WRITE: TLSv1.3 application_data, length = 1192
> javax.net.ssl|DEBUG|10 00|httpclient-dispatch-1|2025-05-22 23:25:59.054
> CDT|null:-1|Plaintext before ENCRYPTION (
> 0000: 50 55 54 20 2F 64 61 74 61 73 74 6F 72 65 2F 30 PUT /datastore/0
> ......
> 04B0: 00 00 00 00 00 00 00 00 00 .........
> )
> javax.net.ssl|DEBUG|10 00|httpclient-dispatch-1|2025-05-22 23:25:59.055
> CDT|null:-1|Raw write (
> 0000: 17 03 03 04 C9 5A A2 39 B8 35 E7 D5 C4 71 6D 17 .....Z.9.5...qm.
> ......
> 04C0: 4D 21 76 7E 8C 5E 32 A2 66 1C A5 4E 6F 6E M!v..^2.f..Non
> )
> org.apache.hc.client5.http.impl.async.LoggingIOSession write:FINE:
> c-0000000057[ACTIVE][rw:w][ACTIVE][rw][NOT_HANDSHAKING][0][0][1230] 1192
> bytes written
> org.apache.hc.client5.http.impl.async.LoggingIOSession logData:FINE:
> c-0000000057[ACTIVE][rw:w][ACTIVE][rw][NOT_HANDSHAKING][0][0][1230] >> PUT
> /datastore/0 50 55 54 20 2f 64 61 74 61 73 74 6f 72 65 2f 30
> ......
> org.apache.hc.client5.http.impl.async.LoggingIOSession logData:FINE:
> c-0000000057[ACTIVE][rw:w][ACTIVE][rw][NOT_HANDSHAKING][0][0][1230] >>
> c1d77"}} 63 31 64 37 37 22 7d 7d
> org.apache.hc.client5.http.impl.async.LoggingIOSession clearEvent:FINE:
> c-0000000057[ACTIVE][rw:w][ACTIVE][r][NOT_HANDSHAKING][0][0][1230] Event
> cleared [w]
> org.apache.hc.client5.http.impl.async.LoggingIOSession setEvent:FINE:
> c-0000000057[ACTIVE][rw:w][ACTIVE][rw][NOT_HANDSHAKING][0][0][1230] Event set
> [w]
> org.apache.hc.client5.http.impl.async.LoggingIOSession clearEvent:FINE:
> c-0000000057[ACTIVE][r:w][ACTIVE][r][NOT_HANDSHAKING][0][0][0] Event cleared
> [w]
> javax.net.ssl|DEBUG|10 00|httpclient-dispatch-1|2025-05-22 23:25:59.141
> CDT|null:-1|Raw read (
> 0000: 17 03 03 03 F0 A5 85 DA 55 61 CB 41 FB 30 B9 18 ........Ua.A.0..
> ......
> 03F0: D8 23 08 C6 D2 .#...
> )
> javax.net.ssl|DEBUG|10 00|httpclient-dispatch-1|2025-05-22 23:25:59.141
> CDT|null:-1|READ: TLSv1.2 application_data, length = 1008
> javax.net.ssl|DEBUG|10 00|httpclient-dispatch-1|2025-05-22 23:25:59.143
> CDT|null:-1|Plaintext after DECRYPTION (
> 0000: 48 54 54 50 2F 31 2E 31 20 32 30 30 20 4F 4B 0D HTTP/1.1 200 OK.
> ......
> 03D0: 72 73 69 6F 6E 49 64 22 3A 22 31 30 22 7D 7D rsionId":"10"..
> )
> org.apache.hc.client5.http.impl.async.LoggingIOSession logData:FINE:
> c-0000000057[ACTIVE][r:r][ACTIVE][r][NOT_HANDSHAKING][1013][0][0] << HTTP/1.1
> 200 OK 48 54 54 50 2f 31 2e 31 20 32 30 30 20 4f 4b 0d
> ......
> org.apache.hc.client5.http.impl.async.LoggingIOSession logData:FINE:
> c-0000000057[ACTIVE][r:r][ACTIVE][r][NOT_HANDSHAKING][1013][0][0] <<
> rsionId":"10"}} 72 73 69 6f 6e 49 64 22 3a 22 31 30 22 7d 7d
> org.apache.hc.client5.http.impl.async.LoggingIOSession clearEvent:FINE:
> c-0000000057[ACTIVE][:r][ACTIVE][][NOT_HANDSHAKING][1013][991][0] Event
> cleared [r]
> org.apache.hc.client5.http.impl.async.LoggingIOSession close:FINE:
> c-0000000057[ACTIVE][:r][ACTIVE][][NOT_HANDSHAKING][0][0][0] Close GRACEFUL
> javax.net.ssl|ALL|30|Finalizer|2025-05-22 23:26:04.054 CDT|null:-1|Closing
> outbound of SSLEngine
> org.apache.hc.client5.http.impl.nio.PoolingAsyncClientConnectionManager
> close:FINE: Shutdown connection pool GRACEFUL
> org.apache.hc.client5.http.impl.nio.DefaultManagedAsyncClientConnection
> close:FINE: c-0000000057 Shutdown connection GRACEFUL
> org.apache.hc.client5.http.impl.nio.PoolingAsyncClientConnectionManager
> close:FINE: Connection pool shut down{noformat}
> {noformat}
> org.apache.cxf.transport.http.HTTPConduit$WrappedOutputStream
> makeTrustDecision:FINE: No Trust Decider for Conduit
> '{https://localhost:18084/FhirServer/baseR4}WebClient.http-conduit'. An
> affirmative Trust Decision is assumed.
> org.apache.hc.client5.http.impl.async.InternalAbstractHttpAsyncClient
> lambda$doExecute$0:FINE: ex-0000000565 preparing request execution
> org.apache.hc.client5.http.impl.async.AsyncProtocolExec internalExecute:FINE:
> ex-0000000565 proxy auth state: UNCHALLENGED
> org.apache.hc.client5.http.impl.async.AsyncConnectExec execute:FINE:
> ex-0000000565 acquiring connection with route
> {s}->[https://healthlake.us-east-2.amazonaws.com:443]
> org.apache.hc.client5.http.impl.async.InternalHttpAsyncExecRuntime
> acquireEndpoint:FINE: ex-0000000565 acquiring endpoint (60000 MILLISECONDS)
> org.apache.hc.client5.http.impl.nio.PoolingAsyncClientConnectionManager
> lease:FINE: ex-0000000565 endpoint lease request (60000 MILLISECONDS) [route:
> {s}->[https://healthlake.us-east-2.amazonaws.com:443]][total available: 1;
> route allocated: 1 of 1000; total allocated: 1 of 5000]
> org.apache.hc.client5.http.impl.async.AbstractHttpAsyncClientBase close:FINE:
> Shutdown GRACEFUL
> org.apache.hc.client5.http.impl.nio.PoolingAsyncClientConnectionManager$3$1
> leaseCompleted:FINE: ex-0000000565 endpoint leased [route:
> {s}->[https://healthlake.us-east-2.amazonaws.com:443]][total available: 0;
> route allocated: 1 of 1000; total allocated: 1 of 5000]
> org.apache.hc.client5.http.impl.nio.PoolingAsyncClientConnectionManager$3$1
> leaseCompleted:FINE: ex-0000000565 acquired ep-0000000558
> org.apache.hc.client5.http.impl.async.InternalHttpAsyncExecRuntime$1
> completed:FINE: ex-0000000565 acquired endpoint ep-0000000558
> org.apache.hc.client5.http.impl.async.HttpAsyncMainClientExec execute:FINE:
> ex-0000000565 executing PUT
> /datastore/0c04d492787311f75eda4565b519225c/r4/Observation/d22c5aaf-f36e-82ab-49c9-0bf757120606
> org.apache.hc.client5.http.impl.async.LoggingIOSession enqueue:FINE:
> c-0000000104[ACTIVE][rw:r][ACTIVE][rw][NOT_HANDSHAKING][0][0][0] Enqueued
> ShutdownCommand with priority IMMEDIATE
> org.apache.hc.client5.http.impl.async.LoggingIOSession clearEvent:FINE:
> c-0000000104[ACTIVE][r:w][ACTIVE][r][NOT_HANDSHAKING][0][0][0] Event cleared
> [w]
> org.apache.hc.client5.http.impl.async.LoggingIOSession setEvent:FINE:
> c-0000000104[ACTIVE][rw:w][ACTIVE][rw][NOT_HANDSHAKING][0][0][0] Event set [w]
> org.apache.hc.client5.http.impl.async.LoggingIOSession clearEvent:FINE:
> c-0000000104[ACTIVE][r:w][ACTIVE][r][NOT_HANDSHAKING][0][0][0] Event cleared
> [w]
> org.apache.hc.client5.http.impl.async.LoggingIOSession close:FINE:
> c-0000000104[ACTIVE][r:w][ACTIVE][r][NOT_HANDSHAKING][0][0][0] Close GRACEFUL
> org.apache.hc.client5.http.impl.async.InternalHttpAsyncExecRuntime
> execute:FINE: ep-0000000558 start execution ex-0000000565
> javax.net.ssl|ALL|10 CB|httpclient-dispatch-1|2025-05-23 24:18:25.691
> CDT|null:-1|Closing outbound of SSLEngine
> javax.net.ssl|WARNING|10 CB|httpclient-dispatch-1|2025-05-23 24:18:25.691
> CDT|null:-1|outbound has closed, ignore outbound application data
> javax.net.ssl|DEBUG|10 CB|httpclient-dispatch-1|2025-05-23 24:18:25.692
> CDT|null:-1|WRITE: TLSv1.3 alert, length = 2
> org.apache.hc.client5.http.impl.nio.PoolingAsyncClientConnectionManager$InternalConnectionEndpoint
> execute:FINE: ep-0000000558 executing exchange ex-0000000565 over
> c-0000000104
> org.apache.hc.client5.http.impl.nio.DefaultManagedAsyncClientConnection
> submitCommand:FINE: c-0000000104 RequestExecutionCommand with NORMAL priority
> javax.net.ssl|DEBUG|10 CB|httpclient-dispatch-1|2025-05-23 24:18:25.692
> CDT|null:-1|Plaintext before ENCRYPTION (
> 0000: 01 00 15 00 00 00 00 00 00 00 00 00 00 00 00 00 ................
> 0010: 00 00 00 ...
> )
> javax.net.ssl|DEBUG|10 CB|httpclient-dispatch-1|2025-05-23 24:18:25.692
> CDT|null:-1|Raw write (
> 0000: 17 03 03 00 23 69 BC C4 9D A3 26 00 2D E7 29 AC ....#i....&.-.).
> 0010: 45 CE 30 19 41 12 73 72 A4 9E D4 4C 4A 43 B0 FF E.0.A.sr...LJC..
> 0020: A2 DF 02 F7 77 AA 7B 0D ....w...
> )
> org.apache.hc.client5.http.impl.async.LoggingIOSession enqueue:FINE:
> c-0000000104[ACTIVE][rw:w][CLOSING][rw][NOT_HANDSHAKING][outbound
> done][][0][0][40] Enqueued RequestExecutionCommand with priority IMMEDIATE
> org.apache.hc.client5.http.impl.async.LoggingIOSession clearEvent:FINE:
> c-0000000104[CLOSED][][CLOSED][w][NOT_HANDSHAKING][outbound
> done][][EOF][][0][0][0] Event cleared [r]
> org.apache.hc.client5.http.impl.nio.PoolingAsyncClientConnectionManager
> close:FINE: Shutdown connection pool GRACEFUL
> org.apache.hc.client5.http.impl.nio.DefaultManagedAsyncClientConnection
> close:FINE: c-0000000104 Shutdown connection GRACEFUL
> org.apache.hc.client5.http.impl.nio.PoolingAsyncClientConnectionManager
> close:FINE: Connection pool shut down{noformat}
>
--
This message was sent by Atlassian Jira
(v8.20.10#820010)
