CXF-8629: AsyncHTTPConduit (hc5) should support chunked request / response. Add test cases with auto-redirect

[reta]

AsyncHTTPConduit (hc5) should support chunked request / response. Add test cases with auto-redirect

[jyinpci]

camel-spring-boot-examples-8.10.0.zip
Hi @reta, here is a project that can reproduce the duplicate response issue. I created the test case based on Camel example project (from the Camel team - camel 4.10.0-SNAPSHOT, cxf 4.1.0). The test case is in the rest-cxf subproject. Please run it using maven spring-boot:run. It will use port 8081 on localhost. The upload file includes the git base, so you can easily see what I changed from the original camel example project (including dependencies I added).

[reta]

Hi @reta, here is a project that can reproduce the duplicate response issue. I created the test case based on Camel example project (from the Camel team - camel 4.10.0-SNAPSHOT, cxf 4.1.0).

@jyinpci the issue seems clear now, the logging comes from the server AND the client since you have configured the logging feature in the bus (which is this particular case is the same for server and the client).

[jyinpci]

Hi @reta,

Thanks for looking into this again. I am afraid it was not double-logging by the server and the client. Yes, both server and client logged the response. But the server logged the response once (indicated by "Outbound Message" label), and the client logged the response twice (indicated by "Inbound Message" label). In fact, because of the null body, it caused Camel to fail afterwards. Please note this was done using Camel without synchronous=true on the endpoint - I am under the impression that with the async support in CXF http client, we do not have to use synchronous=true with Camel. Here is the log generated by the test project I submitted:

