3 Replies Latest reply on Feb 17, 2011 10:04 AM by Fernando Salceda

    Premature end of file

    Fernando Salceda Novice

      Using FuseESB 4.3.0-fuse-03-00, servicemix cxfbc:consumer with jbi endpoints, camel RecipientList and servicemix cxfb:provider. After a while I receive empty response messages and log shows only:

       

      18:13:33,882 | DEBUG | vider-thread-398 | OsgiCamelJbiComponent            | icemix.common.AsyncBaseLifeCycle  586 | 94 - servicemix-common - 2010.02.0.fuse-02-00 | Received exchange: status: Done, role: provider

      18:13:33,882 | DEBUG | vider-thread-398 | OsgiCamelJbiComponent            | icemix.common.AsyncBaseLifeCycle  647 | 94 - servicemix-common - 2010.02.0.fuse-02-00 | Retrieved correlation id: 81eb8dda-4937-4b54-8e73-0799b5698414

      18:13:33,882 | DEBUG | sumer-thread-177 | CxfBcComponent                   | icemix.common.AsyncBaseLifeCycle  586 | 94 - servicemix-common - 2010.02.0.fuse-02-00 | Received exchange: status: Active, role: consumer

      18:13:33,882 | DEBUG | sumer-thread-177 | CxfBcComponent                   | icemix.common.AsyncBaseLifeCycle  647 | 94 - servicemix-common - 2010.02.0.fuse-02-00 | Retrieved correlation id: 81eb8dda-4937-4b54-8e73-0799b5698414

       

      But when all works fine (omitted In and Out Messages):

       

      18:15:27,760 | DEBUG | vider-thread-401 | OsgiCamelJbiComponent            | icemix.common.AsyncBaseLifeCycle  586 | 94 - servicemix-common - 2010.02.0.fuse-02-00 | Received exchange: status: Done, role: provider

      18:15:27,760 | DEBUG | vider-thread-401 | OsgiCamelJbiComponent            | icemix.common.AsyncBaseLifeCycle  647 | 94 - servicemix-common - 2010.02.0.fuse-02-00 | Retrieved correlation id: 546730a1-dc8a-4934-a829-5dc381637c92

      18:15:27,760 | DEBUG | sumer-thread-178 | CxfBcComponent                   | icemix.common.AsyncBaseLifeCycle  586 | 94 - servicemix-common - 2010.02.0.fuse-02-00 | Received exchange: status: Active, role: consumer

      18:15:27,760 | DEBUG | sumer-thread-178 | CxfBcComponent                   | icemix.common.AsyncBaseLifeCycle  647 | 94 - servicemix-common - 2010.02.0.fuse-02-00 | Retrieved correlation id: 546730a1-dc8a-4934-a829-5dc381637c92

      18:15:27,760 | DEBUG | tp-1855212917-12 | jetty                            | service.jetty.internal.JCLLogger   85 | 108 - org.ops4j.pax.web.pax-web-jetty - 0.7.3 | resume continuation RetryContinuation@1144063451,pending,resumed

      18:15:27,760 | DEBUG | ctoryServicePort | jetty                            | service.jetty.internal.JCLLogger   85 | 108 - org.ops4j.pax.web.pax-web-jetty - 0.7.3 | REQUEST /PielStreetDirectoryServicePort on org.mortbay.jetty.HttpConnection@25b98cc0

      18:15:27,760 | DEBUG | ctoryServicePort | JettyHTTPDestination             | .http_jetty.JettyHTTPDestination  289 |  -  -  | Service http request on thread: Thread[452096943@qtp-1855212917-12 - /PielStreetDirectoryServicePort,5,main]

      18:15:27,760 | DEBUG | ctoryServicePort | PhaseInterceptorChain            | .cxf.phase.PhaseInterceptorChain  240 |  -  -  | Invoking handleMessage on interceptor org.apache.servicemix.cxfbc.CxfBcConsumer$JbiInvokerInterceptor@1e7df4ea

      18:15:27,760 | DEBUG | ctoryServicePort | PhaseInterceptorChain            | .cxf.phase.PhaseInterceptorChain  240 |  -  -  | Invoking handleMessage on interceptor org.apache.servicemix.cxfbc.CxfBcConsumer$JbiPostInvokerInterceptor@265f9d82

      18:15:27,760 | DEBUG | ctoryServicePort | PhaseInterceptorChain            | .cxf.phase.PhaseInterceptorChain  240 |  -  -  | Invoking handleMessage on interceptor org.apache.cxf.interceptor.OutgoingChainInterceptor@4f5dd57c

      18:15:27,760 | DEBUG | ctoryServicePort | OutgoingChainInterceptor         | rceptor.OutgoingChainInterceptor  177 |  -  -  | Interceptors contributed by bus:

      18:15:27,760 | DEBUG | ctoryServicePort | OutgoingChainInterceptor         | rceptor.OutgoingChainInterceptor  181 |  -  -  | Interceptors contributed by service:

      18:15:27,760 | DEBUG | ctoryServicePort | OutgoingChainInterceptor         | rceptor.OutgoingChainInterceptor  185 |  -  -  | Interceptors contributed by endpoint:

      18:15:27,760 | DEBUG | ctoryServicePort | OutgoingChainInterceptor         | rceptor.OutgoingChainInterceptor  191 |  -  -  | Interceptors contributed by binding:

      18:15:27,760 | DEBUG | ctoryServicePort | PhaseInterceptorChain            | .cxf.phase.PhaseInterceptorChain  633 |  -  -  | Chain org.apache.cxf.phase.PhaseInterceptorChain@25e80ed7 was created. Current flow:

        setup

        pre-logical

        post-logical

        prepare-send

        pre-stream

        write

        marshal

       

      18:15:27,760 | DEBUG | ctoryServicePort | PhaseInterceptorChain            | .cxf.phase.PhaseInterceptorChain  240 |  -  -  | Invoking handleMessage on interceptor org.apache.cxf.ws.policy.PolicyOutInterceptor@26ddf0ff

      18:15:27,760 | DEBUG | ctoryServicePort | PhaseInterceptorChain            | .cxf.phase.PhaseInterceptorChain  240 |  -  -  | Invoking handleMessage on interceptor org.apache.cxf.binding.soap.interceptor.SoapHeaderOutFilterInterceptor@6ac92f34

      18:15:27,764 | DEBUG | ctoryServicePort | PhaseInterceptorChain            | .cxf.phase.PhaseInterceptorChain  240 |  -  -  | Invoking handleMessage on interceptor org.apache.cxf.binding.soap.interceptor.SoapPreProtocolOutInterceptor@1abec0de

      18:15:27,764 | DEBUG | ctoryServicePort | PhaseInterceptorChain            | .cxf.phase.PhaseInterceptorChain  240 |  -  -  | Invoking handleMessage on interceptor org.apache.cxf.interceptor.MessageSenderInterceptor@25e7855

      18:15:27,764 | DEBUG | ctoryServicePort | PhaseInterceptorChain            | .cxf.phase.PhaseInterceptorChain  203 |  -  -  | Adding interceptor org.apache.cxf.interceptor.MessageSenderInterceptor$MessageSenderEndingInterceptor@4bf6628e to phase prepare-send-ending

      18:15:27,764 | DEBUG | ctoryServicePort | PhaseInterceptorChain            | .cxf.phase.PhaseInterceptorChain  631 |  -  -  | Chain org.apache.cxf.phase.PhaseInterceptorChain@25e80ed7 was modified. Current flow:

        setup

        pre-logical

        post-logical

        prepare-send

        pre-stream

        write

        marshal

        prepare-send-ending

       

      18:15:27,764 | DEBUG | ctoryServicePort | PhaseInterceptorChain            | .cxf.phase.PhaseInterceptorChain  240 |  -  -  | Invoking handleMessage on interceptor org.apache.servicemix.cxfbc.interceptors.ExtractHeaderPartIntercepor@39cca1d8

      18:15:27,764 | DEBUG | ctoryServicePort | PhaseInterceptorChain            | .cxf.phase.PhaseInterceptorChain  240 |  -  -  | Invoking handleMessage on interceptor org.apache.servicemix.cxfbc.interceptors.MtomCheckInterceptor@5846ba16

      18:15:27,764 | DEBUG | ctoryServicePort | PhaseInterceptorChain            | .cxf.phase.PhaseInterceptorChain  240 |  -  -  | Invoking handleMessage on interceptor org.apache.cxf.interceptor.AttachmentOutInterceptor@18799d4f

      18:15:27,764 | DEBUG | ctoryServicePort | PhaseInterceptorChain            | .cxf.phase.PhaseInterceptorChain  240 |  -  -  | Invoking handleMessage on interceptor org.apache.cxf.interceptor.StaxOutInterceptor@b6327a1

      18:15:27,764 | DEBUG | ctoryServicePort | PhaseInterceptorChain            | .cxf.phase.PhaseInterceptorChain  203 |  -  -  | Adding interceptor org.apache.cxf.interceptor.StaxOutInterceptor$StaxOutEndingInterceptor@6f1a0ec5 to phase pre-stream-ending

      18:15:27,764 | DEBUG | ctoryServicePort | PhaseInterceptorChain            | .cxf.phase.PhaseInterceptorChain  631 |  -  -  | Chain org.apache.cxf.phase.PhaseInterceptorChain@25e80ed7 was modified. Current flow:

        setup

        pre-logical

        post-logical

        prepare-send

        pre-stream

        write

        marshal

        pre-stream-ending

        prepare-send-ending

       

      18:15:27,764 | DEBUG | ctoryServicePort | PhaseInterceptorChain            | .cxf.phase.PhaseInterceptorChain  240 |  -  -  | Invoking handleMessage on interceptor org.apache.cxf.binding.soap.interceptor.SoapOutInterceptor@61683c89

      18:15:27,764 | DEBUG | ctoryServicePort | PhaseInterceptorChain            | .cxf.phase.PhaseInterceptorChain  203 |  -  -  | Adding interceptor org.apache.cxf.binding.soap.interceptor.SoapOutInterceptor$SoapOutEndingInterceptor@1f8921af to phase write-ending

      18:15:27,764 | DEBUG | ctoryServicePort | PhaseInterceptorChain            | .cxf.phase.PhaseInterceptorChain  631 |  -  -  | Chain org.apache.cxf.phase.PhaseInterceptorChain@25e80ed7 was modified. Current flow:

        setup

        pre-logical

        post-logical

        prepare-send

        pre-stream

        write

        marshal

        write-ending

        pre-stream-ending

        prepare-send-ending

       

      18:15:27,764 | DEBUG | ctoryServicePort | PhaseInterceptorChain            | .cxf.phase.PhaseInterceptorChain  240 |  -  -  | Invoking handleMessage on interceptor org.apache.servicemix.cxfbc.interceptors.JbiOutWsdl1Interceptor@196ae899

      18:15:27,768 | DEBUG | ctoryServicePort | PhaseInterceptorChain            | .cxf.phase.PhaseInterceptorChain  240 |  -  -  | Invoking handleMessage on interceptor org.apache.servicemix.cxfbc.interceptors.SetStatusInterceptor@2995898d

      18:15:27,772 | DEBUG | ctoryServicePort | NMR                              | .servicemix.nmr.core.ChannelImpl  274 | 84 - org.apache.servicemix.nmr.core - 1.3.0.fuse-02-00 | Channel org.apache.servicemix.nmr.core.ChannelImpl@62b56d87 dispatching exchange: [

        id:        546730a1-dc8a-4934-a829-5dc381637c92

        mep:       InOut

        status:    Done

        role:      Consumer

        target:    PropertyMatchingReference[{ENDPOINT_NAME=RouterEndpoint, SERVICE_NAME={http://streetdirectory.piel.andago.com}Router}]

        operation: getStreets

        properties: [

            javax.jbi.servicedesc.ServiceEndpoint = org.apache.servicemix.jbi.runtime.impl.EndpointImpl@1c347ccf

            CamelMulticastComplete = true

            JbiOperation = getStreets

            org.apache.servicemix.senderEndpoint = PielStreetDirectoryService:PielStreetDirectoryServicePort

            javax.jbi.messaging.MessageExchange = org.apache.servicemix.jbi.runtime.impl.InOutImpl@5e9a9a88

            CamelMulticastIndex = 0

            CamelToEndpoint = service:http://streetdirectory.piel.andago.com/eibarserviciocallejero-GetStreets

            javax.jbi.ServiceName = Router

            javax.jbi.messaging.sendSync =

            org.apache.servicemix.correlationId = 546730a1-dc8a-4934-a829-5dc381637c92

        ]

        In: [

      ...

          ]

        ]

        Out: [

      ...

        ]

      ]

       

      18:15:27,772 | DEBUG | ctoryServicePort | NMR                              | .servicemix.nmr.core.ChannelImpl  198 | 84 - org.apache.servicemix.nmr.core - 1.3.0.fuse-02-00 | Channel org.apache.servicemix.nmr.core.ChannelImpl@39ee0880 delivering exchange: [

        id:        546730a1-dc8a-4934-a829-5dc381637c92

        mep:       InOut

        status:    Done

        role:      Consumer

        target:    PropertyMatchingReference[{ENDPOINT_NAME=RouterEndpoint, SERVICE_NAME={http://streetdirectory.piel.andago.com}Router}]

        operation: getStreets

        properties: [

            javax.jbi.servicedesc.ServiceEndpoint = org.apache.servicemix.jbi.runtime.impl.EndpointImpl@1c347ccf

            CamelMulticastComplete = true

            JbiOperation = getStreets

            org.apache.servicemix.senderEndpoint = PielStreetDirectoryService:PielStreetDirectoryServicePort

            javax.jbi.messaging.MessageExchange = org.apache.servicemix.jbi.runtime.impl.InOutImpl@5e9a9a88

            CamelMulticastIndex = 0

            CamelToEndpoint = service:http://streetdirectory.piel.andago.com/eibarserviciocallejero-GetStreets

            javax.jbi.ServiceName = Router

            javax.jbi.messaging.sendSync =

            org.apache.servicemix.correlationId = 546730a1-dc8a-4934-a829-5dc381637c92

        ]

        In: [

      ...

          ]

        ]

        Out: [

      ...

        ]

      ]

       

      18:15:27,772 | DEBUG | ctoryServicePort | PhaseInterceptorChain            | .cxf.phase.PhaseInterceptorChain  240 |  -  -  | Invoking handleMessage on interceptor org.apache.cxf.binding.soap.interceptor.SoapOutInterceptor$SoapOutEndingInterceptor@1f8921af

      18:15:27,772 | DEBUG | ctoryServicePort | PhaseInterceptorChain            | .cxf.phase.PhaseInterceptorChain  240 |  -  -  | Invoking handleMessage on interceptor org.apache.cxf.interceptor.StaxOutInterceptor$StaxOutEndingInterceptor@6f1a0ec5

      18:15:27,772 | DEBUG | ctoryServicePort | PhaseInterceptorChain            | .cxf.phase.PhaseInterceptorChain  240 |  -  -  | Invoking handleMessage on interceptor org.apache.cxf.interceptor.MessageSenderInterceptor$MessageSenderEndingInterceptor@4bf6628e

      18:15:27,772 | DEBUG | ctoryServicePort | JettyHTTPDestination             | .http_jetty.JettyHTTPDestination  336 |  -  -  | Finished servicing http request on thread: Thread[452096943@qtp-1855212917-12 - /PielStreetDirectoryServicePort,5,main]

       

       

      The cxf-consumer proptery synchronous is by default false, I think in version 2010.02.0-fuse-02-00 of servicemix-cxf-bc components, isnt'it?

       

      Any Idea of what is happening?

       

      Thx.

        • 1. Re: Premature end of file
          Lars Heinemann Novice

          Could you check if it behaves the same when switching the log level to INFO?

           

          Regards

          Lars

          • 2. Re: Premature end of file
            Fernando Salceda Novice

            This behaviour started with INFO log level, then I setted DEBUG level  to get more info.

            I also had activated streamCache in all my routes.

             

            Edited by: fsalceda on Feb 16, 2011 10:17 AM

            • 3. Re: Premature end of file
              Fernando Salceda Novice

              Debbuging the servicemix-cxfbc component and focusing my attention on CxfBcConsumer class and its process method when It was supposed to process the response, I notice that my cxfbc-consumers that work fine is Pending and run within if condition and my cxfbc-consumer that hangs is not Pending and runs else.

               

                              if (continuation.isPending()) {

                                  continuation.resume();

                                  isSTFlow = false;

                              } else {

                                  isSTFlow = true;

                              }

               

              When all work ok the SetStatusInterceptor intercepts the message and changes exchange status to DONE. But when I call my cxfbc-consumer that dont work it never happens and I get the following response:

               

              HTTP/1.1 200 OK

               

              Connection: close

               

              Server: Jetty(6.1.x)

               

               

               

              without the soap message!

               

               

              I hope that I gave you enough information this time to know what is happening to my cxfbc-consumer. I compared my cxfbc-consumer configurations, and the xbean.xml and pom.xml of the cxfbc-consumer that hang without returning soap messages apparently are the same as those of the other cxfbc-consumers.

               

              Please ask me for any other information that could be helpful to explain what is happening and resolve it.

               

              Thx.