cxf rs deadlock waiting for response

classic Classic list List threaded Threaded
5 messages Options
Reply | Threaded
Open this post in threaded view
|

cxf rs deadlock waiting for response

Preben.Asmussen
Hi


There seems to be a problem doing a POST to a rest service that that returns http 202 with an empty body resulting in a inflight exchange that never completes (deadlock).
btw the service response content-length header is set to 0
 
The lock is in ->
at org.apache.cxf.jaxrs.client.AbstractClient.preProcessResult(AbstractClient.java:567)
        - locked <0x00000000fc1eed70> (a org.apache.cxf.message.ExchangeImpl)



The camel route is pretty simple ->

<route id="videorecorder-ma-out-route">
            <from uri="jmsc:topic:VIDEORECORDER_HUB?clientId=MA&amp;durableSubscriptionName=MA" />
            <transacted />
            <setHeader headerName="requester">
                <jsonpath>$.Requester</jsonpath>
            </setHeader>
            <filter>
                <simple>${header.requester} =~ 'MA'</simple>
                <inOnly uri="cxfrs:bean:maVideoRecorder" />
                <log message="hello ${body}"></log>
            </filter>
        </route>

The debug from the log is ->

[JmsConsumer[VIDEORECORDER_HUB]] PhaseInterceptorChain          DEBUG Invoking handleMessage on interceptor org.apache.cxf.jaxrs.client.spec.ClientRequestFilterInterceptor@77cf0138
[JmsConsumer[VIDEORECORDER_HUB]] PhaseInterceptorChain          DEBUG Invoking handleMessage on interceptor org.apache.cxf.interceptor.MessageSenderInterceptor@6b837aef
[JmsConsumer[VIDEORECORDER_HUB]] PhaseInterceptorChain          DEBUG Adding interceptor org.apache.cxf.interceptor.MessageSenderInterceptor$MessageSenderEndingInterceptor@7503b6e5 to phase prepare-send-ending
[JmsConsumer[VIDEORECORDER_HUB]] PhaseInterceptorChain          DEBUG Chain org.apache.cxf.phase.PhaseInterceptorChain@144390f9 was modified. Current flow:
  setup [PolicyOutInterceptor]
  pre-logical [ClientRequestFilterInterceptor]
  prepare-send [MessageSenderInterceptor]
  pre-stream [LoggingOutInterceptor]
  write [BodyWriter]
  prepare-send-ending [MessageSenderEndingInterceptor]