2024-12-23T19:39:49.341-05:00 INFO 8592 --- [ - timer://test] o.a.c.interceptor.LoggingOutInterceptor : Outbound Message

ID: 1
Address: http://localhost:8081/test/user
Http-Method: PUT
Content-Type: application/json
Headers: {cache-control=[no-cache], Content-Type=[application/json], Content-Language=[en_US], Connection=[Keep-Alive], Accept=[/]}
Payload: {"id":4,"name":"Charlie Parker"}

2024-12-23T19:39:49.512-05:00 INFO 8592 --- [qtp669781254-80] o.a.c.interceptor.LoggingInInterceptor : Inbound Message

ID: 2
Address: http://localhost:8081/test/user
Encoding: UTF-8
Http-Method: PUT
Content-Type: application/json
Headers: {Accept=[/], Cache-Control=[no-cache], connection=[keep-alive], Content-Language=[en_US], Content-Length=[32], content-type=[application/json], Host=[localhost:8081], User-Agent=[Apache CXF 4.1.0]}
Payload: {"id":4,"name":"Charlie Parker"}

2024-12-23T19:39:49.525-05:00 INFO 8592 --- [qtp669781254-80] route1 : request received {"id":4,"name":"Charlie Parker"}
2024-12-23T19:39:49.533-05:00 INFO 8592 --- [qtp669781254-80] o.a.c.interceptor.LoggingOutInterceptor : Outbound Message

ID: 2
Response-Code: 200
Content-Type: application/json
Headers: {uri_eb_url_any=[user], Accept=[/], Cache-Control=[no-cache], User-Agent=[Apache CXF 4.1.0], connection=[keep-alive], Host=[localhost:8081], Content-Language=[en_US], Content-Type=[application/json], Date=[Tue, 24 Dec 2024 00:39:49 GMT]}
Payload: {"result": "Ok"}

2024-12-23T19:39:49.545-05:00 INFO 8592 --- [ult-workqueue-2] o.a.c.interceptor.LoggingInInterceptor : Inbound Message

ID: 1
Response-Code: 200
Encoding: ISO-8859-1
Content-Type: application/json
Headers: {Accept=[/], Cache-Control=[no-cache], Content-Language=[en_US], Content-Type=[application/json], Date=[Tue, 24 Dec 2024 00:39:49 GMT], Host=[localhost:8081], Server=[Jetty(12.0.16)], Transfer-Encoding=[chunked], uri_eb_url_any=[user], User-Agent=[Apache CXF 4.1.0]}

2024-12-23T19:39:49.545-05:00 INFO 8592 --- [ult-workqueue-1] o.a.c.interceptor.LoggingInInterceptor : Inbound Message

ID: 1
Response-Code: 200
Encoding: ISO-8859-1
Content-Type: application/json
Headers: {Accept=[/], Cache-Control=[no-cache], Content-Language=[en_US], Content-Type=[application/json], Date=[Tue, 24 Dec 2024 00:39:49 GMT], Host=[localhost:8081], Server=[Jetty(12.0.16)], Transfer-Encoding=[chunked], uri_eb_url_any=[user], User-Agent=[Apache CXF 4.1.0]}
Payload: {"result": "Ok"}

2024-12-23T19:39:49.548-05:00 INFO 8592 --- [ult-workqueue-2] route2 : response received:
2024-12-23T19:39:49.548-05:00 INFO 8592 --- [ult-workqueue-1] route2 : response received:
2024-12-23T19:39:49.549-05:00 WARN 8592 --- [ult-workqueue-2] o.a.c.i.engine.DefaultReactiveExecutor : Error executing reactive work due to null. This exception is ignored.

java.util.NoSuchElementException: null
at java.base/java.util.TreeMap$PrivateEntryIterator.nextEntry(TreeMap.java:1519) ~[na:na]
at java.base/java.util.TreeMap$EntryIterator.next(TreeMap.java:1557) ~[na:na]
at java.base/java.util.TreeMap$EntryIterator.next(TreeMap.java:1552) ~[na:na]
at java.base/java.util.TreeMap.buildFromSorted(TreeMap.java:2914) ~[na:na]
at java.base/java.util.TreeMap.buildFromSorted(TreeMap.java:2938) ~[na:na]
at java.base/java.util.TreeMap.buildFromSorted(TreeMap.java:2938) ~[na:na]
at java.base/java.util.TreeMap.buildFromSorted(TreeMap.java:2938) ~[na:na]
at java.base/java.util.TreeMap.buildFromSorted(TreeMap.java:2863) ~[na:na]
at java.base/java.util.TreeMap.putAll(TreeMap.java:354) ~[na:na]
at org.apache.camel.support.MessageSupport.copyFromWithNewBody(MessageSupport.java:226) ~[camel-support-4.10.0-SNAPSHOT.jar:4.10.0-SNAPSHOT]
at org.apache.camel.support.MessageSupport.copyFrom(MessageSupport.java:193) ~[camel-support-4.10.0-SNAPSHOT.jar:4.10.0-SNAPSHOT]
at org.apache.camel.support.ExchangeHelper.copyFromOutMessageConditionally(ExchangeHelper.java:402) ~[camel-support-4.10.0-SNAPSHOT.jar:4.10.0-SNAPSHOT]
at org.apache.camel.support.ExchangeHelper.doCopyResults(ExchangeHelper.java:365) ~[camel-support-4.10.0-SNAPSHOT.jar:4.10.0-SNAPSHOT]
at org.apache.camel.support.ExchangeHelper.copyResults(ExchangeHelper.java:349) ~[camel-support-4.10.0-SNAPSHOT.jar:4.10.0-SNAPSHOT]
at org.apache.camel.processor.Pipeline$PipelineTask.run(Pipeline.java:105) ~[camel-core-processor-4.10.0-SNAPSHOT.jar:4.10.0-SNAPSHOT]
at org.apache.camel.impl.engine.DefaultReactiveExecutor$Worker.doRun(DefaultReactiveExecutor.java:199) ~[camel-base-engine-4.10.0-SNAPSHOT.jar:4.10.0-SNAPSHOT]
at org.apache.camel.impl.engine.DefaultReactiveExecutor$Worker.executeReactiveWork(DefaultReactiveExecutor.java:189) ~[camel-base-engine-4.10.0-SNAPSHOT.jar:4.10.0-SNAPSHOT]
at org.apache.camel.impl.engine.DefaultReactiveExecutor$Worker.tryExecuteReactiveWork(DefaultReactiveExecutor.java:166) ~[camel-base-engine-4.10.0-SNAPSHOT.jar:4.10.0-SNAPSHOT]
at org.apache.camel.impl.engine.DefaultReactiveExecutor$Worker.schedule(DefaultReactiveExecutor.java:148) ~[camel-base-engine-4.10.0-SNAPSHOT.jar:4.10.0-SNAPSHOT]
at org.apache.camel.impl.engine.DefaultReactiveExecutor.schedule(DefaultReactiveExecutor.java:54) ~[camel-base-engine-4.10.0-SNAPSHOT.jar:4.10.0-SNAPSHOT]
at org.apache.camel.processor.errorhandler.RedeliveryErrorHandler$RedeliveryTask.lambda$doRun$1(RedeliveryErrorHandler.java:813) ~[camel-core-processor-4.10.0-SNAPSHOT.jar:4.10.0-SNAPSHOT]
at org.apache.camel.component.cxf.jaxrs.CxfRsProducer$CxfInvocationCallback.completed(CxfRsProducer.java:732) ~[camel-cxf-rest-4.10.0-SNAPSHOT.jar:4.10.0-SNAPSHOT]
at org.apache.camel.component.cxf.jaxrs.CxfRsProducer$CxfInvocationCallback.completed(CxfRsProducer.java:680) ~[camel-cxf-rest-4.10.0-SNAPSHOT.jar:4.10.0-SNAPSHOT]
at org.apache.cxf.jaxrs.client.JaxrsClientCallback.handleResponse(JaxrsClientCallback.java:86) ~[cxf-rt-rs-client-4.1.0.jar:4.1.0]
at org.apache.cxf.jaxrs.client.WebClient$ClientAsyncResponseInterceptor.doHandleAsyncResponse(WebClient.java:1033) ~[cxf-rt-rs-client-4.1.0.jar:4.1.0]
at org.apache.cxf.jaxrs.client.AbstractClient$AbstractClientAsyncResponseInterceptor.handleAsyncResponse(AbstractClient.java:1317) ~[cxf-rt-rs-client-4.1.0.jar:4.1.0]
at org.apache.cxf.jaxrs.client.AbstractClient$AbstractClientAsyncResponseInterceptor.handleMessage(AbstractClient.java:1287) ~[cxf-rt-rs-client-4.1.0.jar:4.1.0]
at org.apache.cxf.phase.PhaseInterceptorChain.doIntercept(PhaseInterceptorChain.java:307) ~[cxf-core-4.1.0.jar:4.1.0]
at org.apache.cxf.jaxrs.client.ClientMessageObserver.onMessage(ClientMessageObserver.java:56) ~[cxf-rt-rs-client-4.1.0.jar:4.1.0]
at org.apache.cxf.transport.http.HTTPConduit$WrappedOutputStream.handleResponseInternal(HTTPConduit.java:1760) ~[cxf-rt-transports-http-4.1.0.jar:4.1.0]
at org.apache.cxf.transport.http.HTTPConduit$WrappedOutputStream$1.run(HTTPConduit.java:1238) ~[cxf-rt-transports-http-4.1.0.jar:4.1.0]
at org.apache.cxf.workqueue.AutomaticWorkQueueImpl$3.run(AutomaticWorkQueueImpl.java:413) ~[cxf-core-4.1.0.jar:4.1.0]
at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1144) ~[na:na]
at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:642) ~[na:na]
at org.apache.cxf.workqueue.AutomaticWorkQueueImpl$AWQThreadFactory$1.run(AutomaticWorkQueueImpl.java:346) ~[cxf-core-4.1.0.jar:4.1.0]
at java.base/java.lang.Thread.run(Thread.java:1583) ~[na:na]

Thank you very much for being patient with me. :-)

[reta]

Hi @reta,

Thanks for looking into this again. I am afraid it was not double-logging by the server and the client. Yes, both server and client logged the response.

Hi @jyinpci , I think you are very right, and I believe I could reproduce the issue successfully now - the key is to use async() client invocation, and with it, the response callback is called twice. I don't have a fix yet but I do have tests.