ServiceMix
  1. ServiceMix
  2. SM-1712

ExchangeListener is called with exchangeSent instead of exchangeAccepted when using sendSync

    Details

    • Type: Bug Bug
    • Status: Resolved
    • Priority: Major Major
    • Resolution: Fixed
    • Affects Version/s: 3.3
    • Fix Version/s: 3.2.4, 3.3.1
    • Component/s: servicemix-core
    • Labels:
      None

      Description

      I have a very simple process composed as follows:

      CXF-BC Consumer->My component

      The MEP is InOut.
      The problem is that the CXF send too many messages to my component.
      I used a listener to see the messages sent.

      The messages are:

      ------ FIRST MESSAGE (from CXF to my component, only "in" message contained in the exchange) -----
      INFO - SimpleExchangeListener - Status: Active
      INFO - SimpleExchangeListener - InOut[
      id: ID:192.168.20.106-11de3ccb3eb-4:1
      status: Active
      role: consumer

      ------ SECOND MESSAGE (from my component to CXF, same exchange with "out" message, in addition to "in" message) -----

      INFO - SimpleExchangeListener - Status: Active
      INFO - SimpleExchangeListener - InOut[
      id: ID:192.168.20.106-11de3ccb3eb-4:1
      status: Active
      role: provider

      ------ THIRD MESSAGE ----- <---- WHAT IS THIS ?? (This message is sent by CXF, the exchange is the same of second message, but the role changed from provider to consumer. The JBI InOut MEP specification doesn't say anything about this message)

      INFO - SimpleExchangeListener - Status: Active
      INFO - SimpleExchangeListener - InOut[
      id: ID:192.168.20.106-11de3ccb3eb-4:1
      status: Active
      role: consumer

      ------ FOURTH MESSAGE (This is the DONE message sent by the CXF to my component )-----

      INFO - SimpleExchangeListener - Status: Done
      INFO - SimpleExchangeListener - InOut[
      id: ID:192.168.20.106-11de3ccb3eb-4:1
      status: Done
      role: consumer

      1. SimpleExchangeListener.java
        6 kB
        Andrea Zoppello
      2. firstProcess_v_0-sa.zip
        3 kB
        Gianfranco Boccalon

        Activity

        Hide
        Gianfranco Boccalon added a comment -

        This is a sample process with a CXF BC component and a lightweight transformer component.
        If you use a listener to trace all the messages sent, you will see 4 messages, instead of 3, on the bus.

        Show
        Gianfranco Boccalon added a comment - This is a sample process with a CXF BC component and a lightweight transformer component. If you use a listener to trace all the messages sent, you will see 4 messages, instead of 3, on the bus.
        Hide
        Andrea Zoppello added a comment -

        Is there any plan to fix this???

        Is there any idea where to look at???

        Andrea

        Show
        Andrea Zoppello added a comment - Is there any plan to fix this??? Is there any idea where to look at??? Andrea
        Hide
        Guillaume Nodet added a comment -

        I've run your SA and launch a simple soap request.
        I can see only 3 messages there. Are you sure the problem does not come from your listener somehow ?
        IIRC, listeners are invoked when messages are sent and accepted, so the listener should be called 6 times actually.

        DEBUG - CxfBcComponent                 - Created correlation id: ID:192.168.0.128-11e076198a3-18:0
        DEBUG - DeliveryChannelImpl            - SendSync ID:192.168.0.128-11e076198a3-18:0 in DeliveryChannel{servicemix-cxf-bc}
        DEBUG - SecuredBroker                  - send exchange with secure broker
        DEBUG - SecuredBroker                  - service name :{urn:eng:spagic:processes:firstProcess:v0}firstProcess.Transform_v_0
        DEBUG - SecuredBroker                  - operation name :{urn:eng:spagic:processes:firstProcess:v0}run
        DEBUG - SedaFlow                       - Called Flow send
        DEBUG - DeliveryChannelImpl            - Waiting for exchange ID:192.168.0.128-11e076198a3-18:0 (8ccd21) to be answered in DeliveryChannel{servicemix-cxf-bc} from sendSync
        DEBUG - SedaQueue                      - org.apache.servicemix.jbi.nmr.flow.seda.SedaQueue$1@ef6abe dequeued exchange: InOut[
          id: ID:192.168.0.128-11e076198a3-18:0
          status: Active
          role: provider
          service: {urn:eng:spagic:processes:firstProcess:v0}firstProcess.Transform_v_0
          endpoint: firstProcess.Transform_v_0
          operation: {urn:eng:spagic:processes:firstProcess:v0}run
          in: <?xml version="1.0" encoding="UTF-8"?><jbi:message xmlns:jbi="http://java.sun.com/xml/ns/jbi/wsdl-11-wrapper" xmlns:msg="urn:eng:spagic:processes:firstProcess:v0" xmlns:xsd="http://www.w3.org/2001/XMLSchema" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" name="msgRequest" type="msg:msgRequest" version="1.0"><jbi:part><urn:payload xmlns:urn="urn:eng:spagic">?</urn:payload></jbi:part></jbi:message>
        ]
        DEBUG - DeliveryChannelImpl            - Send ID:192.168.0.128-11e076198a3-18:0 in DeliveryChannel{firstProcess.Transform_v_0}
        DEBUG - SecuredBroker                  - send exchange with secure broker
        DEBUG - SedaFlow                       - Called Flow send
        DEBUG - SedaQueue                      - org.apache.servicemix.jbi.nmr.flow.seda.SedaQueue$1@e883ec dequeued exchange: InOut[
          id: ID:192.168.0.128-11e076198a3-18:0
          status: Active
          role: consumer
          service: {urn:eng:spagic:processes:firstProcess:v0}firstProcess.Transform_v_0
          endpoint: firstProcess.Transform_v_0
          operation: {urn:eng:spagic:processes:firstProcess:v0}run
          in: <?xml version="1.0" encoding="UTF-8"?><jbi:message xmlns:jbi="http://java.sun.com/xml/ns/jbi/wsdl-11-wrapper" xmlns:msg="urn:eng:spagic:processes:firstProcess:v0" xmlns:xsd="http://www.w3.org/2001/XMLSchema" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" name="msgRequest" type="msg:msgRequest" version="1.0"><jbi:part><urn:payload xmlns:urn="urn:eng:spagic">?</urn:payload></jbi:part></jbi:message>
          out: <?xml version="1.0" encoding="UTF-8"?><jbi:message xmlns:jbi="http://java.sun.com/xml/ns/jbi/wsdl-11-wrapper" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" name="msgRequest" type="msg:msgRequest" version="1.0"><jbi:part><urn:payload xmlns:urn="urn:eng:spagic">?</urn:payload></jbi:part></jbi:message>
        ]
        DEBUG - DeliveryChannelImpl            - Notifying exchange ID:192.168.0.128-11e076198a3-18:0(8ccd21) in DeliveryChannel{servicemix-cxf-bc} from processInboundSynchronousExchange
        DEBUG - DeliveryChannelImpl            - Notified: ID:192.168.0.128-11e076198a3-18:0(8ccd21) in DeliveryChannel{servicemix-cxf-bc} from sendSync
        DEBUG - DeliveryChannelImpl            - Send ID:192.168.0.128-11e076198a3-18:0 in DeliveryChannel{servicemix-cxf-bc}
        DEBUG - SecuredBroker                  - send exchange with secure broker
        DEBUG - SedaFlow                       - Called Flow send
        DEBUG - SedaQueue                      - org.apache.servicemix.jbi.nmr.flow.seda.SedaQueue$1@374f1c dequeued exchange: InOut[
          id: ID:192.168.0.128-11e076198a3-18:0
          status: Done
          role: provider
          service: {urn:eng:spagic:processes:firstProcess:v0}firstProcess.Transform_v_0
          endpoint: firstProcess.Transform_v_0
          operation: {urn:eng:spagic:processes:firstProcess:v0}run
          in: <?xml version="1.0" encoding="UTF-8"?><jbi:message xmlns:jbi="http://java.sun.com/xml/ns/jbi/wsdl-11-wrapper" xmlns:msg="urn:eng:spagic:processes:firstProcess:v0" xmlns:xsd="http://www.w3.org/2001/XMLSchema" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" name="msgRequest" type="msg:msgRequest" version="1.0"><jbi:part><urn:payload xmlns:urn="urn:eng:spagic">?</urn:payload></jbi:part></jbi:message>
          out: <?xml version="1.0" encoding="UTF-8"?><jbi:message xmlns:jbi="http://java.sun.com/xml/ns/jbi/wsdl-11-wrapper" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" name="msgRequest" type="msg:msgRequest" version="1.0"><jbi:part><urn:payload xmlns:urn="urn:eng:spagic">?</urn:payload></jbi:part></jbi:message>
        ]
        
        Show
        Guillaume Nodet added a comment - I've run your SA and launch a simple soap request. I can see only 3 messages there. Are you sure the problem does not come from your listener somehow ? IIRC, listeners are invoked when messages are sent and accepted, so the listener should be called 6 times actually. DEBUG - CxfBcComponent - Created correlation id: ID:192.168.0.128-11e076198a3-18:0 DEBUG - DeliveryChannelImpl - SendSync ID:192.168.0.128-11e076198a3-18:0 in DeliveryChannel{servicemix-cxf-bc} DEBUG - SecuredBroker - send exchange with secure broker DEBUG - SecuredBroker - service name :{urn:eng:spagic:processes:firstProcess:v0}firstProcess.Transform_v_0 DEBUG - SecuredBroker - operation name :{urn:eng:spagic:processes:firstProcess:v0}run DEBUG - SedaFlow - Called Flow send DEBUG - DeliveryChannelImpl - Waiting for exchange ID:192.168.0.128-11e076198a3-18:0 (8ccd21) to be answered in DeliveryChannel{servicemix-cxf-bc} from sendSync DEBUG - SedaQueue - org.apache.servicemix.jbi.nmr.flow.seda.SedaQueue$1@ef6abe dequeued exchange: InOut[ id: ID:192.168.0.128-11e076198a3-18:0 status: Active role: provider service: {urn:eng:spagic:processes:firstProcess:v0}firstProcess.Transform_v_0 endpoint: firstProcess.Transform_v_0 operation: {urn:eng:spagic:processes:firstProcess:v0}run in: <?xml version= "1.0" encoding= "UTF-8" ?><jbi:message xmlns:jbi= "http: //java.sun.com/xml/ns/jbi/wsdl-11-wrapper" xmlns:msg= "urn:eng:spagic:processes:firstProcess:v0" xmlns:xsd= "http://www.w3.org/2001/XMLSchema" xmlns:xsi= "http://www.w3.org/2001/XMLSchema-instance" name= "msgRequest" type= "msg:msgRequest" version= "1.0" ><jbi:part><urn:payload xmlns:urn= "urn:eng:spagic" >?</urn:payload></jbi:part></jbi:message> ] DEBUG - DeliveryChannelImpl - Send ID:192.168.0.128-11e076198a3-18:0 in DeliveryChannel{firstProcess.Transform_v_0} DEBUG - SecuredBroker - send exchange with secure broker DEBUG - SedaFlow - Called Flow send DEBUG - SedaQueue - org.apache.servicemix.jbi.nmr.flow.seda.SedaQueue$1@e883ec dequeued exchange: InOut[ id: ID:192.168.0.128-11e076198a3-18:0 status: Active role: consumer service: {urn:eng:spagic:processes:firstProcess:v0}firstProcess.Transform_v_0 endpoint: firstProcess.Transform_v_0 operation: {urn:eng:spagic:processes:firstProcess:v0}run in: <?xml version= "1.0" encoding= "UTF-8" ?><jbi:message xmlns:jbi= "http: //java.sun.com/xml/ns/jbi/wsdl-11-wrapper" xmlns:msg= "urn:eng:spagic:processes:firstProcess:v0" xmlns:xsd= "http://www.w3.org/2001/XMLSchema" xmlns:xsi= "http://www.w3.org/2001/XMLSchema-instance" name= "msgRequest" type= "msg:msgRequest" version= "1.0" ><jbi:part><urn:payload xmlns:urn= "urn:eng:spagic" >?</urn:payload></jbi:part></jbi:message> out: <?xml version= "1.0" encoding= "UTF-8" ?><jbi:message xmlns:jbi= "http: //java.sun.com/xml/ns/jbi/wsdl-11-wrapper" xmlns:xsi= "http://www.w3.org/2001/XMLSchema-instance" name= "msgRequest" type= "msg:msgRequest" version= "1.0" ><jbi:part><urn:payload xmlns:urn= "urn:eng:spagic" >?</urn:payload></jbi:part></jbi:message> ] DEBUG - DeliveryChannelImpl - Notifying exchange ID:192.168.0.128-11e076198a3-18:0(8ccd21) in DeliveryChannel{servicemix-cxf-bc} from processInboundSynchronousExchange DEBUG - DeliveryChannelImpl - Notified: ID:192.168.0.128-11e076198a3-18:0(8ccd21) in DeliveryChannel{servicemix-cxf-bc} from sendSync DEBUG - DeliveryChannelImpl - Send ID:192.168.0.128-11e076198a3-18:0 in DeliveryChannel{servicemix-cxf-bc} DEBUG - SecuredBroker - send exchange with secure broker DEBUG - SedaFlow - Called Flow send DEBUG - SedaQueue - org.apache.servicemix.jbi.nmr.flow.seda.SedaQueue$1@374f1c dequeued exchange: InOut[ id: ID:192.168.0.128-11e076198a3-18:0 status: Done role: provider service: {urn:eng:spagic:processes:firstProcess:v0}firstProcess.Transform_v_0 endpoint: firstProcess.Transform_v_0 operation: {urn:eng:spagic:processes:firstProcess:v0}run in: <?xml version= "1.0" encoding= "UTF-8" ?><jbi:message xmlns:jbi= "http: //java.sun.com/xml/ns/jbi/wsdl-11-wrapper" xmlns:msg= "urn:eng:spagic:processes:firstProcess:v0" xmlns:xsd= "http://www.w3.org/2001/XMLSchema" xmlns:xsi= "http://www.w3.org/2001/XMLSchema-instance" name= "msgRequest" type= "msg:msgRequest" version= "1.0" ><jbi:part><urn:payload xmlns:urn= "urn:eng:spagic" >?</urn:payload></jbi:part></jbi:message> out: <?xml version= "1.0" encoding= "UTF-8" ?><jbi:message xmlns:jbi= "http: //java.sun.com/xml/ns/jbi/wsdl-11-wrapper" xmlns:xsi= "http://www.w3.org/2001/XMLSchema-instance" name= "msgRequest" type= "msg:msgRequest" version= "1.0" ><jbi:part><urn:payload xmlns:urn= "urn:eng:spagic" >?</urn:payload></jbi:part></jbi:message> ]
        Hide
        Guillaume Nodet added a comment -

        Another point is that the NMR strongly checks the state of the JBI exchanges, so there is no way an exchange could be sent one more time than expected.

        Show
        Guillaume Nodet added a comment - Another point is that the NMR strongly checks the state of the JBI exchanges, so there is no way an exchange could be sent one more time than expected.
        Hide
        Andrea Zoppello added a comment -

        Hi Guillaume,

        I've attached the code of the listener, as you could see we trace only the exchange sent event.

        BTW

        I've noticed this error in the use case when i'm using a process very similar to the example attached but using servicemix-bean instead of lw-container.

        Andrea

        Show
        Andrea Zoppello added a comment - Hi Guillaume, I've attached the code of the listener, as you could see we trace only the exchange sent event. BTW I've noticed this error in the use case when i'm using a process very similar to the example attached but using servicemix-bean instead of lw-container. Andrea
        Hide
        Guillaume Nodet added a comment -

        I may have identified the problem.
        When using sendSync (which is the case from cxf-bc), the listener should be called when the exchange is sent with an EXCHANGE_SENT event, and when the exchange comes back with an EXCHANGE_ACCEPTED.
        IN the DeliveryChannelImpl, line 495, (in servicemix-core) there is a call to

          l[i].exchangeSent(event);
        

        but I think it should be

          l[i].exchangeAccepted(event); 
        

        Could you see if this change fix the behavior for you and I would apply that patch.

        Show
        Guillaume Nodet added a comment - I may have identified the problem. When using sendSync (which is the case from cxf-bc), the listener should be called when the exchange is sent with an EXCHANGE_SENT event, and when the exchange comes back with an EXCHANGE_ACCEPTED. IN the DeliveryChannelImpl, line 495, (in servicemix-core) there is a call to l[i].exchangeSent(event); but I think it should be l[i].exchangeAccepted(event); Could you see if this change fix the behavior for you and I would apply that patch.
        Hide
        Andrea Zoppello added a comment -

        Guillaume,

        I'm going to test but what i cannot figure is because if instead of
        a process with lw ( CXF-BC <-> LW ), i use the same process using the
        same pojo component ( extending TransformBeanSupport instead of
        TransformComponentSupport ) and having the process as CXFBC <->SMXBean
        i have the pojo component hanging saying it could not handle an exchange in illegal
        state.

        We have started investigating the excahnges sent after we've found this.

        Any idea??

        Show
        Andrea Zoppello added a comment - Guillaume, I'm going to test but what i cannot figure is because if instead of a process with lw ( CXF-BC <-> LW ), i use the same process using the same pojo component ( extending TransformBeanSupport instead of TransformComponentSupport ) and having the process as CXFBC <->SMXBean i have the pojo component hanging saying it could not handle an exchange in illegal state. We have started investigating the excahnges sent after we've found this. Any idea??
        Hide
        Guillaume Nodet added a comment -

        A simple workaround for now would be to check the kind of message: EXCHANGE_SENT or EXCHANGE_ACCEPTED in your listener and discard the accepted ones.

        Show
        Guillaume Nodet added a comment - A simple workaround for now would be to check the kind of message: EXCHANGE_SENT or EXCHANGE_ACCEPTED in your listener and discard the accepted ones.
        Hide
        Guillaume Nodet added a comment -

        I guess the servicemix-bean problem is a different issue. It's really easy to mess with JBI exchanges states and such.
        You may want to open another issue for that, but I would suspect either the TransformBeanSupport or your own code.

        Show
        Guillaume Nodet added a comment - I guess the servicemix-bean problem is a different issue. It's really easy to mess with JBI exchanges states and such. You may want to open another issue for that, but I would suspect either the TransformBeanSupport or your own code.
        Hide
        Andrea Zoppello added a comment -

        Yes Guillaume,

        It could be mine problems, but it's a little strange that with the same POJO bean if i use another
        http input/output binding components, for example the old http all is ok.

        HTTPInputOutput <-> POJOBean ( All is OK and smx-bean is not giving any error )
        CXFBCInputOutput <-> POJOBean ( The problem arises... )

        Show
        Andrea Zoppello added a comment - Yes Guillaume, It could be mine problems, but it's a little strange that with the same POJO bean if i use another http input/output binding components, for example the old http all is ok. HTTPInputOutput <-> POJOBean ( All is OK and smx-bean is not giving any error ) CXFBCInputOutput <-> POJOBean ( The problem arises... )
        Hide
        Freeman Fang added a comment -

        Hi Andrea,

        I think the difference you see between the http component and cxf bc component is that http component use send() but cxf component by default use sendSync().
        You can add attribute synchronous="false" for cxf bc endpoint to see what happen.

        Freeman

        Show
        Freeman Fang added a comment - Hi Andrea, I think the difference you see between the http component and cxf bc component is that http component use send() but cxf component by default use sendSync(). You can add attribute synchronous="false" for cxf bc endpoint to see what happen. Freeman
        Hide
        Guillaume Nodet added a comment -

        Sending src/main/java/org/apache/servicemix/jbi/messaging/DeliveryChannelImpl.java
        Transmitting file data .
        Committed revision 724301.

        Sending src/main/java/org/apache/servicemix/jbi/messaging/DeliveryChannelImpl.java
        Transmitting file data .
        Committed revision 724299.

        Show
        Guillaume Nodet added a comment - Sending src/main/java/org/apache/servicemix/jbi/messaging/DeliveryChannelImpl.java Transmitting file data . Committed revision 724301. Sending src/main/java/org/apache/servicemix/jbi/messaging/DeliveryChannelImpl.java Transmitting file data . Committed revision 724299.

          People

          • Assignee:
            Guillaume Nodet
            Reporter:
            Gianfranco Boccalon
          • Votes:
            0 Vote for this issue
            Watchers:
            0 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved:

              Development