[
https://issues.apache.org/jira/browse/CXF-9140?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17953983#comment-17953983
]
Luke Xu commented on CXF-9140:
------------------------------
[~reta] We have a client tested for production that can be used as a
reproducer. I can't share it here due to company copyrights. But if CXF team
has debug builds to diagnose the issue, I should be able to help.
About whether it's random, I tend to be affirmative on that. Tests done by me
and my colleague showed that the client got blocked after the 651st, 38th,
345th, 1134th, 1238th, 36th, 71st, and 1342nd message.
> 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)
