1 Reply Latest reply on Jan 10, 2007 5:05 AM by njipwo Bertrand

    Joss.remoting.Client: invoke called, but our invoker is disc

    njipwo Bertrand Newbie

      Hello,

      i have the following problem. I hope hier in the remoting forum i can find help. For Background information see the other thread: http://www.jboss.com/index.html?module=bb&op=viewtopic&t=98256

      I have a BPEL process invoking my deployed service. The remote service receive the request and process it. It generate a response and send (try to send) it back to the running bpel BPEL process. Wright know the connection with the invoker is losed see:

      2007-01-04 20:24:29,948 DEBUG [org.jbpm.bpel.relation.jms.RelationContext] initialized partner reference: instance=org.jbpm.bpel.service.exe.PartnerLinkInstance@ae8542[name=SchufaLink,id=0], reference=org.jbpm.bpel.service.exe.wsa.WsaEndpointReference@19f410[address=USE_ACTUAL_URI_FROM_CATALOG,portType={urn:samples:schufa}SchufaWS,service={urn:samples:schufa}SchufaWSService]
      2007-01-04 20:24:30,138 DEBUG [org.jboss.ws.server.ServiceEndpoint] WSDL request, using host: milaine
      2007-01-04 20:24:30,178 DEBUG [org.jboss.ws.server.WSDLRequestHandler] Mapping import from 'schufa.wsdl' to 'http://milaine:8080/schufa/schufaWS?wsdl&resource=schufa.wsdl'
      2007-01-04 20:24:30,278 DEBUG [org.jboss.ws.server.ServiceEndpoint] WSDL request, using host: milaine
      2007-01-04 20:24:30,368 DEBUG [org.jbpm.bpel.relation.jms.RelationContext] selected partner port: instance=org.jbpm.bpel.service.exe.PartnerLinkInstance@ae8542[name=SchufaLink,id=0], port=SchufaService
      2007-01-04 20:24:30,408 INFO [STDOUT] PortConsumer: AddresseLocation configure to: http://127.0.0.1:8081/creditprocess/schufa
      2007-01-04 20:24:30,419 DEBUG [org.hibernate.impl.SessionImpl] initializing proxy: [org.jbpm.bpel.wsdl.impl.OperationImpl#82]
      2007-01-04 20:24:30,419 DEBUG [org.hibernate.cache.NonstrictReadWriteCache] Cache lookup: org.jbpm.bpel.wsdl.impl.OperationImpl#82
      2007-01-04 20:24:30,419 DEBUG [org.hibernate.cache.EhCache] key: org.jbpm.bpel.wsdl.impl.OperationImpl#82
      2007-01-04 20:24:30,419 DEBUG [org.hibernate.cache.EhCache] Element for org.jbpm.bpel.wsdl.impl.OperationImpl#82 is null
      2007-01-04 20:24:30,419 DEBUG [org.hibernate.cache.NonstrictReadWriteCache] Cache miss
      2007-01-04 20:24:30,419 DEBUG [org.hibernate.loader.Loader] loading entity: [org.jbpm.bpel.wsdl.impl.OperationImpl#82]
      2007-01-04 20:24:30,419 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
      2007-01-04 20:24:30,419 DEBUG [org.hibernate.SQL] select operationi0_.id as id60_0_, operationi0_.NAME_ as NAME2_60_0_, operationi0_.STYLE_ as STYLE3_60_0_, operationi0_.INPUT_ as INPUT4_60_0_, operationi0_.OUTPUT_ as OUTPUT5_60_0_ from WSDL_OPERATION operationi0_ where operationi0_.id=?
      2007-01-04 20:24:30,419 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to open ResultSet (open ResultSets: 0, globally: 0)
      2007-01-04 20:24:30,419 DEBUG [org.hibernate.loader.Loader] result row: EntityKey[org.jbpm.bpel.wsdl.impl.OperationImpl#82]
      2007-01-04 20:24:30,419 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to close ResultSet (open ResultSets: 1, globally: 1)
      2007-01-04 20:24:30,419 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
      2007-01-04 20:24:30,419 DEBUG [org.hibernate.engine.TwoPhaseLoad] resolving associations for [org.jbpm.bpel.wsdl.impl.OperationImpl#82]
      2007-01-04 20:24:30,419 DEBUG [org.hibernate.engine.TwoPhaseLoad] adding entity to second-level cache: [org.jbpm.bpel.wsdl.impl.OperationImpl#82]
      2007-01-04 20:24:30,429 DEBUG [org.hibernate.cache.NonstrictReadWriteCache] Caching: org.jbpm.bpel.wsdl.impl.OperationImpl#82
      2007-01-04 20:24:30,429 DEBUG [net.sf.ehcache.Cache] org.jbpm.bpel.wsdl.impl.OperationImpl: Is element with key org.jbpm.bpel.wsdl.impl.OperationImpl#81 expired?: false
      2007-01-04 20:24:30,429 DEBUG [org.hibernate.engine.TwoPhaseLoad] done materializing entity [org.jbpm.bpel.wsdl.impl.OperationImpl#82]
      2007-01-04 20:24:30,429 DEBUG [org.hibernate.engine.StatefulPersistenceContext] initializing non-lazy collections
      2007-01-04 20:24:30,429 DEBUG [org.hibernate.loader.Loader] done entity load
      2007-01-04 20:24:30,429 INFO [STDOUT] JmsRelationService: Requested Operation by invoker: validCustomer
      2007-01-04 20:24:30,439 DEBUG [org.jbpm.bpel.relation.jms.JmsRelationService] invoking: partnerLink=54, operation=validCustomer, input={_surname=[_surname: null], _firstname=[_firstname: null]}
      2007-01-04 20:24:30,459 INFO [STDOUT] PortConsumer: Builded SOAPMessage: org.jboss.ws.soap.SOAPMessageImpl@e28347
      2007-01-04 20:24:30,619 DEBUG [org.jboss.ws.soap.SOAPConnectionImpl] Get locator for: http://127.0.0.1:8081/creditprocess/schufa

      2007-01-04 20:24:30,949 DEBUG [org.jboss.remoting.Client] invoke called, but our invoker is disconnected, discarding and fetching another fresh invoker for: InvokerLocator [http://127.0.0.1:8081/creditprocess/schufa]

      2007-01-04 20:24:30,949 DEBUG [org.jboss.remoting.transport.http.HTTPClientInvoker] connect called for: org.jboss.remoting.transport.http.HTTPClientInvoker@a76306
      2007-01-04 20:24:30,959 DEBUG [org.jboss.remoting.transport.http.HTTPClientInvoker] Setting request header with SOAPAction : "urn:samples:schufa:validCustomer"
      2007-01-04 20:24:30,959 DEBUG [org.jboss.remoting.transport.http.HTTPClientInvoker] Setting request header with Content-Type : text/xml; charset=UTF-8
      2007-01-04 20:25:00,612 INFO [STDOUT] ================================================
      2007-01-04 20:25:00,612 INFO [STDOUT] Schufa web service B: Start method validCustomer
      2007-01-04 20:25:00,612 INFO [STDOUT] - SchufaWSB.isCustomerRegistrated()...
      2007-01-04 20:25:00,612 INFO [STDOUT] - Is customer "Bertrand", "Njipwo" known?
      2007-01-04 20:25:00,682 INFO [STDOUT] - Result: true
      2007-01-04 20:25:00,682 INFO [STDOUT] - ...SchufaWSB.isCustomerRegistrated() done.
      2007-01-04 20:25:00,682 INFO [STDOUT] - SchufaWSB.isCustomerAuthorized()...
      2007-01-04 20:25:00,682 INFO [STDOUT] - Is customer "Bertrand", "Njipwo" authorized for credits?
      2007-01-04 20:25:00,712 INFO [STDOUT] - Result: true
      2007-01-04 20:25:00,712 INFO [STDOUT] - ...SchufaWSB.isCustomerAuthorized() done.
      2007-01-04 20:25:00,712 INFO [STDOUT] - Customer "Bertrand", "Njipwo" is known and authorized for credits.
      2007-01-04 20:25:00,712 INFO [STDOUT] Schufa web service B: End method validCustomer
      2007-01-04 20:25:00,712 INFO [STDOUT] ==============================================

      2007-01-04 20:25:01,273 DEBUG [org.jboss.ws.binding.soap.SOAPMessageUnMarshaller] getMimeHeaders from: {Content-Length=[398], X-Powered-By=[Servlet 2.4; JBoss-4.0.4.GA (build: CVSTag=JBoss_4_0_4_GA date=200605151000)/Tomcat-5.5], ResponseCodeMessage=OK, null=[HTTP/1.1 200 OK], Date=[Thu, 04 Jan 2007 19:25:00 GMT], Content-Type=[text/xml;charset=utf-8], Server=[Apache-Coyote/1.1], HEADER={SOAPAction="urn:samples:schufa:validCustomer", Content-Type=text/xml; charset=UTF-8}, ResponseCode=200}

      2007-01-04 20:25:01,914 DEBUG [org.jboss.ws.soap.MessageFactoryImpl] createMessage: [contentType=text/xml; charset=utf-8]
      2007-01-04 20:25:01,944 DEBUG

      [org.hibernate.cache.NonstrictReadWriteCache] Cache lookup: org.jbpm.graph.def.Node.exceptionHandlers#463
      ..
      .....
      .......
      ..........


      But the generated SOAP Message (Response) are well received by the Jbossws components org.jboss.remoting.transport.http.HTTPClientInvoker
      and org.jboss.ws.soap.MessageFactoryImp:

      Response Message of remote Host:
      HTTP/1.1 200 OK
      Server: Apache-Coyote/1.1
      X-Powered-By: Servlet 2.4; JBoss-4.0.4.GA (build: CVSTag=JBoss_4_0_4_GA date=200605151000)/Tomcat-5.
      5
      Content-Type: text/xml;charset=utf-8
      Content-Length: 398
      Date: Wed, 03 Jan 2007 21:10:10 GMT
      
      <?xml version="1.0" encoding="UTF-8"?>
       <soapenv:Envelope xmlns:soapenv="http://schemas.xmlsoap.org/soap/envelope/" xmlns:xsd="http://www.w3.org/2001/XMLSchema"
       xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance">
       <soapenv:Body>
       <validCustomerResponse xmlns="urn:samples:schufa">
       <validCustomerReturn>true</validCustomerReturn>
       </validCustomerResponse>
       </soapenv:Body>
       </soapenv:Envelope>


      I think hier the running process instance can't access the generated SOAP Response routed and when the jbpm.bpel module try to access the expected SOAP Message (see following Error log) by reading the RPCBody elements in the output elements, the collection object are not initialised and therefore this cause a NullPointerException.




      2007-01-04 20:25:02,044 DEBUG [org.hibernate.cache.NonstrictReadWriteCache] Cache miss
      2007-01-04 20:25:02,044 DEBUG [org.hibernate.loader.Loader] loading collection: [org.jbpm.graph.def.Node.exceptionHandlers#462]
      2007-01-04 20:25:02,044 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
      2007-01-04 20:25:02,044 DEBUG [org.hibernate.SQL] select exceptionh0_.NODE_ as NODE9_1_, exceptionh0_.ID_ as ID1_1_, exceptionh0_.GRAPHELEMENTINDEX_ as GRAPHELE6_1_, exceptionh0_.ID_ as ID1_3_0_, exceptionh0_.EXCEPTIONCLASSNAME_ as EXCEPTIO2_3_0_, exceptionh0_.TYPE_ as TYPE3_3_0_, exceptionh0_.GRAPHELEMENT_ as GRAPHELE4_3_0_ from JBPM_EXCEPTIONHANDLER exceptionh0_ where exceptionh0_.NODE_=?
      2007-01-04 20:25:02,054 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to open ResultSet (open ResultSets: 0, globally: 0)
      2007-01-04 20:25:02,054 DEBUG [org.hibernate.loader.Loader] result set contains (possibly empty) collection: [org.jbpm.graph.def.Node.exceptionHandlers#462]
      2007-01-04 20:25:02,054 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to close ResultSet (open ResultSets: 1, globally: 1)
      2007-01-04 20:25:02,054 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
      2007-01-04 20:25:02,054 DEBUG [org.hibernate.engine.CollectionLoadContext] 1 collections were found in result set for role: org.jbpm.graph.def.Node.exceptionHandlers
      2007-01-04 20:25:02,054 DEBUG [org.hibernate.engine.CollectionLoadContext] Caching collection: [org.jbpm.graph.def.Node.exceptionHandlers#462]
      2007-01-04 20:25:02,054 DEBUG [org.hibernate.cache.NonstrictReadWriteCache] Caching: org.jbpm.graph.def.Node.exceptionHandlers#462
      2007-01-04 20:25:02,054 DEBUG [net.sf.ehcache.Cache] org.jbpm.graph.def.Node.exceptionHandlers: Is element with key org.jbpm.graph.def.Node.exceptionHandlers#463 expired?: false
      2007-01-04 20:25:02,054 DEBUG [org.hibernate.engine.CollectionLoadContext] collection fully initialized: [org.jbpm.graph.def.Node.exceptionHandlers#462]
      2007-01-04 20:25:02,054 DEBUG [org.hibernate.engine.CollectionLoadContext] 1 collections initialized for role: org.jbpm.graph.def.Node.exceptionHandlers
      2007-01-04 20:25:02,054 DEBUG [org.hibernate.engine.StatefulPersistenceContext] initializing non-lazy collections
      2007-01-04 20:25:02,054 DEBUG [org.hibernate.loader.Loader] done loading collection
      2007-01-04 20:25:02,054 DEBUG [org.jbpm.bpel.relation.jms.StartListener] caught exception while passing control to process, searching for handler
      org.jbpm.graph.def.DelegationException
      at org.jbpm.graph.def.GraphElement.raiseException(GraphElement.java:349)
      at org.jbpm.graph.def.GraphElement.raiseException(GraphElement.java:343)
      at org.jbpm.graph.def.GraphElement.raiseException(GraphElement.java:343)
      at org.jbpm.graph.def.GraphElement.raiseException(GraphElement.java:343)
      at org.jbpm.bpel.def.Activity.enter(Activity.java:88)
      at org.jbpm.graph.def.Transition.take(Transition.java:119)
      at org.jbpm.graph.def.Node.leave(Node.java:382)
      at org.jbpm.bpel.def.Activity.leave(Activity.java:148)
      at org.jbpm.bpel.def.ProcessInstanceStarter.visit(ProcessInstanceStarter.java:43)
      at org.jbpm.bpel.def.Receive.accept(Receive.java:64)
      at org.jbpm.bpel.def.Receive$$FastClassByCGLIB$$516412f0.invoke(<generated>)
      at net.sf.cglib.proxy.MethodProxy.invoke(MethodProxy.java:149)
      at org.hibernate.proxy.pojo.cglib.CGLIBLazyInitializer.intercept(CGLIBLazyInitializer.java:163)
      at org.jbpm.bpel.def.Receive$$EnhancerByCGLIB$$8b85477d.accept(<generated>)
      at org.jbpm.bpel.def.ProcessInstanceStarter.visit(ProcessInstanceStarter.java:82)
      at org.jbpm.bpel.def.Sequence.accept(Sequence.java:84)
      at org.jbpm.bpel.def.ProcessInstanceStarter.visit(ProcessInstanceStarter.java:29)
      at org.jbpm.bpel.def.BpelDefinition.messageReceived(BpelDefinition.java:110)
      at org.jbpm.bpel.relation.jms.StartListener.onMessage(StartListener.java:94)
      at org.jboss.mq.SpyMessageConsumer.run(SpyMessageConsumer.java:694)
      at java.lang.Thread.run(Thread.java:595)
      Caused by: org.jbpm.graph.def.DelegationException
      at org.jbpm.graph.def.GraphElement.raiseException(GraphElement.java:349)
      at org.jbpm.graph.def.GraphElement.raiseException(GraphElement.java:343)
      at org.jbpm.graph.def.GraphElement.raiseException(GraphElement.java:343)
      at org.jbpm.graph.def.GraphElement.raiseException(GraphElement.java:343)
      at org.jbpm.bpel.def.Activity.enter(Activity.java:88)
      at org.jbpm.graph.def.Transition.take(Transition.java:119)
      at org.jbpm.graph.def.Node.leave(Node.java:382)
      at org.jbpm.bpel.def.Activity.leave(Activity.java:148)
      at org.jbpm.bpel.def.Assign.execute(Assign.java:41)
      at org.jbpm.bpel.def.Activity.enter(Activity.java:83)
      ... 16 more
      Caused by: java.lang.NullPointerException
      at org.jbpm.bpel.xml.util.XmlUtil.copyAttributes(XmlUtil.java:520)
      at org.jbpm.bpel.xml.util.XmlUtil.copy(XmlUtil.java:485)
      at org.jbpm.bpel.service.consumer.PortConsumer.readRpcBody(PortConsumer.java:345)
      at org.jbpm.bpel.service.consumer.PortConsumer.readMessage(PortConsumer.java:313)
      at org.jbpm.bpel.service.consumer.PortConsumer.call(PortConsumer.java:107)
      at org.jbpm.bpel.relation.jms.JmsRelationService.invoke(JmsRelationService.java:145)
      at org.jbpm.bpel.def.Invoke.execute(Invoke.java:28)
      at org.jbpm.bpel.def.Activity.enter(Activity.java:83)

      ... 21 more
      2007-01-04 20:25:02,064 ERROR [org.jbpm.bpel.relation.jms.StartListener] could not start process instance
      org.jbpm.graph.def.DelegationException
      at org.jbpm.graph.def.GraphElement.raiseException(GraphElement.java:349)
      at org.jbpm.graph.def.GraphElement.raiseException(GraphElement.java:343)
      at org.jbpm.bpel.relation.jms.StartListener.onMessage(StartListener.java:98)
      at org.jboss.mq.SpyMessageConsumer.run(SpyMessageConsumer.java:694)
      at java.lang.Thread.run(Thread.java:595)
      Caused by: org.jbpm.graph.def.DelegationException
      at org.jbpm.graph.def.GraphElement.raiseException(GraphElement.java:349)
      at org.jbpm.graph.def.GraphElement.raiseException(GraphElement.java:343)
      at org.jbpm.graph.def.GraphElement.raiseException(GraphElement.java:343)
      at org.jbpm.graph.def.GraphElement.raiseException(GraphElement.java:343)
      at org.jbpm.bpel.def.Activity.enter(Activity.java:88)
      at org.jbpm.graph.def.Transition.take(Transition.java:119)
      at org.jbpm.graph.def.Node.leave(Node.java:382)
      at org.jbpm.bpel.def.Activity.leave(Activity.java:148)
      at org.jbpm.bpel.def.ProcessInstanceStarter.visit(ProcessInstanceStarter.java:43)
      at org.jbpm.bpel.def.Receive.accept(Receive.java:64)
      at org.jbpm.bpel.def.Receive$$FastClassByCGLIB$$516412f0.invoke(<generated>)
      at net.sf.cglib.proxy.MethodProxy.invoke(MethodProxy.java:149)
      at org.hibernate.proxy.pojo.cglib.CGLIBLazyInitializer.intercept(CGLIBLazyInitializer.java:163)
      at org.jbpm.bpel.def.Receive$$EnhancerByCGLIB$$8b85477d.accept(<generated>)
      at org.jbpm.bpel.def.ProcessInstanceStarter.visit(ProcessInstanceStarter.java:82)
      at org.jbpm.bpel.def.Sequence.accept(Sequence.java:84)
      at org.jbpm.bpel.def.ProcessInstanceStarter.visit(ProcessInstanceStarter.java:29)
      at org.jbpm.bpel.def.BpelDefinition.messageReceived(BpelDefinition.java:110)
      at org.jbpm.bpel.relation.jms.StartListener.onMessage(StartListener.java:94)
      ... 2 more
      Caused by: org.jbpm.graph.def.DelegationException
      at org.jbpm.graph.def.GraphElement.raiseException(GraphElement.java:349)
      at org.jbpm.graph.def.GraphElement.raiseException(GraphElement.java:343)
      at org.jbpm.graph.def.GraphElement.raiseException(GraphElement.java:343)
      at org.jbpm.graph.def.GraphElement.raiseException(GraphElement.java:343)
      at org.jbpm.bpel.def.Activity.enter(Activity.java:88)
      at org.jbpm.graph.def.Transition.take(Transition.java:119)
      at org.jbpm.graph.def.Node.leave(Node.java:382)
      at org.jbpm.bpel.def.Activity.leave(Activity.java:148)
      at org.jbpm.bpel.def.Assign.execute(Assign.java:41)
      at org.jbpm.bpel.def.Activity.enter(Activity.java:83)
      ... 16 more
      Caused by: java.lang.NullPointerException
      at org.jbpm.bpel.xml.util.XmlUtil.copyAttributes(XmlUtil.java:520)
      at org.jbpm.bpel.xml.util.XmlUtil.copy(XmlUtil.java:485)
      at org.jbpm.bpel.service.consumer.PortConsumer.readRpcBody(PortConsumer.java:345)
      at org.jbpm.bpel.service.consumer.PortConsumer.readMessage(PortConsumer.java:313)
      at org.jbpm.bpel.service.consumer.PortConsumer.call(PortConsumer.java:107)
      at org.jbpm.bpel.relation.jms.JmsRelationService.invoke(JmsRelationService.java:145)
      at org.jbpm.bpel.def.Invoke.execute(Invoke.java:28)
      at org.jbpm.bpel.def.Activity.enter(Activity.java:83)
      ... 21 more
      2007-01-04 20:25:02,214 DEBUG [org.jbpm.JbpmContext] closing JbpmContext


      At this point of time i don't know if this issue is related to the use of wrong jbossws bibliotheke instead of axis one and why i can't access the generated SOAP Response within the bpel process after the jbossws create a new message and failed to initialyse his contain by copying his message parts.


      Any one has an idee what is wrong hier?

      Thanks for any suggestion.