[JmsConsumer[VIDEORECORDER_HUB]] PhaseInterceptorChain          DEBUG Invoking handleMessage on interceptor org.apache.cxf.interceptor.LoggingOutInterceptor@5445fa77
[JmsConsumer[VIDEORECORDER_HUB]] PhaseInterceptorChain          DEBUG Invoking handleMessage on interceptor org.apache.cxf.jaxrs.client.WebClient$BodyWriter@485c3512
[JmsConsumer[VIDEORECORDER_HUB]] PhaseInterceptorChain          DEBUG Invoking handleMessage on interceptor org.apache.cxf.interceptor.MessageSenderInterceptor$MessageSenderEndingInterceptor@7503b6e5
[JmsConsumer[VIDEORECORDER_HUB]] LoggingOutInterceptor          INFO  Outbound Message
---------------------------
ID: 1
Address: http://liverec01tst:8005/api/v1/returns202
Http-Method: POST
Content-Type: application/json
Headers: {Charset=[UTF-8], Content-Type=[application/json], adapterName=[videorecorder-out/ma], breadcrumbId=[ID-A78029-52394-1478159276700-0-1], JMS_OracleConnectionID=[4061c6f642b36737e053b50d650a771f], JMS_OracleDelay=[0], JMS_OracleDeliveryMode=[2], JMS_OracleTimestamp=[1478159282699], JMSDeliveryMode=[2], JMSDestination=[INTAQ.VIDEORECORDER_HUB], JMSExpiration=[0], JMSMessageID=[ID:4061C6F642B46737E053B50D650A771F], JMSPriority=[8], JMSRedelivered=[true], JMSTimestamp=[1478159282699], JMSXDeliveryCount=[5], JMSXRcvTimestamp=[1478161691380], JMSXState=[0], JMSXUserID=[INTAQ], MessageID=[1234], requester=[ma], Accept=[*/*]}
Payload: {
  "OrderId":"1234",
  "Status":"string",
  "Requester":"ma",
  "RecordingType":"string",
  "ProductionNumber":"string",
  "StartTime":"ISO 8601 UTC",
  "EndTime":"ISO 8601 UTC",
  "Channel":"string",
  "BlockId":"string",
  "EventId":"string",
  "EstimatedDeliveryTime":"ISO 8601 UTC",
  "Message":"string",
  "RequesterInfo":"string",
  "Attempt":"string",
  "Manifestations": [{
    "manifestation":"string",
    "fileInfos": [{
      "fileName":"string",
      "ftpName":"string",
      "blockId":"string",
      "blockIndex":"string"
    }]
  }]
}

--------------------------------------
[JmsConsumer[VIDEORECORDER_HUB]] Headers                        DEBUG Charset: UTF-8
[JmsConsumer[VIDEORECORDER_HUB]] Headers                        DEBUG Content-Type: application/json
[JmsConsumer[VIDEORECORDER_HUB]] Headers                        DEBUG adapterName: videorecorder-out/ma
[JmsConsumer[VIDEORECORDER_HUB]] Headers                        DEBUG breadcrumbId: ID-A78029-52394-1478159276700-0-1
[JmsConsumer[VIDEORECORDER_HUB]] Headers                        DEBUG JMS_OracleConnectionID: 4061c6f642b36737e053b50d650a771f
[JmsConsumer[VIDEORECORDER_HUB]] Headers                        DEBUG JMS_OracleDelay: 0
[JmsConsumer[VIDEORECORDER_HUB]] Headers                        DEBUG JMS_OracleDeliveryMode: 2
[JmsConsumer[VIDEORECORDER_HUB]] Headers                        DEBUG JMS_OracleTimestamp: 1478159282699
[JmsConsumer[VIDEORECORDER_HUB]] Headers                        DEBUG JMSDeliveryMode: 2
[JmsConsumer[VIDEORECORDER_HUB]] Headers                        DEBUG JMSDestination: INTAQ.VIDEORECORDER_HUB
[JmsConsumer[VIDEORECORDER_HUB]] Headers                        DEBUG JMSExpiration: 0
[JmsConsumer[VIDEORECORDER_HUB]] Headers                        DEBUG JMSMessageID: ID:4061C6F642B46737E053B50D650A771F
[JmsConsumer[VIDEORECORDER_HUB]] Headers                        DEBUG JMSPriority: 8
[JmsConsumer[VIDEORECORDER_HUB]] Headers                        DEBUG JMSRedelivered: true
[JmsConsumer[VIDEORECORDER_HUB]] Headers                        DEBUG JMSTimestamp: 1478159282699
[JmsConsumer[VIDEORECORDER_HUB]] Headers                        DEBUG JMSXDeliveryCount: 5
[JmsConsumer[VIDEORECORDER_HUB]] Headers                        DEBUG JMSXRcvTimestamp: 1478161691380
[JmsConsumer[VIDEORECORDER_HUB]] Headers                        DEBUG JMSXState: 0
[JmsConsumer[VIDEORECORDER_HUB]] Headers                        DEBUG JMSXUserID: INTAQ
[JmsConsumer[VIDEORECORDER_HUB]] Headers                        DEBUG MessageID: 1234
[JmsConsumer[VIDEORECORDER_HUB]] Headers                        DEBUG requester: ma
[JmsConsumer[VIDEORECORDER_HUB]] Headers                        DEBUG Accept: */*
[JmsConsumer[VIDEORECORDER_HUB]] HTTPConduit                    DEBUG No Trust Decider for Conduit '{http://liverec01tst:8005/api/v1/returns202}WebClient.http-conduit'. An affirmative Trust Decision is assumed.
[JmsConsumer[VIDEORECORDER_HUB]] HTTPConduit                    DEBUG Sending POST Message with Headers to http://liverec01tst:8005/api/v1/returns202 Conduit :{http://liverec01tst:8005/api/v1/returns202}WebClient.http-conduit


So I never see the hello ${body} log message.

Threaddump ->

"Camel (msub-videorecorder-out-Context) thread #0 - JmsConsumer[VIDEORECORDER_HUB]" #71 daemon prio=5 os_prio=0 tid=0x0000000058b43800 nid=0x18c0 in Object.wait() [0x000000006b16d000]
   java.lang.Thread.State: TIMED_WAITING (on object monitor)
        at java.lang.Object.wait(Native Method)
        at org.apache.cxf.jaxrs.client.AbstractClient.preProcessResult(AbstractClient.java:567)
        - locked <0x00000000fc1eed70> (a org.apache.cxf.message.ExchangeImpl)
        at org.apache.cxf.jaxrs.client.WebClient.doResponse(WebClient.java:1098)
        at org.apache.cxf.jaxrs.client.WebClient.doChainedInvocation(WebClient.java:1035)
        at org.apache.cxf.jaxrs.client.WebClient.doInvoke(WebClient.java:892)
        at org.apache.cxf.jaxrs.client.WebClient.doInvoke(WebClient.java:863)
        at org.apache.cxf.jaxrs.client.WebClient.invoke(WebClient.java:329)
        at org.apache.camel.component.cxf.jaxrs.CxfRsProducer.invokeHttpClient(CxfRsProducer.java:211)
        at org.apache.camel.component.cxf.jaxrs.CxfRsProducer.process(CxfRsProducer.java:89)
        at org.apache.camel.util.AsyncProcessorConverterHelper$ProcessorToAsyncProcessorBridge.process(AsyncProcessorConverterHelper.java:61)
        at org.apache.camel.processor.SendProcessor.process(SendProcessor.java:145)
        at org.apache.camel.management.InstrumentationProcessor.process(InstrumentationProcessor.java:77)
        at org.apache.camel.processor.RedeliveryErrorHandler.process(RedeliveryErrorHandler.java:542)
        at org.apache.camel.processor.RedeliveryErrorHandler.process(RedeliveryErrorHandler.java:400)
        at org.apache.camel.processor.CamelInternalProcessor.process(CamelInternalProcessor.java:172)
        at org.apache.camel.processor.Pipeline.process(Pipeline.java:120)
        at org.apache.camel.processor.Pipeline.process(Pipeline.java:83)
        at org.apache.camel.processor.FilterProcessor.process(FilterProcessor.java:57)
        at org.apache.camel.management.InstrumentationProcessor.process(InstrumentationProcessor.java:77)
        at org.apache.camel.processor.RedeliveryErrorHandler.process(RedeliveryErrorHandler.java:542)
        at org.apache.camel.processor.RedeliveryErrorHandler.process(RedeliveryErrorHandler.java:400)
        at org.apache.camel.processor.CamelInternalProcessor.process(CamelInternalProcessor.java:172)
        at org.apache.camel.processor.Pipeline.process(Pipeline.java:120)
        at org.apache.camel.processor.Pipeline.process(Pipeline.java:83)
        at org.apache.camel.processor.RedeliveryErrorHandler.process(RedeliveryErrorHandler.java:542)
        at org.apache.camel.spring.spi.TransactionErrorHandler.processByErrorHandler(TransactionErrorHandler.java:220)
        at org.apache.camel.spring.spi.TransactionErrorHandler.process(TransactionErrorHandler.java:101)
        at org.apache.camel.spring.spi.TransactionErrorHandler.process(TransactionErrorHandler.java:114)
        at org.apache.camel.management.InstrumentationProcessor.process(InstrumentationProcessor.java:77)
        at org.apache.camel.processor.RedeliveryErrorHandler.process(RedeliveryErrorHandler.java:542)
        at org.apache.camel.spring.spi.TransactionErrorHandler.processByErrorHandler(TransactionErrorHandler.java:220)
        at org.apache.camel.spring.spi.TransactionErrorHandler$1.doInTransactionWithoutResult(TransactionErrorHandler.java:183)
        at org.springframework.transaction.support.TransactionCallbackWithoutResult.doInTransaction(TransactionCallbackWithoutResult.java:34)
        at org.springframework.transaction.support.TransactionTemplate.execute(TransactionTemplate.java:133)
        at org.apache.camel.spring.spi.TransactionErrorHandler.doInTransactionTemplate(TransactionErrorHandler.java:176)
        at org.apache.camel.spring.spi.TransactionErrorHandler.processInTransaction(TransactionErrorHandler.java:136)
        at org.apache.camel.spring.spi.TransactionErrorHandler.process(TransactionErrorHandler.java:105)
        at org.apache.camel.spring.spi.TransactionErrorHandler.process(TransactionErrorHandler.java:114)
        at org.apache.camel.processor.CamelInternalProcessor.process(CamelInternalProcessor.java:197)
        at org.apache.camel.processor.CamelInternalProcessor.process(CamelInternalProcessor.java:197)
        at org.apache.camel.processor.DelegateAsyncProcessor.process(DelegateAsyncProcessor.java:97)
        at org.apache.camel.component.jms.EndpointMessageListener.onMessage(EndpointMessageListener.java:112)
        at org.springframework.jms.listener.AbstractMessageListenerContainer.doInvokeListener(AbstractMessageListenerContainer.java:721)
        at org.springframework.jms.listener.AbstractMessageListenerContainer.invokeListener(AbstractMessageListenerContainer.java:681)
        at org.springframework.jms.listener.AbstractMessageListenerContainer.doExecuteListener(AbstractMessageListenerContainer.java:651)
        at org.springframework.jms.listener.AbstractPollingMessageListenerContainer.doReceiveAndExecute(AbstractPollingMessageListenerContainer.java:317)
        at org.springframework.jms.listener.AbstractPollingMessageListenerContainer.receiveAndExecute(AbstractPollingMessageListenerContainer.java:235)
        at org.springframework.jms.listener.DefaultMessageListenerContainer$AsyncMessageListenerInvoker.invokeListener(DefaultMessageListenerContainer.java:1166)
        at org.springframework.jms.listener.DefaultMessageListenerContainer$AsyncMessageListenerInvoker.executeOngoingLoop(DefaultMessageListenerContainer.java:1158)
        at org.springframework.jms.listener.DefaultMessageListenerContainer$AsyncMessageListenerInvoker.run(DefaultMessageListenerContainer.java:1055)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
        at java.lang.Thread.run(Thread.java:745)

   Locked ownable synchronizers:
        - <0x00000000fb7738e0> (a java.util.concurrent.ThreadPoolExecutor$Worker)

AFAIK there should not be any cxf option that tells cxf about an empty response, or am I missing something ??
I presume it's a bug in the latest cxf release since it seems to work when using camel 2.17.1, and the corrosponding cxf

Camel version 2.18.0 and cxf version 3.1.7

Cheers

/Preben
Reply | Threaded
Open this post in threaded view
|

Re: cxf rs deadlock waiting for response

Preben.Asmussen
I debugged a bit to get closer.

The root problem is in org.apache.cxf.jaxrs.client.AbstractClient as the threaddump shows

the block in line 564 gets activated

        if (ex == null && !exchange.isOneWay()) {
            synchronized (exchange) {
                while (exchange.get("IN_CHAIN_COMPLETE") == null) {
                    exchange.wait(cfg.getSynchronousTimeout());
                }
            }
        }

The exchange.isOneWay returns false. Shouldn't it return true since it's a inonly exchange ???
And the while loop continues infinite since IN_CHAIN_COMPLETE is allways null

/Preben

Reply | Threaded
Open this post in threaded view
|

Re: cxf rs deadlock waiting for response

Sergey Beryozkin
Hi

You are right, it is a new code which was added to avoid some
synchronization issues in case of the async client invocations.

FYI, the existing CXF RS oneway tests still work with this code but only
because the client does set a oneway CXF exchange status before the
invocation, in case of the proxy it is done if a CXF @OneWay method
annotation is available, in case of WebClient if a 'OnewayRequest' HTTP
header is set.

I'm going to fix it shortly:
https://issues.apache.org/jira/browse/CXF-7113

Cheers, Sergey
On 03/11/16 10:16, Preben.Asmussen wrote:

> I debugged a bit to get closer.
>
> The root problem is in org.apache.cxf.jaxrs.client.AbstractClient as the
> threaddump shows
>
> the block in line 564 gets activated
>
>         if (ex == null && !exchange.isOneWay()) {
>             synchronized (exchange) {
>                 while (exchange.get("IN_CHAIN_COMPLETE") == null) {
>                     exchange.wait(cfg.getSynchronousTimeout());
>                 }
>             }
>         }
>
> The exchange.isOneWay returns false. Shouldn't it return true since it's a
> inonly exchange ???
> And the while loop continues infinite since IN_CHAIN_COMPLETE is allways
> null
>
> /Preben
>
>
>
>
>
> --
> View this message in context: http://camel.465427.n5.nabble.com/cxf-rs-deadlock-waiting-for-response-tp5789687p5789692.html
> Sent from the Camel - Users mailing list archive at Nabble.com.
>


--
Sergey Beryozkin

Talend Community Coders
http://coders.talend.com/
Reply | Threaded
Open this post in threaded view
|

Re: cxf rs deadlock waiting for response

Preben.Asmussen
Thanks Sergey :-)

I think the link should be https://issues.apache.org/jira/browse/CXF-7123

Cheers

/Preben
Reply | Threaded
Open this post in threaded view
|

Re: cxf rs deadlock waiting for response

Sergey Beryozkin
Oops :-), sorry. CXF-7123 has now been fixed

Cheers, Sergey
On 03/11/16 13:36, Preben.Asmussen wrote:

> Thanks Sergey :-)
>
> I think the link should be https://issues.apache.org/jira/browse/CXF-7123
>
> Cheers
>
> /Preben
>
>
>
> --
> View this message in context: http://camel.465427.n5.nabble.com/cxf-rs-deadlock-waiting-for-response-tp5789687p5789708.html
> Sent from the Camel - Users mailing list archive at Nabble.com.
>