You are viewing a plain text version of this content. The canonical link for it is here.
Posted to user@ode.apache.org by Anup Chandran <an...@3ds.com> on 2007/09/10 23:45:18 UTC
Invoke - with communication error
Alex/Matthieu,
I know this is pretty silly but cant figure what is the issue here...... I
have a runtime error with the following trace..... If i remove the invoke.
from BPEL.. the process runs without errors. Can you tell me what is going
on from the trace? Thanks...
17:40:23,536 DEBUG [ExternalService] Message: <?xml version='1.0'
encoding='utf-8'?><soapenv:Envelope xmlns:soapenv="htt
p://schemas.xmlsoap.org/soap/envelope/"><soapenv:Body><axis2ns16:setAttribute
xmlns:axis2ns16="http://engineering.cbp.jp
o" xmlns:tns1="http://engineering.cbp.jpo">
<axis2ns16:in2
xmlns:ns="http://www.apache.org/ode/pmapi/types/2006/08/02/"
xmlns="http://www.apache.
org/ode/pmapi/types/2006/08/02/">1057</axis2ns16:in2>
</axis2ns16:setAttribute></soapenv:Body></soapenv:Envelope>
DEBUG - GeronimoLog.debug(66) | replyAsync mex=hqejbhcnphr2kte2v4jbl8
17:40:23,536 DEBUG [PartnerRoleMessageExchangeImpl] replyAsync
mex=hqejbhcnphr2kte2v4jbl8
DEBUG - GeronimoLog.debug(66) | Setting execution state on instance 1057
17:40:23,546 DEBUG [BpelRuntimeContextImpl] Setting execution state on
instance 1057
DEBUG - GeronimoLog.debug(66) | Thread[pool-2-thread-9,5,main]:
unlock(iid=1057)
17:40:23,707 DEBUG [InstanceLockManager] Thread[pool-2-thread-9,5,main]:
unlock(iid=1057)
DEBUG - GeronimoLog.debug(66) | Sending stateful TO epr in message header
using session null
17:40:23,717 DEBUG [SessionOutHandler] Sending stateful TO epr in message
header using session null
DEBUG - GeronimoLog.debug(66) | Sending a message containing wsa endpoints
in headers for session passing.
17:40:23,717 DEBUG [SessionOutHandler] Sending a message containing wsa
endpoints in headers for session passing.
DEBUG - GeronimoLog.debug(66) | <?xml version='1.0'
encoding='utf-8'?><soapenv:Envelope xmlns:soapenv="http://schemas.xm
lsoap.org/soap/envelope/"><soapenv:Header><addr:To
xmlns:addr="http://www.w3.org/2005/08/addressing">http://localhost:80
80/ematrix/services/JpoCbpEngineeringCBPWorkflow</addr:To><addr:Action
xmlns:addr="http://www.w3.org/2005/08/addressing"
></addr:Action><addr:ReplyTo
xmlns:addr="http://www.w3.org/2005/08/addressing"><addr:Address>http://www.w3.org/2005/08/a
ddressing/anonymous</addr:Address></addr:ReplyTo><addr:MessageID
xmlns:addr="http://www.w3.org/2005/08/addressing">uuid:
hqejbhcnphr2kte2v4jbl9</addr:MessageID></soapenv:Header><soapenv:Body><axis2ns16:setAttribute
xmlns:axis2ns16="http://en
gineering.cbp.jpo" xmlns:tns1="http://engineering.cbp.jpo">
<axis2ns16:in2
xmlns:ns="http://www.apache.org/ode/pmapi/types/2006/08/02/"
xmlns="http://www.apache.
org/ode/pmapi/types/2006/08/02/">1057</axis2ns16:in2>
</axis2ns16:setAttribute></soapenv:Body></soapenv:Envelope>
17:40:23,717 DEBUG [SessionOutHandler] <?xml version='1.0'
encoding='utf-8'?><soapenv:Envelope xmlns:soapenv="http://sch
emas.xmlsoap.org/soap/envelope/"><soapenv:Header><addr:To
xmlns:addr="http://www.w3.org/2005/08/addressing">http://local
host:8080/ematrix/services/JpoCbpEngineeringCBPWorkflow</addr:To><addr:Action
xmlns:addr="http://www.w3.org/2005/08/addr
essing"></addr:Action><addr:ReplyTo
xmlns:addr="http://www.w3.org/2005/08/addressing"><addr:Address>http://www.w3.org/20
05/08/addressing/anonymous</addr:Address></addr:ReplyTo><addr:MessageID
xmlns:addr="http://www.w3.org/2005/08/addressing
">uuid:hqejbhcnphr2kte2v4jbl9</addr:MessageID></soapenv:Header><soapenv:Body><axis2ns16:setAttribute
xmlns:axis2ns16="ht
tp://engineering.cbp.jpo" xmlns:tns1="http://engineering.cbp.jpo">
<axis2ns16:in2
xmlns:ns="http://www.apache.org/ode/pmapi/types/2006/08/02/"
xmlns="http://www.apache.
org/ode/pmapi/types/2006/08/02/">1057</axis2ns16:in2>
</axis2ns16:setAttribute></soapenv:Body></soapenv:Envelope>
ERROR - GeronimoLog.error(108) | Error sending message
(mex={PartnerRoleMex#hqejbhcnphr2kte2v4jbl8 [PID {http://eclipse.
org/bpel/sample}ECRProcess-9] calling
org.apache.ode.bpel.epr.WSAEndpoint@16fd757.setAttribute(...)}):
java.lang.NullPoi
nterException
org.apache.axis2.AxisFault: java.lang.NullPointerException
at
org.apache.axis2.util.Utils.getInboundFaultFromMessageContext(Utils.java:486)
at
org.apache.axis2.description.OutInAxisOperationClient.handleResponse(OutInAxisOperation.java:343)
at
org.apache.axis2.description.OutInAxisOperationClient.send(OutInAxisOperation.java:389)
at
org.apache.axis2.description.OutInAxisOperationClient.executeImpl(OutInAxisOperation.java:211)
at
org.apache.axis2.client.OperationClient.execute(OperationClient.java:163)
at
org.apache.ode.axis2.ExternalService$1$1.call(ExternalService.java:150)
at
java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:269)
at java.util.concurrent.FutureTask.run(FutureTask.java:123)
at
java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:650)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:675)
at java.lang.Thread.run(Thread.java:595)
17:40:23,737 ERROR [ExternalService] Error sending message
(mex={PartnerRoleMex#hqejbhcnphr2kte2v4jbl8 [PID {http://ecli
pse.org/bpel/sample}ECRProcess-9] calling
org.apache.ode.bpel.epr.WSAEndpoint@16fd757.setAttribute(...)}):
java.lang.Nul
lPointerException
org.apache.axis2.AxisFault: java.lang.NullPointerException
at
org.apache.axis2.util.Utils.getInboundFaultFromMessageContext(Utils.java:486)
at
org.apache.axis2.description.OutInAxisOperationClient.handleResponse(OutInAxisOperation.java:343)
at
org.apache.axis2.description.OutInAxisOperationClient.send(OutInAxisOperation.java:389)
at
org.apache.axis2.description.OutInAxisOperationClient.executeImpl(OutInAxisOperation.java:211)
at
org.apache.axis2.client.OperationClient.execute(OperationClient.java:163)
at
org.apache.ode.axis2.ExternalService$1$1.call(ExternalService.java:150)
at
java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:269)
at java.util.concurrent.FutureTask.run(FutureTask.java:123)
at
java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:650)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:675)
at java.lang.Thread.run(Thread.java:595)
DEBUG - GeronimoLog.trace(54) | Mex[hqejbhcnphr2kte2v4jbl8].setPortOp(...)
17:40:23,747 DEBUG [MessageExchangeImpl]
Mex[hqejbhcnphr2kte2v4jbl8].setPortOp(...)
DEBUG - GeronimoLog.debug(66) | replyWithFailure mex=hqejbhcnphr2kte2v4jbl8
failureType=COMMUNICATION_ERROR description=
Error sending message (mex={PartnerRoleMex#hqejbhcnphr2kte2v4jbl8 [PID
{http://eclipse.org/bpel/sample}ECRProcess-9] cal
ling org.apache.ode.bpel.epr.WSAEndpoint@16fd757.setAttribute(...)}):
java.lang.NullPointerException details=null
17:40:23,747 DEBUG [PartnerRoleMessageExchangeImpl] replyWithFailure
mex=hqejbhcnphr2kte2v4jbl8 failureType=COMMUNICATIO
N_ERROR description=Error sending message
(mex={PartnerRoleMex#hqejbhcnphr2kte2v4jbl8 [PID
{http://eclipse.org/bpel/samp
le}ECRProcess-9] calling
org.apache.ode.bpel.epr.WSAEndpoint@16fd757.setAttribute(...)}):
java.lang.NullPointerException
details=null
DEBUG - GeronimoLog.debug(66) | create work event for
mex=hqejbhcnphr2kte2v4jbl8
17:40:23,747 DEBUG [PartnerRoleMessageExchangeImpl] create work event for
mex=hqejbhcnphr2kte2v4jbl8
DEBUG - GeronimoLog.debug(66) | Thread[pool-2-thread-9,5,main]:
lock(iid=1057, time=1MICROSECONDS)
17:40:23,757 DEBUG [InstanceLockManager] Thread[pool-2-thread-9,5,main]:
lock(iid=1057, time=1MICROSECONDS)
DEBUG - GeronimoLog.debug(66) | Thread[pool-2-thread-9,5,main]:
lock(iid=1057, time=1MICROSECONDS)-->GRANTED
17:40:23,757 DEBUG [InstanceLockManager] Thread[pool-2-thread-9,5,main]:
lock(iid=1057, time=1MICROSECONDS)-->GRANTED
DEBUG - GeronimoLog.debug(66) | >>
handleWorkEvent(jobData={type=INVOKE_RESPONSE, mexid=hqejbhcnphr2kte2v4jbl8,
channel=
54, iid=1057})
17:40:23,757 DEBUG [BpelProcess] >>
handleWorkEvent(jobData={type=INVOKE_RESPONSE, mexid=hqejbhcnphr2kte2v4jbl8,
channel
=54, iid=1057})
--
View this message in context: http://www.nabble.com/Invoke---with-communication-error-tf4418802.html#a12603692
Sent from the Apache Ode User mailing list archive at Nabble.com.
Re: Invoke - with communication error
Posted by Anup Chandran <an...@3ds.com>.
Yes found that the issue is with my assign activity... i think some how the
right inputs are sent out in the invoke... I have logged another posting...
if you can comment on the assign issue it will be helpful.... thanks a lot..
Alex Boisvert wrote:
>
> Hi Anup,
>
> The service is returning a 500 Internal Error... so I think what you
> should
> do is compare the request sent by Ode with that of SoapUI and investigate
> why your service is failing with Ode's request.
>
> I don't think Axis2 should be throwing the NullPointerException either so
> it
> would be nice if you could file a bug report for Axis2 as well.
>
> cheers,
> alex
>
>
> On 9/11/07, Anup Chandran <an...@3ds.com> wrote:
>>
>>
>>
>> The Service works fine when i send request via soapUI.
>>
>> I turned on the httpclient DEBUG.
>>
>> This is trace..
>>
>> DEBUG - GeronimoLog.debug(66) | InvokeResponse event for iid 1202
>> 09:46:35,240 DEBUG [BpelProcess] InvokeResponse event for iid 1202
>> DEBUG - GeronimoLog.debug(66) | Invoking message response for mexid
>> hqejbhcnphr2kvk6gstpxt and channel 40
>> 09:46:35,240 DEBUG [BpelRuntimeContextImpl] Invoking message response for
>> mexid hqejbhcnphr2kvk6gstpxt and channel 40
>> DEBUG - GeronimoLog.debug(66) | Triggering response
>> 09:46:35,240 DEBUG [BpelRuntimeContextImpl] Triggering response
>> DEBUG - GeronimoLog.trace(54) | >>
>> createScopeInstance(parentScopeId=1204,scope={OScope 'UpdateCBPWorkflow'
>> id=144})
>> 09:46:35,536 DEBUG [BpelProcess] >>
>> createScopeInstance(parentScopeId=1204,scope={OScope 'UpdateCBPWorkflow'
>> id=144})
>> DEBUG - GeronimoLog.trace(54) | >>
>> initializeEndpointReferences(parentScopeId=1270,partnerLinks=[])
>> 09:46:35,546 DEBUG [BpelProcess] >>
>> initializeEndpointReferences(parentScopeId=1270,partnerLinks=[])
>> DEBUG - GeronimoLog.debug(66) | INVOKING PARTNER:
>> partnerLink={PartnerLinkInstance partnerLinkDecl=OPartnerLink#44,scope
>> InstanceId=1203}, op=setAttribute channel=InvokeResponseChannel#54)
>> 09:46:35,566 DEBUG [BpelProcess] INVOKING PARTNER:
>> partnerLink={PartnerLinkInstance partnerLinkDecl=OPartnerLink#44,scop
>> eInstanceId=1203}, op=setAttribute channel=InvokeResponseChannel#54)
>> DEBUG - GeronimoLog.debug(66) | INVOKE PARTNER (SEP): sessionId=null
>> partnerSessionId=null
>> 09:46:35,566 DEBUG [BpelRuntimeContextImpl] INVOKE PARTNER (SEP):
>> sessionId=null partnerSessionId=null
>> DEBUG - GeronimoLog.trace(54) |
>> Mex[hqejbhcnphr2kvk6gstpxw].setPortOp(...)
>> 09:46:35,566 DEBUG [MessageExchangeImpl]
>> Mex[hqejbhcnphr2kvk6gstpxw].setPortOp(...)
>> DEBUG - GeronimoLog.debug(66) | Routed: svcQname
>> {http://client.engineering.cbp.jpo}CBPWorkflowService --> null
>> 09:46:35,566 DEBUG [BpelEngineImpl] Routed: svcQname
>> {http://client.engineering.cbp.jpo}CBPWorkflowService --> null
>> DEBUG - GeronimoLog.debug(66) | Invoking a partner operation:
>> setAttribute
>> 09:46:35,566 DEBUG [MessageExchangeContextImpl] Invoking a partner
>> operation: setAttribute
>> DEBUG - GeronimoLog.debug(66) | The service to invoke is the external
>> service org.apache.ode.axis2.ExternalService@d3852
>> 5
>> 09:46:35,566 DEBUG [MessageExchangeContextImpl] The service to invoke is
>> the
>> external service org.apache.ode.axis2.Exter
>> nalService@d38525
>> DEBUG - GeronimoLog.debug(66) | Resolving endpoint reference <?xml
>> version="1.0" encoding="UTF-8"?>
>> <service-ref
>> xmlns="http://docs.oasis-open.org/wsbpel/2.0/serviceref
>> "><EndpointReference
>> xmlns="http://www.w3.org/2005/0
>> 8/addressing"><Metadata><ServiceName
>> xmlns="http://www.w3.org/2006/05/addressing/wsdl"
>> EndpointName="JpoCbpEngineeringCB
>> PWorkflow"
>> xmlns:servicens="http://client.engineering.cbp.jpo
>> ">servicens:CBPWorkflowService</ServiceName></Metadata><Add
>> ress>http://localhost:8080/ematrix/services/JpoCbpEngineeringCBPWorkflow
>> </Address></EndpointReference></service-ref>
>> 09:46:35,566 DEBUG [EndpointReferenceContextImpl] Resolving endpoint
>> reference <?xml version="1.0" encoding="UTF-8"?>
>> <service-ref
>> xmlns="http://docs.oasis-open.org/wsbpel/2.0/serviceref
>> "><EndpointReference
>> xmlns="http://www.w3.org/2005/0
>> 8/addressing"><Metadata><ServiceName
>> xmlns="http://www.w3.org/2006/05/addressing/wsdl"
>> EndpointName="JpoCbpEngineeringCB
>> PWorkflow"
>> xmlns:servicens="http://client.engineering.cbp.jpo
>> ">servicens:CBPWorkflowService</ServiceName></Metadata><Add
>> ress>http://localhost:8080/ematrix/services/JpoCbpEngineeringCBPWorkflow
>> </Address></EndpointReference></service-ref>
>> DEBUG - GeronimoLog.debug(66) | GET MEX property
>> org.apache.ode.bpel.partnerRoleSessionId = null
>> 09:46:35,566 DEBUG [MessageExchangeImpl] GET MEX property
>> org.apache.ode.bpel.partnerRoleSessionId = null
>> DEBUG - GeronimoLog.debug(66) | GET MEX property
>> org.apache.ode.bpel.myRoleSessionId = null
>> 09:46:35,566 DEBUG [MessageExchangeImpl] GET MEX property
>> org.apache.ode.bpel.myRoleSessionId = null
>> DEBUG - GeronimoLog.debug(66) | My-Role EPR not specified, SEP will not
>> be
>> used.
>> 09:46:35,566 DEBUG [ExternalService] My-Role EPR not specified, SEP will
>> not
>> be used.
>> DEBUG - GeronimoLog.debug(66) | Axis2 sending message to
>> http://localhost:8080/ematrix/services/JpoCbpEngineeringCBPWork
>> flow using MEX {PartnerRoleMex#hqejbhcnphr2kvk6gstpxw [PID
>> {http://eclipse.org/bpel/sample}ECRProcess-9] calling org.apa
>> che.ode.bpel.epr.WSAEndpoint@11dca40.setAttribute(...)}
>> 09:46:35,566 DEBUG [ExternalService] Axis2 sending message to
>> http://localhost:8080/ematrix/services/JpoCbpEngineeringCB
>> PWorkflow using MEX {PartnerRoleMex#hqejbhcnphr2kvk6gstpxw [PID
>> {http://eclipse.org/bpel/sample}ECRProcess-9] calling or
>> g.apache.ode.bpel.epr.WSAEndpoint@11dca40.setAttribute(...)}
>> DEBUG - GeronimoLog.debug(66) | Message: <?xml version='1.0'
>> encoding='utf-8'?><soapenv:Envelope xmlns:soapenv="http://s
>> chemas.xmlsoap.org/soap/envelope/"><soapenv:Body><axis2ns4:setAttribute
>> xmlns:axis2ns4="http://engineering.cbp.jpo" xmln
>> s:tns1="http://engineering.cbp.jpo">
>> <tns1:in2
>> xmlns:ns="http://www.apache.org/ode/pmapi/types/2006/08/02/"
>> xmlns="http://www.apache.org/o
>> de/pmapi/types/2006/08/02/">1202</tns1:in2>
>>
>> </axis2ns4:setAttribute></soapenv:Body></soapenv:Envelope>
>> 09:46:35,577 DEBUG [ExternalService] Message: <?xml version='1.0'
>> encoding='utf-8'?><soapenv:Envelope xmlns:soapenv="htt
>>
>> p://schemas.xmlsoap.org/soap/envelope/"><soapenv:Body><axis2ns4:setAttribute
>> xmlns:axis2ns4="http://engineering.cbp.jpo"
>> xmlns:tns1="http://engineering.cbp.jpo">
>> <tns1:in2
>> xmlns:ns="http://www.apache.org/ode/pmapi/types/2006/08/02/"
>> xmlns="http://www.apache.org/o
>> de/pmapi/types/2006/08/02/">1202</tns1:in2>
>>
>> </axis2ns4:setAttribute></soapenv:Body></soapenv:Envelope>
>> DEBUG - GeronimoLog.debug(66) | replyAsync mex=hqejbhcnphr2kvk6gstpxw
>> 09:46:35,577 DEBUG [PartnerRoleMessageExchangeImpl] replyAsync
>> mex=hqejbhcnphr2kvk6gstpxw
>> DEBUG - GeronimoLog.debug(66) | Setting execution state on instance 1202
>> 09:46:35,577 DEBUG [BpelRuntimeContextImpl] Setting execution state on
>> instance 1202
>> DEBUG - GeronimoLog.debug(66) | Thread[pool-2-thread-2,5,main]:
>> unlock(iid=1202)
>> 09:46:36,230 DEBUG [InstanceLockManager] Thread[pool-2-thread-2,5,main]:
>> unlock(iid=1202)
>> DEBUG - GeronimoLog.debug(66) | Sending stateful TO epr in message header
>> using session null
>> 09:46:36,251 DEBUG [SessionOutHandler] Sending stateful TO epr in message
>> header using session null
>> DEBUG - GeronimoLog.debug(66) | Sending a message containing wsa
>> endpoints
>> in headers for session passing.
>> 09:46:36,251 DEBUG [SessionOutHandler] Sending a message containing wsa
>> endpoints in headers for session passing.
>> DEBUG - GeronimoLog.debug(66) | <?xml version='1.0'
>> encoding='utf-8'?><soapenv:Envelope xmlns:soapenv="http://schemas.xm
>> lsoap.org/soap/envelope/"><soapenv:Header><addr:To
>> xmlns:addr="http://www.w3.org/2005/08/addressing">http://localhost:80
>> 80/ematrix/services/JpoCbpEngineeringCBPWorkflow</addr:To><addr:Action
>> xmlns:addr="http://www.w3.org/2005/08/addressing"
>> ></addr:Action><addr:ReplyTo
>> xmlns:addr="http://www.w3.org/2005/08/addressing"><addr:Address>
>> http://www.w3.org/2005/08/a
>> ddressing/anonymous</addr:Address></addr:ReplyTo><addr:MessageID
>> xmlns:addr="http://www.w3.org/2005/08/addressing">uuid:
>>
>> hqejbhcnphr2kvk6gstpxx</addr:MessageID></soapenv:Header><soapenv:Body><axis2ns4:setAttribute
>> xmlns:axis2ns4="http://engi
>> neering.cbp.jpo" xmlns:tns1="http://engineering.cbp.jpo">
>> <tns1:in2
>> xmlns:ns="http://www.apache.org/ode/pmapi/types/2006/08/02/"
>> xmlns="http://www.apache.org/o
>> de/pmapi/types/2006/08/02/">1202</tns1:in2>
>>
>> </axis2ns4:setAttribute></soapenv:Body></soapenv:Envelope>
>> 09:46:36,271 DEBUG [SessionOutHandler] <?xml version='1.0'
>> encoding='utf-8'?><soapenv:Envelope xmlns:soapenv="http://sch
>> emas.xmlsoap.org/soap/envelope/"><soapenv:Header><addr:To
>> xmlns:addr="http://www.w3.org/2005/08/addressing">http://local
>>
>> host:8080/ematrix/services/JpoCbpEngineeringCBPWorkflow</addr:To><addr:Action
>> xmlns:addr="http://www.w3.org/2005/08/addr
>> essing"></addr:Action><addr:ReplyTo
>> xmlns:addr="http://www.w3.org/2005/08/addressing"><addr:Address>
>> http://www.w3.org/20
>> 05/08/addressing/anonymous</addr:Address></addr:ReplyTo><addr:MessageID
>> xmlns:addr="http://www.w3.org/2005/08/addressing
>>
>> ">uuid:hqejbhcnphr2kvk6gstpxx</addr:MessageID></soapenv:Header><soapenv:Body><axis2ns4:setAttribute
>> xmlns:axis2ns4="http
>> ://engineering.cbp.jpo" xmlns:tns1="http://engineering.cbp.jpo">
>> <tns1:in2
>> xmlns:ns="http://www.apache.org/ode/pmapi/types/2006/08/02/"
>> xmlns="http://www.apache.org/o
>> de/pmapi/types/2006/08/02/">1202</tns1:in2>
>>
>> </axis2ns4:setAttribute></soapenv:Body></soapenv:Envelope>
>> DEBUG - GeronimoLog.debug(66) | Set parameter http.connection.timeout =
>> 60000
>> 09:46:36,271 DEBUG [DefaultHttpParams] Set parameter
>> http.connection.timeout
>> = 60000
>> DEBUG - GeronimoLog.debug(66) | Set parameter http.socket.timeout = 60000
>> 09:46:36,271 DEBUG [DefaultHttpParams] Set parameter http.socket.timeout
>> =
>> 60000
>> DEBUG - GeronimoLog.debug(66) | Set parameter http.socket.timeout = 60000
>> 09:46:36,271 DEBUG [DefaultHttpParams] Set parameter http.socket.timeout
>> =
>> 60000
>> DEBUG - GeronimoLog.trace(54) | enter PostMethod.clearRequestBody()
>> 09:46:36,271 DEBUG [PostMethod] enter PostMethod.clearRequestBody()
>> DEBUG - GeronimoLog.trace(54) | enter
>> EntityEnclosingMethod.clearRequestBody()
>> 09:46:36,271 DEBUG [EntityEnclosingMethod] enter
>> EntityEnclosingMethod.clearRequestBody()
>> DEBUG - GeronimoLog.trace(54) | enter
>> HttpClient.executeMethod(HostConfiguration,HttpMethod)
>> 09:46:36,281 DEBUG [HttpClient] enter
>> HttpClient.executeMethod(HostConfiguration,HttpMethod)
>> DEBUG - GeronimoLog.trace(54) | enter
>> HttpClient.executeMethod(HostConfiguration,HttpMethod,HttpState)
>> 09:46:36,281 DEBUG [HttpClient] enter
>> HttpClient.executeMethod(HostConfiguration,HttpMethod,HttpState)
>> DEBUG - GeronimoLog.trace(54) | enter
>> HttpConnectionManager.getConnectionWithTimeout(HostConfiguration, long)
>> 09:46:36,281 DEBUG [MultiThreadedHttpConnectionManager] enter
>> HttpConnectionManager.getConnectionWithTimeout(HostConfigu
>> ration, long)
>> DEBUG - GeronimoLog.debug(66) | HttpConnectionManager.getConnection
>> : config
>> = HostConfiguration[host=http://localhost:8
>> 080], timeout = 0
>> 09:46:36,281 DEBUG [MultiThreadedHttpConnectionManager]
>> HttpConnectionManager.getConnection: config = HostConfiguration
>> [host=http://localhost:8080], timeout = 0
>> DEBUG - GeronimoLog.trace(54) | enter
>> HttpConnectionManager.ConnectionPool.getHostPool(HostConfiguration)
>> 09:46:36,281 DEBUG [MultiThreadedHttpConnectionManager] enter
>> HttpConnectionManager.ConnectionPool.getHostPool(HostConfi
>> guration)
>> DEBUG - GeronimoLog.trace(54) | enter
>> HttpConnectionManager.ConnectionPool.getHostPool(HostConfiguration)
>> 09:46:36,281 DEBUG [MultiThreadedHttpConnectionManager] enter
>> HttpConnectionManager.ConnectionPool.getHostPool(HostConfi
>> guration)
>> DEBUG - GeronimoLog.debug(66) | Allocating new connection,
>> hostConfig=HostConfiguration[host=http://localhost:8080]
>> 09:46:36,281 DEBUG [MultiThreadedHttpConnectionManager] Allocating new
>> connection, hostConfig=HostConfiguration[host=htt
>> p://localhost:8080]
>> DEBUG - GeronimoLog.trace(54) | Attempt number 1 to process request
>> 09:46:36,281 DEBUG [HttpMethodDirector] Attempt number 1 to process
>> request
>> DEBUG - GeronimoLog.trace(54) | enter HttpConnection.open()
>> 09:46:36,281 DEBUG [HttpConnection] enter HttpConnection.open()
>> DEBUG - GeronimoLog.debug(66) | Open connection to localhost:8080
>> 09:46:36,281 DEBUG [HttpConnection] Open connection to localhost:8080
>> DEBUG - GeronimoLog.trace(54) | enter HttpMethodBase.execute(HttpState,
>> HttpConnection)
>> 09:46:36,281 DEBUG [HttpMethodBase] enter HttpMethodBase.execute
>> (HttpState,
>> HttpConnection)
>> DEBUG - GeronimoLog.trace(54) | enter HttpMethodBase.writeRequest
>> (HttpState,
>> HttpConnection)
>> 09:46:36,281 DEBUG [HttpMethodBase] enter
>> HttpMethodBase.writeRequest(HttpState, HttpConnection)
>> DEBUG - GeronimoLog.trace(54) | enter
>> HttpMethodBase.writeRequestLine(HttpState, HttpConnection)
>> 09:46:36,291 DEBUG [HttpMethodBase] enter
>> HttpMethodBase.writeRequestLine(HttpState, HttpConnection)
>> DEBUG - GeronimoLog.trace(54) | enter
>> HttpMethodBase.generateRequestLine(HttpConnection, String, String,
>> String,
>> String)
>>
>> 09:46:36,291 DEBUG [HttpMethodBase] enter
>> HttpMethodBase.generateRequestLine(HttpConnection, String, String,
>> String,
>> Str
>> ing)
>> DEBUG - GeronimoLog.debug(66) | >> "POST
>> /ematrix/services/JpoCbpEngineeringCBPWorkflow HTTP/1.1[\r][\n]"
>> 09:46:36,291 DEBUG [header] >> "POST
>> /ematrix/services/JpoCbpEngineeringCBPWorkflow HTTP/1.1[\r][\n]"
>> DEBUG - GeronimoLog.trace(54) | enter HttpConnection.print(String)
>> 09:46:36,291 DEBUG [HttpConnection] enter HttpConnection.print(String)
>> DEBUG - GeronimoLog.trace(54) | enter HttpConnection.write(byte[])
>> 09:46:36,291 DEBUG [HttpConnection] enter HttpConnection.write(byte[])
>> DEBUG - GeronimoLog.trace(54) | enter HttpConnection.write(byte[], int,
>> int)
>> 09:46:36,291 DEBUG [HttpConnection] enter HttpConnection.write(byte[],
>> int,
>> int)
>> DEBUG - GeronimoLog.trace(54) | enter
>> HttpMethodBase.writeRequestHeaders(HttpState,HttpConnection)
>> 09:46:36,291 DEBUG [HttpMethodBase] enter
>> HttpMethodBase.writeRequestHeaders(HttpState,HttpConnection)
>> DEBUG - GeronimoLog.trace(54) | enter
>> EntityEnclosingMethod.addRequestHeaders(HttpState, HttpConnection)
>> 09:46:36,291 DEBUG [EntityEnclosingMethod] enter
>> EntityEnclosingMethod.addRequestHeaders(HttpState, HttpConnection)
>> DEBUG - GeronimoLog.trace(54) | enter
>> ExpectContinueMethod.addRequestHeaders(HttpState, HttpConnection)
>> 09:46:36,291 DEBUG [ExpectContinueMethod] enter
>> ExpectContinueMethod.addRequestHeaders(HttpState, HttpConnection)
>> DEBUG - GeronimoLog.trace(54) | enter
>> HttpMethodBase.addRequestHeaders(HttpState, HttpConnection)
>> 09:46:36,291 DEBUG [HttpMethodBase] enter
>> HttpMethodBase.addRequestHeaders(HttpState, HttpConnection)
>> DEBUG - GeronimoLog.trace(54) | enter
>> HttpMethodBase.addUserAgentRequestHeaders(HttpState, HttpConnection)
>> 09:46:36,312 DEBUG [HttpMethodBase] enter
>> HttpMethodBase.addUserAgentRequestHeaders(HttpState, HttpConnection)
>> DEBUG - GeronimoLog.trace(54) | enter
>> HttpMethodBase.addHostRequestHeader(HttpState, HttpConnection)
>> 09:46:36,312 DEBUG [HttpMethodBase] enter
>> HttpMethodBase.addHostRequestHeader(HttpState, HttpConnection)
>> DEBUG - GeronimoLog.debug(66) | Adding Host request header
>> 09:46:36,312 DEBUG [HttpMethodBase] Adding Host request header
>> DEBUG - GeronimoLog.trace(54) | enter
>> HttpMethodBase.addCookieRequestHeader(HttpState, HttpConnection)
>> 09:46:36,312 DEBUG [HttpMethodBase] enter
>> HttpMethodBase.addCookieRequestHeader(HttpState, HttpConnection)
>> DEBUG - GeronimoLog.trace(54) | enter HttpState.getCookies()
>> 09:46:36,312 DEBUG [HttpState] enter HttpState.getCookies()
>> DEBUG - GeronimoLog.trace(54) | enter CookieSpecBase.match(String, int,
>> String, boolean, Cookie[])
>> 09:46:36,312 DEBUG [CookieSpec] enter CookieSpecBase.match(String, int,
>> String, boolean, Cookie[])
>> DEBUG - GeronimoLog.trace(54) | enter
>> HttpMethodBase.addProxyConnectionHeader(HttpState, HttpConnection)
>> 09:46:36,322 DEBUG [HttpMethodBase] enter
>> HttpMethodBase.addProxyConnectionHeader(HttpState, HttpConnection)
>> DEBUG - GeronimoLog.trace(54) | enter
>> EntityEnclosingMethod.addContentLengthRequestHeader(HttpState,
>> HttpConnection)
>> 09:46:36,322 DEBUG [EntityEnclosingMethod] enter
>> EntityEnclosingMethod.addContentLengthRequestHeader(HttpState, HttpConn
>> ection)
>> DEBUG - GeronimoLog.trace(54) | enter
>> EntityEnclosingMethod.getRequestContentLength()
>> 09:46:36,322 DEBUG [EntityEnclosingMethod] enter
>> EntityEnclosingMethod.getRequestContentLength()
>> DEBUG - GeronimoLog.trace(54) | enter PostMethod.hasRequestContent()
>> 09:46:36,322 DEBUG [PostMethod] enter PostMethod.hasRequestContent()
>> DEBUG - GeronimoLog.trace(54) | enter
>> EntityEnclosingMethod.hasRequestContent()
>> 09:46:36,322 DEBUG [EntityEnclosingMethod] enter
>> EntityEnclosingMethod.hasRequestContent()
>> DEBUG - GeronimoLog.trace(54) | HttpMethodBase.addRequestHeader(Header)
>> 09:46:36,322 DEBUG [HttpMethodBase] HttpMethodBase.addRequestHeader
>> (Header)
>> DEBUG - GeronimoLog.debug(66) | >> "Content-Type: text/xml;
>> charset=UTF-8[\r][\n]"
>> 09:46:36,322 DEBUG [header] >> "Content-Type: text/xml;
>> charset=UTF-8[\r][\n]"
>> DEBUG - GeronimoLog.trace(54) | enter HttpConnection.print(String)
>> 09:46:36,322 DEBUG [HttpConnection] enter HttpConnection.print(String)
>> DEBUG - GeronimoLog.trace(54) | enter HttpConnection.write(byte[])
>> 09:46:36,322 DEBUG [HttpConnection] enter HttpConnection.write(byte[])
>> DEBUG - GeronimoLog.trace(54) | enter HttpConnection.write(byte[], int,
>> int)
>> 09:46:36,322 DEBUG [HttpConnection] enter HttpConnection.write(byte[],
>> int,
>> int)
>> DEBUG - GeronimoLog.debug(66) | >> "SOAPAction:
>> "urn:anonOutInOp"[\r][\n]"
>> 09:46:36,322 DEBUG [header] >> "SOAPAction: "urn:anonOutInOp"[\r][\n]"
>> DEBUG - GeronimoLog.trace(54) | enter HttpConnection.print(String)
>> 09:46:36,322 DEBUG [HttpConnection] enter HttpConnection.print(String)
>> DEBUG - GeronimoLog.trace(54) | enter HttpConnection.write(byte[])
>> 09:46:36,322 DEBUG [HttpConnection] enter HttpConnection.write(byte[])
>> DEBUG - GeronimoLog.trace(54) | enter HttpConnection.write(byte[], int,
>> int)
>> 09:46:36,322 DEBUG [HttpConnection] enter HttpConnection.write(byte[],
>> int,
>> int)
>> DEBUG - GeronimoLog.debug(66) | >> "User-Agent: Axis2[\r][\n]"
>> 09:46:36,322 DEBUG [header] >> "User-Agent: Axis2[\r][\n]"
>> DEBUG - GeronimoLog.trace(54) | enter HttpConnection.print(String)
>> 09:46:36,322 DEBUG [HttpConnection] enter HttpConnection.print(String)
>> DEBUG - GeronimoLog.trace(54) | enter HttpConnection.write(byte[])
>> 09:46:36,332 DEBUG [HttpConnection] enter HttpConnection.write(byte[])
>> DEBUG - GeronimoLog.trace(54) | enter HttpConnection.write(byte[], int,
>> int)
>> 09:46:36,332 DEBUG [HttpConnection] enter HttpConnection.write(byte[],
>> int,
>> int)
>> DEBUG - GeronimoLog.debug(66) | >> "Host: localhost:8080[\r][\n]"
>> 09:46:36,332 DEBUG [header] >> "Host: localhost:8080[\r][\n]"
>> DEBUG - GeronimoLog.trace(54) | enter HttpConnection.print(String)
>> 09:46:36,332 DEBUG [HttpConnection] enter HttpConnection.print(String)
>> DEBUG - GeronimoLog.trace(54) | enter HttpConnection.write(byte[])
>> 09:46:36,332 DEBUG [HttpConnection] enter HttpConnection.write(byte[])
>> DEBUG - GeronimoLog.trace(54) | enter HttpConnection.write(byte[], int,
>> int)
>> 09:46:36,332 DEBUG [HttpConnection] enter HttpConnection.write(byte[],
>> int,
>> int)
>> DEBUG - GeronimoLog.debug(66) | >> "Transfer-Encoding: chunked[\r][\n]"
>> 09:46:36,343 DEBUG [header] >> "Transfer-Encoding: chunked[\r][\n]"
>> DEBUG - GeronimoLog.trace(54) | enter HttpConnection.print(String)
>> 09:46:36,343 DEBUG [HttpConnection] enter HttpConnection.print(String)
>> DEBUG - GeronimoLog.trace(54) | enter HttpConnection.write(byte[])
>> 09:46:36,343 DEBUG [HttpConnection] enter HttpConnection.write(byte[])
>> DEBUG - GeronimoLog.trace(54) | enter HttpConnection.write(byte[], int,
>> int)
>> 09:46:36,343 DEBUG [HttpConnection] enter HttpConnection.write(byte[],
>> int,
>> int)
>> DEBUG - GeronimoLog.trace(54) | enter HttpConnection.writeLine()
>> 09:46:36,343 DEBUG [HttpConnection] enter HttpConnection.writeLine()
>> DEBUG - GeronimoLog.trace(54) | enter HttpConnection.write(byte[])
>> 09:46:36,343 DEBUG [HttpConnection] enter HttpConnection.write(byte[])
>> DEBUG - GeronimoLog.trace(54) | enter HttpConnection.write(byte[], int,
>> int)
>> 09:46:36,343 DEBUG [HttpConnection] enter HttpConnection.write(byte[],
>> int,
>> int)
>> DEBUG - GeronimoLog.debug(66) | >> "[\r][\n]"
>> 09:46:36,343 DEBUG [header] >> "[\r][\n]"
>> DEBUG - GeronimoLog.trace(54) | enter
>> EntityEnclosingMethod.writeRequestBody(HttpState, HttpConnection)
>> 09:46:36,343 DEBUG [EntityEnclosingMethod] enter
>> EntityEnclosingMethod.writeRequestBody(HttpState, HttpConnection)
>> DEBUG - GeronimoLog.trace(54) | enter PostMethod.hasRequestContent()
>> 09:46:36,343 DEBUG [PostMethod] enter PostMethod.hasRequestContent()
>> DEBUG - GeronimoLog.trace(54) | enter
>> EntityEnclosingMethod.hasRequestContent()
>> 09:46:36,343 DEBUG [EntityEnclosingMethod] enter
>> EntityEnclosingMethod.hasRequestContent()
>> DEBUG - GeronimoLog.trace(54) | enter
>> EntityEnclosingMethod.getRequestContentLength()
>> 09:46:36,343 DEBUG [EntityEnclosingMethod] enter
>> EntityEnclosingMethod.getRequestContentLength()
>> DEBUG - GeronimoLog.trace(54) | enter PostMethod.hasRequestContent()
>> 09:46:36,343 DEBUG [PostMethod] enter PostMethod.hasRequestContent()
>> DEBUG - GeronimoLog.trace(54) | enter
>> EntityEnclosingMethod.hasRequestContent()
>> 09:46:36,343 DEBUG [EntityEnclosingMethod] enter
>> EntityEnclosingMethod.hasRequestContent()
>> DEBUG - GeronimoLog.trace(54) | enter
>> HttpConnection.getRequestOutputStream()
>> 09:46:36,343 DEBUG [HttpConnection] enter
>> HttpConnection.getRequestOutputStream()
>> DEBUG - GeronimoLog.debug(66) | Request body sent
>> 09:46:36,353 DEBUG [EntityEnclosingMethod] Request body sent
>> DEBUG - GeronimoLog.trace(54) | enter
>> HttpConnection.flushRequestOutputStream()
>> 09:46:36,363 DEBUG [HttpConnection] enter
>> HttpConnection.flushRequestOutputStream()
>> DEBUG - GeronimoLog.trace(54) | enter HttpMethodBase.readResponse
>> (HttpState,
>> HttpConnection)
>> 09:46:36,394 DEBUG [HttpMethodBase] enter
>> HttpMethodBase.readResponse(HttpState, HttpConnection)
>> DEBUG - GeronimoLog.trace(54) | enter
>> HttpMethodBase.readStatusLine(HttpState, HttpConnection)
>> 09:46:36,394 DEBUG [HttpMethodBase] enter
>> HttpMethodBase.readStatusLine(HttpState, HttpConnection)
>> DEBUG - GeronimoLog.trace(54) | enter HttpConnection.readLine()
>> 09:46:36,394 DEBUG [HttpConnection] enter HttpConnection.readLine()
>> DEBUG - GeronimoLog.trace(54) | enter HttpParser.readLine(InputStream,
>> String)
>> 09:46:36,496 DEBUG [HttpParser] enter HttpParser.readLine(InputStream,
>> String)
>> DEBUG - GeronimoLog.trace(54) | enter HttpParser.readRawLine()
>> 09:46:36,506 DEBUG [HttpParser] enter HttpParser.readRawLine()
>> DEBUG - GeronimoLog.debug(66) | << "HTTP/1.1 500 Internal Server
>> Error[\r][\n]"
>> 09:46:37,507 DEBUG [header] << "HTTP/1.1 500 Internal Server
>> Error[\r][\n]"
>> DEBUG - GeronimoLog.trace(54) | enter
>> HttpMethodBase.readResponseHeaders(HttpState,HttpConnection)
>> 09:46:37,517 DEBUG [HttpMethodBase] enter
>> HttpMethodBase.readResponseHeaders(HttpState,HttpConnection)
>> DEBUG - GeronimoLog.trace(54) | enter
>> HttpConnection.getResponseInputStream()
>> 09:46:37,527 DEBUG [HttpConnection] enter
>> HttpConnection.getResponseInputStream()
>> DEBUG - GeronimoLog.trace(54) | enter HeaderParser.parseHeaders
>> (InputStream,
>> String)
>> 09:46:37,527 DEBUG [HttpParser] enter HeaderParser.parseHeaders
>> (InputStream,
>> String)
>> DEBUG - GeronimoLog.trace(54) | enter HttpParser.readLine(InputStream,
>> String)
>> 09:46:37,537 DEBUG [HttpParser] enter HttpParser.readLine(InputStream,
>> String)
>> DEBUG - GeronimoLog.trace(54) | enter HttpParser.readRawLine()
>> 09:46:37,537 DEBUG [HttpParser] enter HttpParser.readRawLine()
>> DEBUG - GeronimoLog.trace(54) | enter HttpParser.readLine(InputStream,
>> String)
>> 09:46:37,537 DEBUG [HttpParser] enter HttpParser.readLine(InputStream,
>> String)
>> DEBUG - GeronimoLog.trace(54) | enter HttpParser.readRawLine()
>> 09:46:37,537 DEBUG [HttpParser] enter HttpParser.readRawLine()
>> DEBUG - GeronimoLog.trace(54) | enter HttpParser.readLine(InputStream,
>> String)
>> 09:46:37,537 DEBUG [HttpParser] enter HttpParser.readLine(InputStream,
>> String)
>> DEBUG - GeronimoLog.trace(54) | enter HttpParser.readRawLine()
>> 09:46:37,537 DEBUG [HttpParser] enter HttpParser.readRawLine()
>> DEBUG - GeronimoLog.trace(54) | enter HttpParser.readLine(InputStream,
>> String)
>> 09:46:37,537 DEBUG [HttpParser] enter HttpParser.readLine(InputStream,
>> String)
>> DEBUG - GeronimoLog.trace(54) | enter HttpParser.readRawLine()
>> 09:46:37,548 DEBUG [HttpParser] enter HttpParser.readRawLine()
>> DEBUG - GeronimoLog.trace(54) | enter HttpParser.readLine(InputStream,
>> String)
>> 09:46:37,548 DEBUG [HttpParser] enter HttpParser.readLine(InputStream,
>> String)
>> DEBUG - GeronimoLog.trace(54) | enter HttpParser.readRawLine()
>> 09:46:37,548 DEBUG [HttpParser] enter HttpParser.readRawLine()
>> DEBUG - GeronimoLog.trace(54) | enter HttpParser.readLine(InputStream,
>> String)
>> 09:46:37,548 DEBUG [HttpParser] enter HttpParser.readLine(InputStream,
>> String)
>> DEBUG - GeronimoLog.trace(54) | enter HttpParser.readRawLine()
>> 09:46:37,548 DEBUG [HttpParser] enter HttpParser.readRawLine()
>> DEBUG - GeronimoLog.debug(66) | << "Server: Apache-Coyote/1.1[\r][\n]"
>> 09:46:37,548 DEBUG [header] << "Server: Apache-Coyote/1.1[\r][\n]"
>> DEBUG - GeronimoLog.debug(66) | << "Content-Type:
>> text/xml;charset=utf-8[\r][\n]"
>> 09:46:37,548 DEBUG [header] << "Content-Type:
>> text/xml;charset=utf-8[\r][\n]"
>> DEBUG - GeronimoLog.debug(66) | << "Transfer-Encoding: chunked[\r][\n]"
>> 09:46:37,548 DEBUG [header] << "Transfer-Encoding: chunked[\r][\n]"
>> DEBUG - GeronimoLog.debug(66) | << "Date: Tue, 11 Sep 2007 13:46:37
>> GMT[\r][\n]"
>> 09:46:37,558 DEBUG [header] << "Date: Tue, 11 Sep 2007 13:46:37
>> GMT[\r][\n]"
>> DEBUG - GeronimoLog.debug(66) | << "Connection: close[\r][\n]"
>> 09:46:37,558 DEBUG [header] << "Connection: close[\r][\n]"
>> DEBUG - GeronimoLog.trace(54) | enter
>> HttpMethodBase.processResponseHeaders(HttpState, HttpConnection)
>> 09:46:37,558 DEBUG [HttpMethodBase] enter
>> HttpMethodBase.processResponseHeaders(HttpState, HttpConnection)
>> DEBUG - GeronimoLog.trace(54) | enter
>> HttpMethodBase.readResponseBody(HttpState, HttpConnection)
>> 09:46:37,558 DEBUG [HttpMethodBase] enter
>> HttpMethodBase.readResponseBody(HttpState, HttpConnection)
>> DEBUG - GeronimoLog.trace(54) | enter
>> HttpMethodBase.readResponseBody(HttpConnection)
>> 09:46:37,578 DEBUG [HttpMethodBase] enter
>> HttpMethodBase.readResponseBody(HttpConnection)
>> DEBUG - GeronimoLog.trace(54) | enter
>> HttpConnection.getResponseInputStream()
>> 09:46:37,578 DEBUG [HttpConnection] enter
>> HttpConnection.getResponseInputStream()
>> DEBUG - GeronimoLog.trace(54) | enter
>> HttpMethodBase.canResponseHaveBody(int)
>> 09:46:37,578 DEBUG [HttpMethodBase] enter
>> HttpMethodBase.canResponseHaveBody(int)
>> DEBUG - GeronimoLog.trace(54) | enter HeaderElement.parseElements(String)
>> 09:46:37,578 DEBUG [HeaderElement] enter HeaderElement.parseElements
>> (String)
>> DEBUG - GeronimoLog.trace(54) | enter HeaderElement.parseElements(char[])
>> 09:46:37,578 DEBUG [HeaderElement] enter HeaderElement.parseElements
>> (char[])
>> DEBUG - GeronimoLog.trace(54) | enter
>> HttpConnection.isResponseAvailable(int)
>> 09:46:37,691 DEBUG [HttpConnection] enter
>> HttpConnection.isResponseAvailable(int)
>> DEBUG - GeronimoLog.trace(54) | enter HeaderElement.parseElements(String)
>> 09:46:37,701 DEBUG [HeaderElement] enter HeaderElement.parseElements
>> (String)
>> DEBUG - GeronimoLog.trace(54) | enter HeaderElement.parseElements(char[])
>> 09:46:37,701 DEBUG [HeaderElement] enter HeaderElement.parseElements
>> (char[])
>> DEBUG - GeronimoLog.trace(54) | enter
>> HeaderElement.getParameterByName(String)
>> 09:46:37,701 DEBUG [HeaderElement] enter
>> HeaderElement.getParameterByName(String)
>> ERROR - GeronimoLog.error(108) | Error sending message
>> (mex={PartnerRoleMex#hqejbhcnphr2kvk6gstpxw [PID {http://eclipse.
>> org/bpel/sample}ECRProcess-9] calling
>> org.apache.ode.bpel.epr.WSAEndpoint@11dca40.setAttribute(...)}):
>> java.lang.NullPoi
>> nterException
>> org.apache.axis2.AxisFault: java.lang.NullPointerException
>> at
>> org.apache.axis2.util.Utils.getInboundFaultFromMessageContext(Utils.java
>> :486)
>> at
>> org.apache.axis2.description.OutInAxisOperationClient.handleResponse(
>> OutInAxisOperation.java:343)
>> at
>> org.apache.axis2.description.OutInAxisOperationClient.send(
>> OutInAxisOperation.java:389)
>> at
>> org.apache.axis2.description.OutInAxisOperationClient.executeImpl(
>> OutInAxisOperation.java:211)
>> at
>> org.apache.axis2.client.OperationClient.execute(OperationClient.java:163)
>> at
>> org.apache.ode.axis2.ExternalService$1$1.call(ExternalService.java:150)
>> at
>> java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:269)
>> at java.util.concurrent.FutureTask.run(FutureTask.java:123)
>> at
>> java.util.concurrent.ThreadPoolExecutor$Worker.runTask(
>> ThreadPoolExecutor.java:650)
>> at
>> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java
>> :675)
>> at java.lang.Thread.run(Thread.java:595)
>> 09:46:37,772 ERROR [ExternalService] Error sending message
>> (mex={PartnerRoleMex#hqejbhcnphr2kvk6gstpxw [PID {http://ecli
>> pse.org/bpel/sample}ECRProcess-9] calling
>> org.apache.ode.bpel.epr.WSAEndpoint@11dca40.setAttribute(...)}):
>> java.lang.Nul
>> lPointerException
>> org.apache.axis2.AxisFault: java.lang.NullPointerException
>> at
>> org.apache.axis2.util.Utils.getInboundFaultFromMessageContext(Utils.java
>> :486)
>> at
>> org.apache.axis2.description.OutInAxisOperationClient.handleResponse(
>> OutInAxisOperation.java:343)
>> at
>> org.apache.axis2.description.OutInAxisOperationClient.send(
>> OutInAxisOperation.java:389)
>> at
>> org.apache.axis2.description.OutInAxisOperationClient.executeImpl(
>> OutInAxisOperation.java:211)
>> at
>> org.apache.axis2.client.OperationClient.execute(OperationClient.java:163)
>> at
>> org.apache.ode.axis2.ExternalService$1$1.call(ExternalService.java:150)
>> at
>> java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:269)
>> at java.util.concurrent.FutureTask.run(FutureTask.java:123)
>> at
>> java.util.concurrent.ThreadPoolExecutor$Worker.runTask(
>> ThreadPoolExecutor.java:650)
>> at
>> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java
>> :675)
>> at java.lang.Thread.run(Thread.java:595)
>> DEBUG - GeronimoLog.trace(54) |
>> Mex[hqejbhcnphr2kvk6gstpxw].setPortOp(...)
>> 09:46:37,803 DEBUG [MessageExchangeImpl]
>> Mex[hqejbhcnphr2kvk6gstpxw].setPortOp(...)
>> DEBUG - GeronimoLog.debug(66) | replyWithFailure
>> mex=hqejbhcnphr2kvk6gstpxw
>> failureType=COMMUNICATION_ERROR description=
>> Error sending message (mex={PartnerRoleMex#hqejbhcnphr2kvk6gstpxw [PID
>> {http://eclipse.org/bpel/sample}ECRProcess-9] cal
>> ling org.apache.ode.bpel.epr.WSAEndpoint@11dca40.setAttribute(...)}):
>> java.lang.NullPointerException details=null
>> 09:46:37,803 DEBUG [PartnerRoleMessageExchangeImpl] replyWithFailure
>> mex=hqejbhcnphr2kvk6gstpxw failureType=COMMUNICATIO
>> N_ERROR description=Error sending message
>> (mex={PartnerRoleMex#hqejbhcnphr2kvk6gstpxw [PID
>> {http://eclipse.org/bpel/samp
>> le}ECRProcess-9] calling
>> org.apache.ode.bpel.epr.WSAEndpoint@11dca40.setAttribute(...)}):
>> java.lang.NullPointerException
>> details=null
>> DEBUG - GeronimoLog.debug(66) | create work event for
>> mex=hqejbhcnphr2kvk6gstpxw
>> 09:46:37,803 DEBUG [PartnerRoleMessageExchangeImpl] create work event for
>> mex=hqejbhcnphr2kvk6gstpxw
>> DEBUG - GeronimoLog.debug(66) | Thread[pool-2-thread-2,5,main]:
>> lock(iid=1202, time=1MICROSECONDS)
>> 09:46:37,864 DEBUG [InstanceLockManager] Thread[pool-2-thread-2,5,main]:
>> lock(iid=1202, time=1MICROSECONDS)
>> DEBUG - GeronimoLog.debug(66) | Thread[pool-2-thread-2,5,main]:
>> lock(iid=1202, time=1MICROSECONDS)-->GRANTED
>> 09:46:37,864 DEBUG [InstanceLockManager] Thread[pool-2-thread-2,5,main]:
>> lock(iid=1202, time=1MICROSECONDS)-->GRANTED
>> DEBUG - GeronimoLog.debug(66) | >>
>> handleWorkEvent(jobData={type=INVOKE_RESPONSE,
>> mexid=hqejbhcnphr2kvk6gstpxw,
>> channel=
>> 54, iid=1202})
>> 09:46:37,874 DEBUG [BpelProcess] >>
>> handleWorkEvent(jobData={type=INVOKE_RESPONSE,
>> mexid=hqejbhcnphr2kvk6gstpxw,
>> channel
>> =54, iid=1202})
>> DEBUG - GeronimoLog.debug(66) | BpelRuntimeContextImpl created for
>> instance
>> 1202. INDEXED STATE={OSequence#45-main::1=[A
>> CTIVITYGUARD(...)], OInvoke#145-UpdateCBPWorkflow::32=[INVOKE(...)],
>> OSequence#47-HiddenSequence::6=[SEQUENCE(self=(OSeq
>> uence#47-HiddenSequence,TerminationChannel#9,ParentScopeChannel#11),
>> linkframe=org.apache.ode.bpel.runtime.LinkFrame@6c7
>> d22, remaining=[{OScope 'UpdateCBPWorkflow' id=144}, {OScope
>> 'callbackClient' id=151}])], OSequence#47-HiddenSequence::5
>> =[ACTIVITYGUARD(...)], {OScope 'Design Change Proposal'
>> id=46}::4=[SCOPE(...)], {OScope '__PROCESS_SCOPE:ECRProcess' id=
>> 3}::0=[ACTIVE(...)], {OScope 'UpdateCBPWorkflow'
>> id=144}::30=[SCOPE(...)],
>> {OScope 'UpdateCBPWorkflow' id=144}::30=[ACTI
>> VE(...)], OInvoke#145-UpdateCBPWorkflow::31=[ACTIVITYGUARD(...)], {OScope
>> 'UpdateCBPWorkflow' id=144}::29=[ACTIVITYGUARD
>> (...)], {OScope 'Design Change Proposal' id=46}::3=[ACTIVITYGUARD(...)],
>> {OScope 'Design Change Proposal' id=46}::4=[ACT
>> IVE(...)], {OScope '__PROCESS_SCOPE:ECRProcess' id=3}::0=[SCOPE(...)],
>> OSequence#45-main::2=[SEQUENCE(self=(OSequence#45
>> -main,TerminationChannel#3,ParentScopeChannel#5),
>> linkframe=org.apache.ode.bpel.runtime.LinkFrame@6c7d22, remaining=[{OS
>> cope 'Design Change Proposal' id=46}])]}
>> 09:46:37,895 DEBUG [BpelRuntimeContextImpl] BpelRuntimeContextImpl
>> created
>> for instance 1202. INDEXED STATE={OSequence#4
>> 5-main::1=[ACTIVITYGUARD(...)],
>> OInvoke#145-UpdateCBPWorkflow::32=[INVOKE(...)],
>> OSequence#47-HiddenSequence::6=[SEQUENC
>>
>> E(self=(OSequence#47-HiddenSequence,TerminationChannel#9,ParentScopeChannel#11),
>> linkframe=org.apache.ode.bpel.runtime.L
>> inkFrame@6c7d22, remaining=[{OScope 'UpdateCBPWorkflow' id=144}, {OScope
>> 'callbackClient' id=151}])], OSequence#47-Hidde
>> nSequence::5=[ACTIVITYGUARD(...)], {OScope 'Design Change Proposal'
>> id=46}::4=[SCOPE(...)], {OScope '__PROCESS_SCOPE:ECR
>> Process' id=3}::0=[ACTIVE(...)], {OScope 'UpdateCBPWorkflow'
>> id=144}::30=[SCOPE(...)], {OScope 'UpdateCBPWorkflow' id=14
>> 4}::30=[ACTIVE(...)],
>> OInvoke#145-UpdateCBPWorkflow::31=[ACTIVITYGUARD(...)], {OScope
>> 'UpdateCBPWorkflow' id=144}::29=[A
>> CTIVITYGUARD(...)], {OScope 'Design Change Proposal'
>> id=46}::3=[ACTIVITYGUARD(...)], {OScope 'Design Change Proposal' id
>> =46}::4=[ACTIVE(...)], {OScope '__PROCESS_SCOPE:ECRProcess'
>> id=3}::0=[SCOPE(...)], OSequence#45-main::2=[SEQUENCE(self=(
>> OSequence#45-main,TerminationChannel#3,ParentScopeChannel#5),
>> linkframe=org.apache.ode.bpel.runtime.LinkFrame@6c7d22, re
>> maining=[{OScope 'Design Change Proposal' id=46}])]}
>> DEBUG - GeronimoLog.debug(66) | InvokeResponse event for iid 1202
>> 09:46:37,905 DEBUG [BpelProcess] InvokeResponse event for iid 1202
>> DEBUG - GeronimoLog.debug(66) | Invoking message response for mexid
>> hqejbhcnphr2kvk6gstpxw and channel 54
>> 09:46:37,905 DEBUG [BpelRuntimeContextImpl] Invoking message response for
>> mexid hqejbhcnphr2kvk6gstpxw and channel 54
>> DEBUG - GeronimoLog.debug(66) | Triggering response
>> 09:46:37,905 DEBUG [BpelRuntimeContextImpl] Triggering response
>> INFO - GeronimoLog.info(79) | ActivityRecovery: Registering activity 31,
>> failure reason: Error sending message (mex={Par
>> tnerRoleMex#hqejbhcnphr2kvk6gstpxw [PID
>> {http://eclipse.org/bpel/sample}ECRProcess-9] calling
>> org.apache.ode.bpel.epr.WS
>> AEndpoint@11dca40.setAttribute(...)}): java.lang.NullPointerException on
>> channel 55
>> 09:46:37,915 INFO [BpelRuntimeContextImpl] ActivityRecovery: Registering
>> activity 31, failure reason: Error sending mes
>> sage (mex={PartnerRoleMex#hqejbhcnphr2kvk6gstpxw [PID
>> {http://eclipse.org/bpel/sample}ECRProcess-9] calling org.apache.o
>> de.bpel.epr.WSAEndpoint@11dca40.setAttribute(...)}):
>> java.lang.NullPointerException on channel 55
>> DEBUG - GeronimoLog.debug(66) | Setting execution state on instance 1202
>> 09:46:38,068 DEBUG [BpelRuntimeContextImpl] Setting execution state on
>> instance 1202
>> DEBUG - GeronimoLog.debug(66) | Thread[pool-2-thread-2,5,main]:
>> unlock(iid=1202)
>> 09:46:38,201 DEBUG [InstanceLockManager] Thread[pool-2-thread-2,5,main]:
>> unlock(iid=1202)
>> DEBUG - GeronimoLog.debug(66) | Connection reclaimed by garbage
>> collector,
>> hostConfig=HostConfiguration[host=http://loca
>> lhost:8080]
>> 09:47:31,939 DEBUG [MultiThreadedHttpConnectionManager] Connection
>> reclaimed
>> by garbage collector, hostConfig=HostConfig
>> uration[host=http://localhost:8080]
>> DEBUG - GeronimoLog.trace(54) | enter
>> HttpConnectionManager.ConnectionPool.getHostPool(HostConfiguration)
>> 09:47:40,293 DEBUG [MultiThreadedHttpConnectionManager] enter
>> HttpConnectionManager.ConnectionPool.getHostPool(HostConfi
>> guration)
>> DEBUG - GeronimoLog.trace(54) | enter
>> HttpConnectionManager.ConnectionPool.getHostPool(HostConfiguration)
>> 09:47:40,303 DEBUG [MultiThreadedHttpConnectionManager] enter
>> HttpConnectionManager.ConnectionPool.getHostPool(HostConfi
>> guration)
>> DEBUG - GeronimoLog.debug(66) | Notifying no-one, there are no waiting
>> threads
>> 09:47:40,303 DEBUG [MultiThreadedHttpConnectionManager] Notifying no-one,
>> there are no waiting threads
>> DEBUG - GeronimoLog.debug(66) | Connection reclaimed by garbage
>> collector,
>> hostConfig=HostConfiguration[host=http://loca
>> lhost:8080]
>> 09:47:40,303 DEBUG [MultiThreadedHttpConnectionManager] Connection
>> reclaimed
>> by garbage collector, hostConfig=HostConfig
>> uration[host=http://localhost:8080]
>> DEBUG - GeronimoLog.trace(54) | enter
>> HttpConnectionManager.ConnectionPool.getHostPool(HostConfiguration)
>> 09:47:40,303 DEBUG [MultiThreadedHttpConnectionManager] enter
>> HttpConnectionManager.ConnectionPool.getHostPool(HostConfi
>> guration)
>> DEBUG - GeronimoLog.trace(54) | enter
>> HttpConnectionManager.ConnectionPool.getHostPool(HostConfiguration)
>> 09:47:40,314 DEBUG [MultiThreadedHttpConnectionManager] enter
>> HttpConnectionManager.ConnectionPool.getHostPool(HostConfi
>>
>>
>>
>> Anup
>>
>>
>>
>>
>> Alex Boisvert wrote:
>> >
>> > You're most likely getting some sort of failure from the service you're
>> > invoking, and Axis2 has a hard time parsing the resulting fault
>> message.
>> > I
>> > would recommend setting the "httpclient" log category to DEBUG to see
>> > what's
>> > going on the wire.
>> >
>> > alex
>> >
>> >
>> > On 9/10/07, Anup Chandran <an...@3ds.com> wrote:
>> >>
>> >>
>> >> Alex/Matthieu,
>> >>
>> >> I know this is pretty silly but cant figure what is the issue
>> here......
>> >> I
>> >> have a runtime error with the following trace..... If i remove the
>> >> invoke.
>> >> from BPEL.. the process runs without errors. Can you tell me what is
>> >> going
>> >> on from the trace? Thanks...
>> >>
>> >> DEBUG - GeronimoLog.debug(66) | InvokeResponse event for iid 1057
>> >> 17:40:22,965 DEBUG [BpelProcess] InvokeResponse event for iid 1057
>> >> DEBUG - GeronimoLog.debug(66) | Invoking message response for mexid
>> >> hqejbhcnphr2kte2v4jbl5 and channel 40
>> >> 17:40:22,965 DEBUG [BpelRuntimeContextImpl] Invoking message response
>> for
>> >> mexid hqejbhcnphr2kte2v4jbl5 and channel 40
>> >> DEBUG - GeronimoLog.debug(66) | Triggering response
>> >> 17:40:22,965 DEBUG [BpelRuntimeContextImpl] Triggering response
>> >> DEBUG - GeronimoLog.trace(54) | >>
>> >> createScopeInstance(parentScopeId=1059,scope={OScope
>> 'UpdateCBPWorkflow'
>> >> id=144})
>> >> 17:40:23,255 DEBUG [BpelProcess] >>
>> >> createScopeInstance(parentScopeId=1059,scope={OScope
>> 'UpdateCBPWorkflow'
>> >> id=144})
>> >> DEBUG - GeronimoLog.trace(54) | >>
>> >> initializeEndpointReferences(parentScopeId=1125,partnerLinks=[])
>> >> 17:40:23,506 DEBUG [BpelProcess] >>
>> >> initializeEndpointReferences(parentScopeId=1125,partnerLinks=[])
>> >> DEBUG - GeronimoLog.debug(66) | INVOKING PARTNER:
>> >> partnerLink={PartnerLinkInstance partnerLinkDecl=OPartnerLink#44,scope
>> >> InstanceId=1058}, op=setAttribute channel=InvokeResponseChannel#54)
>> >> 17:40:23,526 DEBUG [BpelProcess] INVOKING PARTNER:
>> >> partnerLink={PartnerLinkInstance partnerLinkDecl=OPartnerLink#44,scop
>> >> eInstanceId=1058}, op=setAttribute channel=InvokeResponseChannel#54)
>> >> DEBUG - GeronimoLog.debug(66) | INVOKE PARTNER (SEP): sessionId=null
>> >> partnerSessionId=null
>> >> 17:40:23,526 DEBUG [BpelRuntimeContextImpl] INVOKE PARTNER (SEP):
>> >> sessionId=null partnerSessionId=null
>> >> DEBUG - GeronimoLog.trace(54) |
>> >> Mex[hqejbhcnphr2kte2v4jbl8].setPortOp(...)
>> >> 17:40:23,526 DEBUG [MessageExchangeImpl]
>> >> Mex[hqejbhcnphr2kte2v4jbl8].setPortOp(...)
>> >> DEBUG - GeronimoLog.debug(66) | Routed: svcQname
>> >> {http://client.engineering.cbp.jpo}CBPWorkflowService --> null
>> >> 17:40:23,526 DEBUG [BpelEngineImpl] Routed: svcQname
>> >> {http://client.engineering.cbp.jpo}CBPWorkflowService --> null
>> >> DEBUG - GeronimoLog.debug(66) | Invoking a partner operation:
>> >> setAttribute
>> >> 17:40:23,526 DEBUG [MessageExchangeContextImpl] Invoking a partner
>> >> operation: setAttribute
>> >> DEBUG - GeronimoLog.debug(66) | The service to invoke is the external
>> >> service org.apache.ode.axis2.ExternalService@1858f
>> >> 02
>> >> 17:40:23,536 DEBUG [MessageExchangeContextImpl] The service to invoke
>> is
>> >> the
>> >> external service org.apache.ode.axis2.Exter
>> >> nalService@1858f02
>> >> DEBUG - GeronimoLog.debug(66) | Resolving endpoint reference <?xml
>> >> version="1.0" encoding="UTF-8"?>
>> >> <service-ref
>> >> xmlns="http://docs.oasis-open.org/wsbpel/2.0/serviceref
>> >> "><EndpointReference
>> >> xmlns="http://www.w3.org/2005/0
>> >> 8/addressing"><Metadata><ServiceName
>> >> xmlns="http://www.w3.org/2006/05/addressing/wsdl"
>> >> EndpointName="JpoCbpEngineeringCB
>> >> PWorkflow"
>> >> xmlns:servicens="http://client.engineering.cbp.jpo
>> >> ">servicens:CBPWorkflowService</ServiceName></Metadata><Add
>> >> ress>
>> http://localhost:8080/ematrix/services/JpoCbpEngineeringCBPWorkflow
>> >> </Address></EndpointReference></service-ref>
>> >> 17:40:23,536 DEBUG [EndpointReferenceContextImpl] Resolving endpoint
>> >> reference <?xml version="1.0" encoding="UTF-8"?>
>> >> <service-ref
>> >> xmlns="http://docs.oasis-open.org/wsbpel/2.0/serviceref
>> >> "><EndpointReference
>> >> xmlns="http://www.w3.org/2005/0
>> >> 8/addressing"><Metadata><ServiceName
>> >> xmlns="http://www.w3.org/2006/05/addressing/wsdl"
>> >> EndpointName="JpoCbpEngineeringCB
>> >> PWorkflow"
>> >> xmlns:servicens="http://client.engineering.cbp.jpo
>> >> ">servicens:CBPWorkflowService</ServiceName></Metadata><Add
>> >> ress>
>> http://localhost:8080/ematrix/services/JpoCbpEngineeringCBPWorkflow
>> >> </Address></EndpointReference></service-ref>
>> >> DEBUG - GeronimoLog.debug(66) | GET MEX property
>> >> org.apache.ode.bpel.partnerRoleSessionId = null
>> >> 17:40:23,536 DEBUG [MessageExchangeImpl] GET MEX property
>> >> org.apache.ode.bpel.partnerRoleSessionId = null
>> >> DEBUG - GeronimoLog.debug(66) | GET MEX property
>> >> org.apache.ode.bpel.myRoleSessionId = null
>> >> 17:40:23,536 DEBUG [MessageExchangeImpl] GET MEX property
>> >> org.apache.ode.bpel.myRoleSessionId = null
>> >> DEBUG - GeronimoLog.debug(66) | My-Role EPR not specified, SEP will
>> not
>> >> be
>> >> used.
>> >> 17:40:23,536 DEBUG [ExternalService] My-Role EPR not specified, SEP
>> will
>> >> not
>> >> be used.
>> >> DEBUG - GeronimoLog.debug(66) | Axis2 sending message to
>> >> http://localhost:8080/ematrix/services/JpoCbpEngineeringCBPWork
>> >> flow using MEX {PartnerRoleMex#hqejbhcnphr2kte2v4jbl8 [PID
>> >> {http://eclipse.org/bpel/sample}ECRProcess-9] calling org.apa
>> >> che.ode.bpel.epr.WSAEndpoint@16fd757.setAttribute(...)}
>> >> 17:40:23,536 DEBUG [ExternalService] Axis2 sending message to
>> >> http://localhost:8080/ematrix/services/JpoCbpEngineeringCB
>> >> PWorkflow using MEX {PartnerRoleMex#hqejbhcnphr2kte2v4jbl8 [PID
>> >> {http://eclipse.org/bpel/sample}ECRProcess-9] calling or
>> >> g.apache.ode.bpel.epr.WSAEndpoint@16fd757.setAttribute(...)}
>> >> DEBUG - GeronimoLog.debug(66) | Message: <?xml version='1.0'
>> >> encoding='utf-8'?><soapenv:Envelope xmlns:soapenv="http://s
>> >> chemas.xmlsoap.org/soap/envelope/
>> "><soapenv:Body><axis2ns16:setAttribute
>> >> xmlns:axis2ns16="http://engineering.cbp.jpo" xm
>> >> lns:tns1="http://engineering.cbp.jpo">
>> >> <axis2ns16:in2
>> >> xmlns:ns="http://www.apache.org/ode/pmapi/types/2006/08/02/"
>> >> xmlns="http://www.apache.
>> >> org/ode/pmapi/types/2006/08/02/">1057</axis2ns16:in2>
>> >>
>> >>
>> >> </axis2ns16:setAttribute></soapenv:Body></soapenv:Envelope>
>> >> 17:40:23,536 DEBUG [ExternalService] Message: <?xml version='1.0'
>> >> encoding='utf-8'?><soapenv:Envelope xmlns:soapenv="htt
>> >>
>> >>
>> p://schemas.xmlsoap.org/soap/envelope/"><soapenv:Body><axis2ns16:setAttribute
>> >> xmlns:axis2ns16="http://engineering.cbp.jp
>> >> o" xmlns:tns1="http://engineering.cbp.jpo">
>> >> <axis2ns16:in2
>> >> xmlns:ns="http://www.apache.org/ode/pmapi/types/2006/08/02/"
>> >> xmlns="http://www.apache.
>> >> org/ode/pmapi/types/2006/08/02/">1057</axis2ns16:in2>
>> >>
>> >>
>> >> </axis2ns16:setAttribute></soapenv:Body></soapenv:Envelope>
>> >> DEBUG - GeronimoLog.debug(66) | replyAsync mex=hqejbhcnphr2kte2v4jbl8
>> >> 17:40:23,536 DEBUG [PartnerRoleMessageExchangeImpl] replyAsync
>> >> mex=hqejbhcnphr2kte2v4jbl8
>> >> DEBUG - GeronimoLog.debug(66) | Setting execution state on instance
>> 1057
>> >> 17:40:23,546 DEBUG [BpelRuntimeContextImpl] Setting execution state on
>> >> instance 1057
>> >> DEBUG - GeronimoLog.debug(66) | Thread[pool-2-thread-9,5,main]:
>> >> unlock(iid=1057)
>> >> 17:40:23,707 DEBUG [InstanceLockManager]
>> Thread[pool-2-thread-9,5,main]:
>> >> unlock(iid=1057)
>> >> DEBUG - GeronimoLog.debug(66) | Sending stateful TO epr in message
>> header
>> >> using session null
>> >> 17:40:23,717 DEBUG [SessionOutHandler] Sending stateful TO epr in
>> message
>> >> header using session null
>> >> DEBUG - GeronimoLog.debug(66) | Sending a message containing wsa
>> >> endpoints
>> >> in headers for session passing.
>> >> 17:40:23,717 DEBUG [SessionOutHandler] Sending a message containing
>> wsa
>> >> endpoints in headers for session passing.
>> >> DEBUG - GeronimoLog.debug(66) | <?xml version='1.0'
>> >> encoding='utf-8'?><soapenv:Envelope xmlns:soapenv="http://schemas.xm
>> >> lsoap.org/soap/envelope/"><soapenv:Header><addr:To
>> >> xmlns:addr="http://www.w3.org/2005/08/addressing">http://localhost:80
>> >> 80/ematrix/services/JpoCbpEngineeringCBPWorkflow</addr:To><addr:Action
>> >> xmlns:addr="http://www.w3.org/2005/08/addressing"
>> >> ></addr:Action><addr:ReplyTo
>> >> xmlns:addr="http://www.w3.org/2005/08/addressing"><addr:Address>
>> >> http://www.w3.org/2005/08/a
>> >> ddressing/anonymous</addr:Address></addr:ReplyTo><addr:MessageID
>> >> xmlns:addr="http://www.w3.org/2005/08/addressing">uuid:
>> >>
>> >>
>> hqejbhcnphr2kte2v4jbl9</addr:MessageID></soapenv:Header><soapenv:Body><axis2ns16:setAttribute
>> >> xmlns:axis2ns16="http://en
>> >> gineering.cbp.jpo" xmlns:tns1="http://engineering.cbp.jpo">
>> >> <axis2ns16:in2
>> >> xmlns:ns="http://www.apache.org/ode/pmapi/types/2006/08/02/"
>> >> xmlns="http://www.apache.
>> >> org/ode/pmapi/types/2006/08/02/">1057</axis2ns16:in2>
>> >>
>> >>
>> >> </axis2ns16:setAttribute></soapenv:Body></soapenv:Envelope>
>> >> 17:40:23,717 DEBUG [SessionOutHandler] <?xml version='1.0'
>> >> encoding='utf-8'?><soapenv:Envelope xmlns:soapenv="http://sch
>> >> emas.xmlsoap.org/soap/envelope/"><soapenv:Header><addr:To
>> >> xmlns:addr="http://www.w3.org/2005/08/addressing">http://local
>> >>
>> >>
>> host:8080/ematrix/services/JpoCbpEngineeringCBPWorkflow</addr:To><addr:Action
>> >> xmlns:addr="http://www.w3.org/2005/08/addr
>> >> essing"></addr:Action><addr:ReplyTo
>> >> xmlns:addr="http://www.w3.org/2005/08/addressing"><addr:Address>
>> >> http://www.w3.org/20
>> >>
>> 05/08/addressing/anonymous</addr:Address></addr:ReplyTo><addr:MessageID
>> >> xmlns:addr="http://www.w3.org/2005/08/addressing
>> >>
>> >>
>> ">uuid:hqejbhcnphr2kte2v4jbl9</addr:MessageID></soapenv:Header><soapenv:Body><axis2ns16:setAttribute
>> >> xmlns:axis2ns16="ht
>> >> tp://engineering.cbp.jpo" xmlns:tns1="http://engineering.cbp.jpo">
>> >> <axis2ns16:in2
>> >> xmlns:ns="http://www.apache.org/ode/pmapi/types/2006/08/02/"
>> >> xmlns="http://www.apache.
>> >> org/ode/pmapi/types/2006/08/02/">1057</axis2ns16:in2>
>> >>
>> >>
>> >> </axis2ns16:setAttribute></soapenv:Body></soapenv:Envelope>
>> >> ERROR - GeronimoLog.error(108) | Error sending message
>> >> (mex={PartnerRoleMex#hqejbhcnphr2kte2v4jbl8 [PID {http://eclipse.
>> >> org/bpel/sample}ECRProcess-9] calling
>> >> org.apache.ode.bpel.epr.WSAEndpoint@16fd757.setAttribute(...)}):
>> >> java.lang.NullPoi
>> >> nterException
>> >> org.apache.axis2.AxisFault: java.lang.NullPointerException
>> >> at
>> >> org.apache.axis2.util.Utils.getInboundFaultFromMessageContext(
>> Utils.java
>> >> :486)
>> >> at
>> >> org.apache.axis2.description.OutInAxisOperationClient.handleResponse(
>> >> OutInAxisOperation.java:343)
>> >> at
>> >> org.apache.axis2.description.OutInAxisOperationClient.send(
>> >> OutInAxisOperation.java:389)
>> >> at
>> >> org.apache.axis2.description.OutInAxisOperationClient.executeImpl(
>> >> OutInAxisOperation.java:211)
>> >> at
>> >> org.apache.axis2.client.OperationClient.execute(OperationClient.java
>> :163)
>> >> at
>> >>
>> org.apache.ode.axis2.ExternalService$1$1.call(ExternalService.java:150)
>> >> at
>> >> java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:269)
>> >> at java.util.concurrent.FutureTask.run(FutureTask.java:123)
>> >> at
>> >> java.util.concurrent.ThreadPoolExecutor$Worker.runTask(
>> >> ThreadPoolExecutor.java:650)
>> >> at
>> >> java.util.concurrent.ThreadPoolExecutor$Worker.run(
>> ThreadPoolExecutor.java
>> >> :675)
>> >> at java.lang.Thread.run(Thread.java:595)
>> >> 17:40:23,737 ERROR [ExternalService] Error sending message
>> >> (mex={PartnerRoleMex#hqejbhcnphr2kte2v4jbl8 [PID {http://ecli
>> >> pse.org/bpel/sample}ECRProcess-9] calling
>> >> org.apache.ode.bpel.epr.WSAEndpoint@16fd757.setAttribute(...)}):
>> >> java.lang.Nul
>> >> lPointerException
>> >> org.apache.axis2.AxisFault: java.lang.NullPointerException
>> >> at
>> >> org.apache.axis2.util.Utils.getInboundFaultFromMessageContext(
>> Utils.java
>> >> :486)
>> >> at
>> >> org.apache.axis2.description.OutInAxisOperationClient.handleResponse(
>> >> OutInAxisOperation.java:343)
>> >> at
>> >> org.apache.axis2.description.OutInAxisOperationClient.send(
>> >> OutInAxisOperation.java:389)
>> >> at
>> >> org.apache.axis2.description.OutInAxisOperationClient.executeImpl(
>> >> OutInAxisOperation.java:211)
>> >> at
>> >> org.apache.axis2.client.OperationClient.execute(OperationClient.java
>> :163)
>> >> at
>> >>
>> org.apache.ode.axis2.ExternalService$1$1.call(ExternalService.java:150)
>> >> at
>> >> java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:269)
>> >> at java.util.concurrent.FutureTask.run(FutureTask.java:123)
>> >> at
>> >> java.util.concurrent.ThreadPoolExecutor$Worker.runTask(
>> >> ThreadPoolExecutor.java:650)
>> >> at
>> >> java.util.concurrent.ThreadPoolExecutor$Worker.run(
>> ThreadPoolExecutor.java
>> >> :675)
>> >> at java.lang.Thread.run(Thread.java:595)
>> >> DEBUG - GeronimoLog.trace(54) |
>> >> Mex[hqejbhcnphr2kte2v4jbl8].setPortOp(...)
>> >> 17:40:23,747 DEBUG [MessageExchangeImpl]
>> >> Mex[hqejbhcnphr2kte2v4jbl8].setPortOp(...)
>> >> DEBUG - GeronimoLog.debug(66) | replyWithFailure
>> >> mex=hqejbhcnphr2kte2v4jbl8
>> >> failureType=COMMUNICATION_ERROR description=
>> >> Error sending message (mex={PartnerRoleMex#hqejbhcnphr2kte2v4jbl8 [PID
>> >> {http://eclipse.org/bpel/sample}ECRProcess-9] cal
>> >> ling org.apache.ode.bpel.epr.WSAEndpoint@16fd757.setAttribute(...)}):
>> >> java.lang.NullPointerException details=null
>> >> 17:40:23,747 DEBUG [PartnerRoleMessageExchangeImpl] replyWithFailure
>> >> mex=hqejbhcnphr2kte2v4jbl8 failureType=COMMUNICATIO
>> >> N_ERROR description=Error sending message
>> >> (mex={PartnerRoleMex#hqejbhcnphr2kte2v4jbl8 [PID
>> >> {http://eclipse.org/bpel/samp
>> >> le}ECRProcess-9] calling
>> >> org.apache.ode.bpel.epr.WSAEndpoint@16fd757.setAttribute(...)}):
>> >> java.lang.NullPointerException
>> >> details=null
>> >> DEBUG - GeronimoLog.debug(66) | create work event for
>> >> mex=hqejbhcnphr2kte2v4jbl8
>> >> 17:40:23,747 DEBUG [PartnerRoleMessageExchangeImpl] create work event
>> for
>> >> mex=hqejbhcnphr2kte2v4jbl8
>> >> DEBUG - GeronimoLog.debug(66) | Thread[pool-2-thread-9,5,main]:
>> >> lock(iid=1057, time=1MICROSECONDS)
>> >> 17:40:23,757 DEBUG [InstanceLockManager]
>> Thread[pool-2-thread-9,5,main]:
>> >> lock(iid=1057, time=1MICROSECONDS)
>> >> DEBUG - GeronimoLog.debug(66) | Thread[pool-2-thread-9,5,main]:
>> >> lock(iid=1057, time=1MICROSECONDS)-->GRANTED
>> >> 17:40:23,757 DEBUG [InstanceLockManager]
>> Thread[pool-2-thread-9,5,main]:
>> >> lock(iid=1057, time=1MICROSECONDS)-->GRANTED
>> >> DEBUG - GeronimoLog.debug(66) | >>
>> >> handleWorkEvent(jobData={type=INVOKE_RESPONSE,
>> >> mexid=hqejbhcnphr2kte2v4jbl8,
>> >> channel=
>> >> 54, iid=1057})
>> >> 17:40:23,757 DEBUG [BpelProcess] >>
>> >> handleWorkEvent(jobData={type=INVOKE_RESPONSE,
>> >> mexid=hqejbhcnphr2kte2v4jbl8,
>> >> channel
>> >> =54, iid=1057})
>> >> DEBUG - GeronimoLog.debug(66) | BpelRuntimeContextImpl created for
>> >> instance
>> >> 1057. INDEXED STATE={{OScope 'Design Change
>> >> Proposal' id=46}::4=[ACTIVE(...)], {OScope 'Design Change Proposal'
>> >> id=46}::4=[SCOPE(...)], {OScope 'UpdateCBPWorkflow'
>> >> id=144}::29=[ACTIVITYGUARD(...)],
>> >>
>> >>
>> OSequence#47-HiddenSequence::6=[SEQUENCE(self=(OSequence#47-HiddenSequence,Termination
>> >> Channel#9,ParentScopeChannel#11),
>> >> linkframe=org.apache.ode.bpel.runtime.LinkFrame@1c90d2c,
>> >> remaining=[{OScope
>> >> 'UpdateCBP
>> >> Workflow' id=144}, {OScope 'callbackClient' id=151}])],
>> >> OSequence#45-main::2=[SEQUENCE(self=(OSequence#45-main,Terminati
>> >> onChannel#3,ParentScopeChannel#5),
>> >> linkframe=org.apache.ode.bpel.runtime.LinkFrame@1c90d2c,
>> >> remaining=[{OScope
>> >> 'Design C
>> >> hange Proposal' id=46}])], {OScope 'UpdateCBPWorkflow'
>> >> id=144}::30=[ACTIVE(...)], OInvoke#145-UpdateCBPWorkflow::31=[ACT
>> >> IVITYGUARD(...)], {OScope 'UpdateCBPWorkflow'
>> id=144}::30=[SCOPE(...)],
>> >> {OScope '__PROCESS_SCOPE:ECRProcess' id=3}::0=[S
>> >> COPE(...)], {OScope '__PROCESS_SCOPE:ECRProcess'
>> id=3}::0=[ACTIVE(...)],
>> >> OSequence#47-HiddenSequence::5=[ACTIVITYGUARD(.
>> >> ..)], OSequence#45-main::1=[ACTIVITYGUARD(...)],
>> >> OInvoke#145-UpdateCBPWorkflow::32=[INVOKE(...)], {OScope 'Design
>> Change
>> >> Proposal' id=46}::3=[ACTIVITYGUARD(...)]}
>> >> 17:40:23,777 DEBUG [BpelRuntimeContextImpl] BpelRuntimeContextImpl
>> >> created
>> >> for instance 1057. INDEXED STATE={{OScope 'De
>> >> sign Change Proposal' id=46}::4=[ACTIVE(...)], {OScope 'Design Change
>> >> Proposal' id=46}::4=[SCOPE(...)], {OScope 'UpdateC
>> >> BPWorkflow' id=144}::29=[ACTIVITYGUARD(...)],
>> >>
>> OSequence#47-HiddenSequence::6=[SEQUENCE(self=(OSequence#47-HiddenSequence
>> >> ,TerminationChannel#9,ParentScopeChannel#11),
>> >> linkframe=org.apache.ode.bpel.runtime.LinkFrame@1c90d2c,
>> >> remaining=[{OScop
>> >> e 'UpdateCBPWorkflow' id=144}, {OScope 'callbackClient' id=151}])],
>> >> OSequence#45-main::2=[SEQUENCE(self=(OSequence#45-ma
>> >> in,TerminationChannel#3,ParentScopeChannel#5),
>> >> linkframe=org.apache.ode.bpel.runtime.LinkFrame@1c90d2c,
>> remaining=[{OSco
>> >> pe 'Design Change Proposal' id=46}])], {OScope 'UpdateCBPWorkflow'
>> >> id=144}::30=[ACTIVE(...)], OInvoke#145-UpdateCBPWorkf
>> >> low::31=[ACTIVITYGUARD(...)], {OScope 'UpdateCBPWorkflow'
>> >> id=144}::30=[SCOPE(...)], {OScope '__PROCESS_SCOPE:ECRProcess'
>> >> id=3}::0=[SCOPE(...)], {OScope '__PROCESS_SCOPE:ECRProcess'
>> >> id=3}::0=[ACTIVE(...)], OSequence#47-HiddenSequence::5=[ACT
>> >> IVITYGUARD(...)], OSequence#45-main::1=[ACTIVITYGUARD(...)],
>> >> OInvoke#145-UpdateCBPWorkflow::32=[INVOKE(...)], {OScope 'D
>> >> esign Change Proposal' id=46}::3=[ACTIVITYGUARD(...)]}
>> >> DEBUG - GeronimoLog.debug(66) | InvokeResponse event for iid 1057
>> >> 17:40:23,777 DEBUG [BpelProcess] InvokeResponse event for iid 1057
>> >> DEBUG - GeronimoLog.debug(66) | Invoking message response for mexid
>> >> hqejbhcnphr2kte2v4jbl8 and channel 54
>> >> --
>> >> View this message in context:
>> >>
>> http://www.nabble.com/Invoke---with-communication-error-tf4418802.html#a12603692
>> >> Sent from the Apache Ode User mailing list archive at Nabble.com.
>> >>
>> >>
>> >
>> >
>>
>> --
>> View this message in context:
>> http://www.nabble.com/Invoke---with-communication-error-tf4418802.html#a12615259
>> Sent from the Apache Ode User mailing list archive at Nabble.com.
>>
>>
>
>
--
View this message in context: http://www.nabble.com/Invoke---with-communication-error-tf4418802.html#a12626237
Sent from the Apache Ode User mailing list archive at Nabble.com.
Re: Invoke - with communication error
Posted by Alex Boisvert <bo...@intalio.com>.
Hi Anup,
The service is returning a 500 Internal Error... so I think what you should
do is compare the request sent by Ode with that of SoapUI and investigate
why your service is failing with Ode's request.
I don't think Axis2 should be throwing the NullPointerException either so it
would be nice if you could file a bug report for Axis2 as well.
cheers,
alex
On 9/11/07, Anup Chandran <an...@3ds.com> wrote:
>
>
>
> The Service works fine when i send request via soapUI.
>
> I turned on the httpclient DEBUG.
>
> This is trace..
>
> DEBUG - GeronimoLog.debug(66) | InvokeResponse event for iid 1202
> 09:46:35,240 DEBUG [BpelProcess] InvokeResponse event for iid 1202
> DEBUG - GeronimoLog.debug(66) | Invoking message response for mexid
> hqejbhcnphr2kvk6gstpxt and channel 40
> 09:46:35,240 DEBUG [BpelRuntimeContextImpl] Invoking message response for
> mexid hqejbhcnphr2kvk6gstpxt and channel 40
> DEBUG - GeronimoLog.debug(66) | Triggering response
> 09:46:35,240 DEBUG [BpelRuntimeContextImpl] Triggering response
> DEBUG - GeronimoLog.trace(54) | >>
> createScopeInstance(parentScopeId=1204,scope={OScope 'UpdateCBPWorkflow'
> id=144})
> 09:46:35,536 DEBUG [BpelProcess] >>
> createScopeInstance(parentScopeId=1204,scope={OScope 'UpdateCBPWorkflow'
> id=144})
> DEBUG - GeronimoLog.trace(54) | >>
> initializeEndpointReferences(parentScopeId=1270,partnerLinks=[])
> 09:46:35,546 DEBUG [BpelProcess] >>
> initializeEndpointReferences(parentScopeId=1270,partnerLinks=[])
> DEBUG - GeronimoLog.debug(66) | INVOKING PARTNER:
> partnerLink={PartnerLinkInstance partnerLinkDecl=OPartnerLink#44,scope
> InstanceId=1203}, op=setAttribute channel=InvokeResponseChannel#54)
> 09:46:35,566 DEBUG [BpelProcess] INVOKING PARTNER:
> partnerLink={PartnerLinkInstance partnerLinkDecl=OPartnerLink#44,scop
> eInstanceId=1203}, op=setAttribute channel=InvokeResponseChannel#54)
> DEBUG - GeronimoLog.debug(66) | INVOKE PARTNER (SEP): sessionId=null
> partnerSessionId=null
> 09:46:35,566 DEBUG [BpelRuntimeContextImpl] INVOKE PARTNER (SEP):
> sessionId=null partnerSessionId=null
> DEBUG - GeronimoLog.trace(54) | Mex[hqejbhcnphr2kvk6gstpxw].setPortOp(...)
> 09:46:35,566 DEBUG [MessageExchangeImpl]
> Mex[hqejbhcnphr2kvk6gstpxw].setPortOp(...)
> DEBUG - GeronimoLog.debug(66) | Routed: svcQname
> {http://client.engineering.cbp.jpo}CBPWorkflowService --> null
> 09:46:35,566 DEBUG [BpelEngineImpl] Routed: svcQname
> {http://client.engineering.cbp.jpo}CBPWorkflowService --> null
> DEBUG - GeronimoLog.debug(66) | Invoking a partner operation: setAttribute
> 09:46:35,566 DEBUG [MessageExchangeContextImpl] Invoking a partner
> operation: setAttribute
> DEBUG - GeronimoLog.debug(66) | The service to invoke is the external
> service org.apache.ode.axis2.ExternalService@d3852
> 5
> 09:46:35,566 DEBUG [MessageExchangeContextImpl] The service to invoke is
> the
> external service org.apache.ode.axis2.Exter
> nalService@d38525
> DEBUG - GeronimoLog.debug(66) | Resolving endpoint reference <?xml
> version="1.0" encoding="UTF-8"?>
> <service-ref
> xmlns="http://docs.oasis-open.org/wsbpel/2.0/serviceref
> "><EndpointReference
> xmlns="http://www.w3.org/2005/0
> 8/addressing"><Metadata><ServiceName
> xmlns="http://www.w3.org/2006/05/addressing/wsdl"
> EndpointName="JpoCbpEngineeringCB
> PWorkflow"
> xmlns:servicens="http://client.engineering.cbp.jpo
> ">servicens:CBPWorkflowService</ServiceName></Metadata><Add
> ress>http://localhost:8080/ematrix/services/JpoCbpEngineeringCBPWorkflow
> </Address></EndpointReference></service-ref>
> 09:46:35,566 DEBUG [EndpointReferenceContextImpl] Resolving endpoint
> reference <?xml version="1.0" encoding="UTF-8"?>
> <service-ref
> xmlns="http://docs.oasis-open.org/wsbpel/2.0/serviceref
> "><EndpointReference
> xmlns="http://www.w3.org/2005/0
> 8/addressing"><Metadata><ServiceName
> xmlns="http://www.w3.org/2006/05/addressing/wsdl"
> EndpointName="JpoCbpEngineeringCB
> PWorkflow"
> xmlns:servicens="http://client.engineering.cbp.jpo
> ">servicens:CBPWorkflowService</ServiceName></Metadata><Add
> ress>http://localhost:8080/ematrix/services/JpoCbpEngineeringCBPWorkflow
> </Address></EndpointReference></service-ref>
> DEBUG - GeronimoLog.debug(66) | GET MEX property
> org.apache.ode.bpel.partnerRoleSessionId = null
> 09:46:35,566 DEBUG [MessageExchangeImpl] GET MEX property
> org.apache.ode.bpel.partnerRoleSessionId = null
> DEBUG - GeronimoLog.debug(66) | GET MEX property
> org.apache.ode.bpel.myRoleSessionId = null
> 09:46:35,566 DEBUG [MessageExchangeImpl] GET MEX property
> org.apache.ode.bpel.myRoleSessionId = null
> DEBUG - GeronimoLog.debug(66) | My-Role EPR not specified, SEP will not be
> used.
> 09:46:35,566 DEBUG [ExternalService] My-Role EPR not specified, SEP will
> not
> be used.
> DEBUG - GeronimoLog.debug(66) | Axis2 sending message to
> http://localhost:8080/ematrix/services/JpoCbpEngineeringCBPWork
> flow using MEX {PartnerRoleMex#hqejbhcnphr2kvk6gstpxw [PID
> {http://eclipse.org/bpel/sample}ECRProcess-9] calling org.apa
> che.ode.bpel.epr.WSAEndpoint@11dca40.setAttribute(...)}
> 09:46:35,566 DEBUG [ExternalService] Axis2 sending message to
> http://localhost:8080/ematrix/services/JpoCbpEngineeringCB
> PWorkflow using MEX {PartnerRoleMex#hqejbhcnphr2kvk6gstpxw [PID
> {http://eclipse.org/bpel/sample}ECRProcess-9] calling or
> g.apache.ode.bpel.epr.WSAEndpoint@11dca40.setAttribute(...)}
> DEBUG - GeronimoLog.debug(66) | Message: <?xml version='1.0'
> encoding='utf-8'?><soapenv:Envelope xmlns:soapenv="http://s
> chemas.xmlsoap.org/soap/envelope/"><soapenv:Body><axis2ns4:setAttribute
> xmlns:axis2ns4="http://engineering.cbp.jpo" xmln
> s:tns1="http://engineering.cbp.jpo">
> <tns1:in2
> xmlns:ns="http://www.apache.org/ode/pmapi/types/2006/08/02/"
> xmlns="http://www.apache.org/o
> de/pmapi/types/2006/08/02/">1202</tns1:in2>
> </axis2ns4:setAttribute></soapenv:Body></soapenv:Envelope>
> 09:46:35,577 DEBUG [ExternalService] Message: <?xml version='1.0'
> encoding='utf-8'?><soapenv:Envelope xmlns:soapenv="htt
>
> p://schemas.xmlsoap.org/soap/envelope/"><soapenv:Body><axis2ns4:setAttribute
> xmlns:axis2ns4="http://engineering.cbp.jpo"
> xmlns:tns1="http://engineering.cbp.jpo">
> <tns1:in2
> xmlns:ns="http://www.apache.org/ode/pmapi/types/2006/08/02/"
> xmlns="http://www.apache.org/o
> de/pmapi/types/2006/08/02/">1202</tns1:in2>
> </axis2ns4:setAttribute></soapenv:Body></soapenv:Envelope>
> DEBUG - GeronimoLog.debug(66) | replyAsync mex=hqejbhcnphr2kvk6gstpxw
> 09:46:35,577 DEBUG [PartnerRoleMessageExchangeImpl] replyAsync
> mex=hqejbhcnphr2kvk6gstpxw
> DEBUG - GeronimoLog.debug(66) | Setting execution state on instance 1202
> 09:46:35,577 DEBUG [BpelRuntimeContextImpl] Setting execution state on
> instance 1202
> DEBUG - GeronimoLog.debug(66) | Thread[pool-2-thread-2,5,main]:
> unlock(iid=1202)
> 09:46:36,230 DEBUG [InstanceLockManager] Thread[pool-2-thread-2,5,main]:
> unlock(iid=1202)
> DEBUG - GeronimoLog.debug(66) | Sending stateful TO epr in message header
> using session null
> 09:46:36,251 DEBUG [SessionOutHandler] Sending stateful TO epr in message
> header using session null
> DEBUG - GeronimoLog.debug(66) | Sending a message containing wsa endpoints
> in headers for session passing.
> 09:46:36,251 DEBUG [SessionOutHandler] Sending a message containing wsa
> endpoints in headers for session passing.
> DEBUG - GeronimoLog.debug(66) | <?xml version='1.0'
> encoding='utf-8'?><soapenv:Envelope xmlns:soapenv="http://schemas.xm
> lsoap.org/soap/envelope/"><soapenv:Header><addr:To
> xmlns:addr="http://www.w3.org/2005/08/addressing">http://localhost:80
> 80/ematrix/services/JpoCbpEngineeringCBPWorkflow</addr:To><addr:Action
> xmlns:addr="http://www.w3.org/2005/08/addressing"
> ></addr:Action><addr:ReplyTo
> xmlns:addr="http://www.w3.org/2005/08/addressing"><addr:Address>
> http://www.w3.org/2005/08/a
> ddressing/anonymous</addr:Address></addr:ReplyTo><addr:MessageID
> xmlns:addr="http://www.w3.org/2005/08/addressing">uuid:
>
> hqejbhcnphr2kvk6gstpxx</addr:MessageID></soapenv:Header><soapenv:Body><axis2ns4:setAttribute
> xmlns:axis2ns4="http://engi
> neering.cbp.jpo" xmlns:tns1="http://engineering.cbp.jpo">
> <tns1:in2
> xmlns:ns="http://www.apache.org/ode/pmapi/types/2006/08/02/"
> xmlns="http://www.apache.org/o
> de/pmapi/types/2006/08/02/">1202</tns1:in2>
> </axis2ns4:setAttribute></soapenv:Body></soapenv:Envelope>
> 09:46:36,271 DEBUG [SessionOutHandler] <?xml version='1.0'
> encoding='utf-8'?><soapenv:Envelope xmlns:soapenv="http://sch
> emas.xmlsoap.org/soap/envelope/"><soapenv:Header><addr:To
> xmlns:addr="http://www.w3.org/2005/08/addressing">http://local
>
> host:8080/ematrix/services/JpoCbpEngineeringCBPWorkflow</addr:To><addr:Action
> xmlns:addr="http://www.w3.org/2005/08/addr
> essing"></addr:Action><addr:ReplyTo
> xmlns:addr="http://www.w3.org/2005/08/addressing"><addr:Address>
> http://www.w3.org/20
> 05/08/addressing/anonymous</addr:Address></addr:ReplyTo><addr:MessageID
> xmlns:addr="http://www.w3.org/2005/08/addressing
>
> ">uuid:hqejbhcnphr2kvk6gstpxx</addr:MessageID></soapenv:Header><soapenv:Body><axis2ns4:setAttribute
> xmlns:axis2ns4="http
> ://engineering.cbp.jpo" xmlns:tns1="http://engineering.cbp.jpo">
> <tns1:in2
> xmlns:ns="http://www.apache.org/ode/pmapi/types/2006/08/02/"
> xmlns="http://www.apache.org/o
> de/pmapi/types/2006/08/02/">1202</tns1:in2>
> </axis2ns4:setAttribute></soapenv:Body></soapenv:Envelope>
> DEBUG - GeronimoLog.debug(66) | Set parameter http.connection.timeout =
> 60000
> 09:46:36,271 DEBUG [DefaultHttpParams] Set parameter
> http.connection.timeout
> = 60000
> DEBUG - GeronimoLog.debug(66) | Set parameter http.socket.timeout = 60000
> 09:46:36,271 DEBUG [DefaultHttpParams] Set parameter http.socket.timeout =
> 60000
> DEBUG - GeronimoLog.debug(66) | Set parameter http.socket.timeout = 60000
> 09:46:36,271 DEBUG [DefaultHttpParams] Set parameter http.socket.timeout =
> 60000
> DEBUG - GeronimoLog.trace(54) | enter PostMethod.clearRequestBody()
> 09:46:36,271 DEBUG [PostMethod] enter PostMethod.clearRequestBody()
> DEBUG - GeronimoLog.trace(54) | enter
> EntityEnclosingMethod.clearRequestBody()
> 09:46:36,271 DEBUG [EntityEnclosingMethod] enter
> EntityEnclosingMethod.clearRequestBody()
> DEBUG - GeronimoLog.trace(54) | enter
> HttpClient.executeMethod(HostConfiguration,HttpMethod)
> 09:46:36,281 DEBUG [HttpClient] enter
> HttpClient.executeMethod(HostConfiguration,HttpMethod)
> DEBUG - GeronimoLog.trace(54) | enter
> HttpClient.executeMethod(HostConfiguration,HttpMethod,HttpState)
> 09:46:36,281 DEBUG [HttpClient] enter
> HttpClient.executeMethod(HostConfiguration,HttpMethod,HttpState)
> DEBUG - GeronimoLog.trace(54) | enter
> HttpConnectionManager.getConnectionWithTimeout(HostConfiguration, long)
> 09:46:36,281 DEBUG [MultiThreadedHttpConnectionManager] enter
> HttpConnectionManager.getConnectionWithTimeout(HostConfigu
> ration, long)
> DEBUG - GeronimoLog.debug(66) | HttpConnectionManager.getConnection
> : config
> = HostConfiguration[host=http://localhost:8
> 080], timeout = 0
> 09:46:36,281 DEBUG [MultiThreadedHttpConnectionManager]
> HttpConnectionManager.getConnection: config = HostConfiguration
> [host=http://localhost:8080], timeout = 0
> DEBUG - GeronimoLog.trace(54) | enter
> HttpConnectionManager.ConnectionPool.getHostPool(HostConfiguration)
> 09:46:36,281 DEBUG [MultiThreadedHttpConnectionManager] enter
> HttpConnectionManager.ConnectionPool.getHostPool(HostConfi
> guration)
> DEBUG - GeronimoLog.trace(54) | enter
> HttpConnectionManager.ConnectionPool.getHostPool(HostConfiguration)
> 09:46:36,281 DEBUG [MultiThreadedHttpConnectionManager] enter
> HttpConnectionManager.ConnectionPool.getHostPool(HostConfi
> guration)
> DEBUG - GeronimoLog.debug(66) | Allocating new connection,
> hostConfig=HostConfiguration[host=http://localhost:8080]
> 09:46:36,281 DEBUG [MultiThreadedHttpConnectionManager] Allocating new
> connection, hostConfig=HostConfiguration[host=htt
> p://localhost:8080]
> DEBUG - GeronimoLog.trace(54) | Attempt number 1 to process request
> 09:46:36,281 DEBUG [HttpMethodDirector] Attempt number 1 to process
> request
> DEBUG - GeronimoLog.trace(54) | enter HttpConnection.open()
> 09:46:36,281 DEBUG [HttpConnection] enter HttpConnection.open()
> DEBUG - GeronimoLog.debug(66) | Open connection to localhost:8080
> 09:46:36,281 DEBUG [HttpConnection] Open connection to localhost:8080
> DEBUG - GeronimoLog.trace(54) | enter HttpMethodBase.execute(HttpState,
> HttpConnection)
> 09:46:36,281 DEBUG [HttpMethodBase] enter HttpMethodBase.execute
> (HttpState,
> HttpConnection)
> DEBUG - GeronimoLog.trace(54) | enter HttpMethodBase.writeRequest
> (HttpState,
> HttpConnection)
> 09:46:36,281 DEBUG [HttpMethodBase] enter
> HttpMethodBase.writeRequest(HttpState, HttpConnection)
> DEBUG - GeronimoLog.trace(54) | enter
> HttpMethodBase.writeRequestLine(HttpState, HttpConnection)
> 09:46:36,291 DEBUG [HttpMethodBase] enter
> HttpMethodBase.writeRequestLine(HttpState, HttpConnection)
> DEBUG - GeronimoLog.trace(54) | enter
> HttpMethodBase.generateRequestLine(HttpConnection, String, String, String,
> String)
>
> 09:46:36,291 DEBUG [HttpMethodBase] enter
> HttpMethodBase.generateRequestLine(HttpConnection, String, String, String,
> Str
> ing)
> DEBUG - GeronimoLog.debug(66) | >> "POST
> /ematrix/services/JpoCbpEngineeringCBPWorkflow HTTP/1.1[\r][\n]"
> 09:46:36,291 DEBUG [header] >> "POST
> /ematrix/services/JpoCbpEngineeringCBPWorkflow HTTP/1.1[\r][\n]"
> DEBUG - GeronimoLog.trace(54) | enter HttpConnection.print(String)
> 09:46:36,291 DEBUG [HttpConnection] enter HttpConnection.print(String)
> DEBUG - GeronimoLog.trace(54) | enter HttpConnection.write(byte[])
> 09:46:36,291 DEBUG [HttpConnection] enter HttpConnection.write(byte[])
> DEBUG - GeronimoLog.trace(54) | enter HttpConnection.write(byte[], int,
> int)
> 09:46:36,291 DEBUG [HttpConnection] enter HttpConnection.write(byte[],
> int,
> int)
> DEBUG - GeronimoLog.trace(54) | enter
> HttpMethodBase.writeRequestHeaders(HttpState,HttpConnection)
> 09:46:36,291 DEBUG [HttpMethodBase] enter
> HttpMethodBase.writeRequestHeaders(HttpState,HttpConnection)
> DEBUG - GeronimoLog.trace(54) | enter
> EntityEnclosingMethod.addRequestHeaders(HttpState, HttpConnection)
> 09:46:36,291 DEBUG [EntityEnclosingMethod] enter
> EntityEnclosingMethod.addRequestHeaders(HttpState, HttpConnection)
> DEBUG - GeronimoLog.trace(54) | enter
> ExpectContinueMethod.addRequestHeaders(HttpState, HttpConnection)
> 09:46:36,291 DEBUG [ExpectContinueMethod] enter
> ExpectContinueMethod.addRequestHeaders(HttpState, HttpConnection)
> DEBUG - GeronimoLog.trace(54) | enter
> HttpMethodBase.addRequestHeaders(HttpState, HttpConnection)
> 09:46:36,291 DEBUG [HttpMethodBase] enter
> HttpMethodBase.addRequestHeaders(HttpState, HttpConnection)
> DEBUG - GeronimoLog.trace(54) | enter
> HttpMethodBase.addUserAgentRequestHeaders(HttpState, HttpConnection)
> 09:46:36,312 DEBUG [HttpMethodBase] enter
> HttpMethodBase.addUserAgentRequestHeaders(HttpState, HttpConnection)
> DEBUG - GeronimoLog.trace(54) | enter
> HttpMethodBase.addHostRequestHeader(HttpState, HttpConnection)
> 09:46:36,312 DEBUG [HttpMethodBase] enter
> HttpMethodBase.addHostRequestHeader(HttpState, HttpConnection)
> DEBUG - GeronimoLog.debug(66) | Adding Host request header
> 09:46:36,312 DEBUG [HttpMethodBase] Adding Host request header
> DEBUG - GeronimoLog.trace(54) | enter
> HttpMethodBase.addCookieRequestHeader(HttpState, HttpConnection)
> 09:46:36,312 DEBUG [HttpMethodBase] enter
> HttpMethodBase.addCookieRequestHeader(HttpState, HttpConnection)
> DEBUG - GeronimoLog.trace(54) | enter HttpState.getCookies()
> 09:46:36,312 DEBUG [HttpState] enter HttpState.getCookies()
> DEBUG - GeronimoLog.trace(54) | enter CookieSpecBase.match(String, int,
> String, boolean, Cookie[])
> 09:46:36,312 DEBUG [CookieSpec] enter CookieSpecBase.match(String, int,
> String, boolean, Cookie[])
> DEBUG - GeronimoLog.trace(54) | enter
> HttpMethodBase.addProxyConnectionHeader(HttpState, HttpConnection)
> 09:46:36,322 DEBUG [HttpMethodBase] enter
> HttpMethodBase.addProxyConnectionHeader(HttpState, HttpConnection)
> DEBUG - GeronimoLog.trace(54) | enter
> EntityEnclosingMethod.addContentLengthRequestHeader(HttpState,
> HttpConnection)
> 09:46:36,322 DEBUG [EntityEnclosingMethod] enter
> EntityEnclosingMethod.addContentLengthRequestHeader(HttpState, HttpConn
> ection)
> DEBUG - GeronimoLog.trace(54) | enter
> EntityEnclosingMethod.getRequestContentLength()
> 09:46:36,322 DEBUG [EntityEnclosingMethod] enter
> EntityEnclosingMethod.getRequestContentLength()
> DEBUG - GeronimoLog.trace(54) | enter PostMethod.hasRequestContent()
> 09:46:36,322 DEBUG [PostMethod] enter PostMethod.hasRequestContent()
> DEBUG - GeronimoLog.trace(54) | enter
> EntityEnclosingMethod.hasRequestContent()
> 09:46:36,322 DEBUG [EntityEnclosingMethod] enter
> EntityEnclosingMethod.hasRequestContent()
> DEBUG - GeronimoLog.trace(54) | HttpMethodBase.addRequestHeader(Header)
> 09:46:36,322 DEBUG [HttpMethodBase] HttpMethodBase.addRequestHeader
> (Header)
> DEBUG - GeronimoLog.debug(66) | >> "Content-Type: text/xml;
> charset=UTF-8[\r][\n]"
> 09:46:36,322 DEBUG [header] >> "Content-Type: text/xml;
> charset=UTF-8[\r][\n]"
> DEBUG - GeronimoLog.trace(54) | enter HttpConnection.print(String)
> 09:46:36,322 DEBUG [HttpConnection] enter HttpConnection.print(String)
> DEBUG - GeronimoLog.trace(54) | enter HttpConnection.write(byte[])
> 09:46:36,322 DEBUG [HttpConnection] enter HttpConnection.write(byte[])
> DEBUG - GeronimoLog.trace(54) | enter HttpConnection.write(byte[], int,
> int)
> 09:46:36,322 DEBUG [HttpConnection] enter HttpConnection.write(byte[],
> int,
> int)
> DEBUG - GeronimoLog.debug(66) | >> "SOAPAction: "urn:anonOutInOp"[\r][\n]"
> 09:46:36,322 DEBUG [header] >> "SOAPAction: "urn:anonOutInOp"[\r][\n]"
> DEBUG - GeronimoLog.trace(54) | enter HttpConnection.print(String)
> 09:46:36,322 DEBUG [HttpConnection] enter HttpConnection.print(String)
> DEBUG - GeronimoLog.trace(54) | enter HttpConnection.write(byte[])
> 09:46:36,322 DEBUG [HttpConnection] enter HttpConnection.write(byte[])
> DEBUG - GeronimoLog.trace(54) | enter HttpConnection.write(byte[], int,
> int)
> 09:46:36,322 DEBUG [HttpConnection] enter HttpConnection.write(byte[],
> int,
> int)
> DEBUG - GeronimoLog.debug(66) | >> "User-Agent: Axis2[\r][\n]"
> 09:46:36,322 DEBUG [header] >> "User-Agent: Axis2[\r][\n]"
> DEBUG - GeronimoLog.trace(54) | enter HttpConnection.print(String)
> 09:46:36,322 DEBUG [HttpConnection] enter HttpConnection.print(String)
> DEBUG - GeronimoLog.trace(54) | enter HttpConnection.write(byte[])
> 09:46:36,332 DEBUG [HttpConnection] enter HttpConnection.write(byte[])
> DEBUG - GeronimoLog.trace(54) | enter HttpConnection.write(byte[], int,
> int)
> 09:46:36,332 DEBUG [HttpConnection] enter HttpConnection.write(byte[],
> int,
> int)
> DEBUG - GeronimoLog.debug(66) | >> "Host: localhost:8080[\r][\n]"
> 09:46:36,332 DEBUG [header] >> "Host: localhost:8080[\r][\n]"
> DEBUG - GeronimoLog.trace(54) | enter HttpConnection.print(String)
> 09:46:36,332 DEBUG [HttpConnection] enter HttpConnection.print(String)
> DEBUG - GeronimoLog.trace(54) | enter HttpConnection.write(byte[])
> 09:46:36,332 DEBUG [HttpConnection] enter HttpConnection.write(byte[])
> DEBUG - GeronimoLog.trace(54) | enter HttpConnection.write(byte[], int,
> int)
> 09:46:36,332 DEBUG [HttpConnection] enter HttpConnection.write(byte[],
> int,
> int)
> DEBUG - GeronimoLog.debug(66) | >> "Transfer-Encoding: chunked[\r][\n]"
> 09:46:36,343 DEBUG [header] >> "Transfer-Encoding: chunked[\r][\n]"
> DEBUG - GeronimoLog.trace(54) | enter HttpConnection.print(String)
> 09:46:36,343 DEBUG [HttpConnection] enter HttpConnection.print(String)
> DEBUG - GeronimoLog.trace(54) | enter HttpConnection.write(byte[])
> 09:46:36,343 DEBUG [HttpConnection] enter HttpConnection.write(byte[])
> DEBUG - GeronimoLog.trace(54) | enter HttpConnection.write(byte[], int,
> int)
> 09:46:36,343 DEBUG [HttpConnection] enter HttpConnection.write(byte[],
> int,
> int)
> DEBUG - GeronimoLog.trace(54) | enter HttpConnection.writeLine()
> 09:46:36,343 DEBUG [HttpConnection] enter HttpConnection.writeLine()
> DEBUG - GeronimoLog.trace(54) | enter HttpConnection.write(byte[])
> 09:46:36,343 DEBUG [HttpConnection] enter HttpConnection.write(byte[])
> DEBUG - GeronimoLog.trace(54) | enter HttpConnection.write(byte[], int,
> int)
> 09:46:36,343 DEBUG [HttpConnection] enter HttpConnection.write(byte[],
> int,
> int)
> DEBUG - GeronimoLog.debug(66) | >> "[\r][\n]"
> 09:46:36,343 DEBUG [header] >> "[\r][\n]"
> DEBUG - GeronimoLog.trace(54) | enter
> EntityEnclosingMethod.writeRequestBody(HttpState, HttpConnection)
> 09:46:36,343 DEBUG [EntityEnclosingMethod] enter
> EntityEnclosingMethod.writeRequestBody(HttpState, HttpConnection)
> DEBUG - GeronimoLog.trace(54) | enter PostMethod.hasRequestContent()
> 09:46:36,343 DEBUG [PostMethod] enter PostMethod.hasRequestContent()
> DEBUG - GeronimoLog.trace(54) | enter
> EntityEnclosingMethod.hasRequestContent()
> 09:46:36,343 DEBUG [EntityEnclosingMethod] enter
> EntityEnclosingMethod.hasRequestContent()
> DEBUG - GeronimoLog.trace(54) | enter
> EntityEnclosingMethod.getRequestContentLength()
> 09:46:36,343 DEBUG [EntityEnclosingMethod] enter
> EntityEnclosingMethod.getRequestContentLength()
> DEBUG - GeronimoLog.trace(54) | enter PostMethod.hasRequestContent()
> 09:46:36,343 DEBUG [PostMethod] enter PostMethod.hasRequestContent()
> DEBUG - GeronimoLog.trace(54) | enter
> EntityEnclosingMethod.hasRequestContent()
> 09:46:36,343 DEBUG [EntityEnclosingMethod] enter
> EntityEnclosingMethod.hasRequestContent()
> DEBUG - GeronimoLog.trace(54) | enter
> HttpConnection.getRequestOutputStream()
> 09:46:36,343 DEBUG [HttpConnection] enter
> HttpConnection.getRequestOutputStream()
> DEBUG - GeronimoLog.debug(66) | Request body sent
> 09:46:36,353 DEBUG [EntityEnclosingMethod] Request body sent
> DEBUG - GeronimoLog.trace(54) | enter
> HttpConnection.flushRequestOutputStream()
> 09:46:36,363 DEBUG [HttpConnection] enter
> HttpConnection.flushRequestOutputStream()
> DEBUG - GeronimoLog.trace(54) | enter HttpMethodBase.readResponse
> (HttpState,
> HttpConnection)
> 09:46:36,394 DEBUG [HttpMethodBase] enter
> HttpMethodBase.readResponse(HttpState, HttpConnection)
> DEBUG - GeronimoLog.trace(54) | enter
> HttpMethodBase.readStatusLine(HttpState, HttpConnection)
> 09:46:36,394 DEBUG [HttpMethodBase] enter
> HttpMethodBase.readStatusLine(HttpState, HttpConnection)
> DEBUG - GeronimoLog.trace(54) | enter HttpConnection.readLine()
> 09:46:36,394 DEBUG [HttpConnection] enter HttpConnection.readLine()
> DEBUG - GeronimoLog.trace(54) | enter HttpParser.readLine(InputStream,
> String)
> 09:46:36,496 DEBUG [HttpParser] enter HttpParser.readLine(InputStream,
> String)
> DEBUG - GeronimoLog.trace(54) | enter HttpParser.readRawLine()
> 09:46:36,506 DEBUG [HttpParser] enter HttpParser.readRawLine()
> DEBUG - GeronimoLog.debug(66) | << "HTTP/1.1 500 Internal Server
> Error[\r][\n]"
> 09:46:37,507 DEBUG [header] << "HTTP/1.1 500 Internal Server
> Error[\r][\n]"
> DEBUG - GeronimoLog.trace(54) | enter
> HttpMethodBase.readResponseHeaders(HttpState,HttpConnection)
> 09:46:37,517 DEBUG [HttpMethodBase] enter
> HttpMethodBase.readResponseHeaders(HttpState,HttpConnection)
> DEBUG - GeronimoLog.trace(54) | enter
> HttpConnection.getResponseInputStream()
> 09:46:37,527 DEBUG [HttpConnection] enter
> HttpConnection.getResponseInputStream()
> DEBUG - GeronimoLog.trace(54) | enter HeaderParser.parseHeaders
> (InputStream,
> String)
> 09:46:37,527 DEBUG [HttpParser] enter HeaderParser.parseHeaders
> (InputStream,
> String)
> DEBUG - GeronimoLog.trace(54) | enter HttpParser.readLine(InputStream,
> String)
> 09:46:37,537 DEBUG [HttpParser] enter HttpParser.readLine(InputStream,
> String)
> DEBUG - GeronimoLog.trace(54) | enter HttpParser.readRawLine()
> 09:46:37,537 DEBUG [HttpParser] enter HttpParser.readRawLine()
> DEBUG - GeronimoLog.trace(54) | enter HttpParser.readLine(InputStream,
> String)
> 09:46:37,537 DEBUG [HttpParser] enter HttpParser.readLine(InputStream,
> String)
> DEBUG - GeronimoLog.trace(54) | enter HttpParser.readRawLine()
> 09:46:37,537 DEBUG [HttpParser] enter HttpParser.readRawLine()
> DEBUG - GeronimoLog.trace(54) | enter HttpParser.readLine(InputStream,
> String)
> 09:46:37,537 DEBUG [HttpParser] enter HttpParser.readLine(InputStream,
> String)
> DEBUG - GeronimoLog.trace(54) | enter HttpParser.readRawLine()
> 09:46:37,537 DEBUG [HttpParser] enter HttpParser.readRawLine()
> DEBUG - GeronimoLog.trace(54) | enter HttpParser.readLine(InputStream,
> String)
> 09:46:37,537 DEBUG [HttpParser] enter HttpParser.readLine(InputStream,
> String)
> DEBUG - GeronimoLog.trace(54) | enter HttpParser.readRawLine()
> 09:46:37,548 DEBUG [HttpParser] enter HttpParser.readRawLine()
> DEBUG - GeronimoLog.trace(54) | enter HttpParser.readLine(InputStream,
> String)
> 09:46:37,548 DEBUG [HttpParser] enter HttpParser.readLine(InputStream,
> String)
> DEBUG - GeronimoLog.trace(54) | enter HttpParser.readRawLine()
> 09:46:37,548 DEBUG [HttpParser] enter HttpParser.readRawLine()
> DEBUG - GeronimoLog.trace(54) | enter HttpParser.readLine(InputStream,
> String)
> 09:46:37,548 DEBUG [HttpParser] enter HttpParser.readLine(InputStream,
> String)
> DEBUG - GeronimoLog.trace(54) | enter HttpParser.readRawLine()
> 09:46:37,548 DEBUG [HttpParser] enter HttpParser.readRawLine()
> DEBUG - GeronimoLog.debug(66) | << "Server: Apache-Coyote/1.1[\r][\n]"
> 09:46:37,548 DEBUG [header] << "Server: Apache-Coyote/1.1[\r][\n]"
> DEBUG - GeronimoLog.debug(66) | << "Content-Type:
> text/xml;charset=utf-8[\r][\n]"
> 09:46:37,548 DEBUG [header] << "Content-Type:
> text/xml;charset=utf-8[\r][\n]"
> DEBUG - GeronimoLog.debug(66) | << "Transfer-Encoding: chunked[\r][\n]"
> 09:46:37,548 DEBUG [header] << "Transfer-Encoding: chunked[\r][\n]"
> DEBUG - GeronimoLog.debug(66) | << "Date: Tue, 11 Sep 2007 13:46:37
> GMT[\r][\n]"
> 09:46:37,558 DEBUG [header] << "Date: Tue, 11 Sep 2007 13:46:37
> GMT[\r][\n]"
> DEBUG - GeronimoLog.debug(66) | << "Connection: close[\r][\n]"
> 09:46:37,558 DEBUG [header] << "Connection: close[\r][\n]"
> DEBUG - GeronimoLog.trace(54) | enter
> HttpMethodBase.processResponseHeaders(HttpState, HttpConnection)
> 09:46:37,558 DEBUG [HttpMethodBase] enter
> HttpMethodBase.processResponseHeaders(HttpState, HttpConnection)
> DEBUG - GeronimoLog.trace(54) | enter
> HttpMethodBase.readResponseBody(HttpState, HttpConnection)
> 09:46:37,558 DEBUG [HttpMethodBase] enter
> HttpMethodBase.readResponseBody(HttpState, HttpConnection)
> DEBUG - GeronimoLog.trace(54) | enter
> HttpMethodBase.readResponseBody(HttpConnection)
> 09:46:37,578 DEBUG [HttpMethodBase] enter
> HttpMethodBase.readResponseBody(HttpConnection)
> DEBUG - GeronimoLog.trace(54) | enter
> HttpConnection.getResponseInputStream()
> 09:46:37,578 DEBUG [HttpConnection] enter
> HttpConnection.getResponseInputStream()
> DEBUG - GeronimoLog.trace(54) | enter
> HttpMethodBase.canResponseHaveBody(int)
> 09:46:37,578 DEBUG [HttpMethodBase] enter
> HttpMethodBase.canResponseHaveBody(int)
> DEBUG - GeronimoLog.trace(54) | enter HeaderElement.parseElements(String)
> 09:46:37,578 DEBUG [HeaderElement] enter HeaderElement.parseElements
> (String)
> DEBUG - GeronimoLog.trace(54) | enter HeaderElement.parseElements(char[])
> 09:46:37,578 DEBUG [HeaderElement] enter HeaderElement.parseElements
> (char[])
> DEBUG - GeronimoLog.trace(54) | enter
> HttpConnection.isResponseAvailable(int)
> 09:46:37,691 DEBUG [HttpConnection] enter
> HttpConnection.isResponseAvailable(int)
> DEBUG - GeronimoLog.trace(54) | enter HeaderElement.parseElements(String)
> 09:46:37,701 DEBUG [HeaderElement] enter HeaderElement.parseElements
> (String)
> DEBUG - GeronimoLog.trace(54) | enter HeaderElement.parseElements(char[])
> 09:46:37,701 DEBUG [HeaderElement] enter HeaderElement.parseElements
> (char[])
> DEBUG - GeronimoLog.trace(54) | enter
> HeaderElement.getParameterByName(String)
> 09:46:37,701 DEBUG [HeaderElement] enter
> HeaderElement.getParameterByName(String)
> ERROR - GeronimoLog.error(108) | Error sending message
> (mex={PartnerRoleMex#hqejbhcnphr2kvk6gstpxw [PID {http://eclipse.
> org/bpel/sample}ECRProcess-9] calling
> org.apache.ode.bpel.epr.WSAEndpoint@11dca40.setAttribute(...)}):
> java.lang.NullPoi
> nterException
> org.apache.axis2.AxisFault: java.lang.NullPointerException
> at
> org.apache.axis2.util.Utils.getInboundFaultFromMessageContext(Utils.java
> :486)
> at
> org.apache.axis2.description.OutInAxisOperationClient.handleResponse(
> OutInAxisOperation.java:343)
> at
> org.apache.axis2.description.OutInAxisOperationClient.send(
> OutInAxisOperation.java:389)
> at
> org.apache.axis2.description.OutInAxisOperationClient.executeImpl(
> OutInAxisOperation.java:211)
> at
> org.apache.axis2.client.OperationClient.execute(OperationClient.java:163)
> at
> org.apache.ode.axis2.ExternalService$1$1.call(ExternalService.java:150)
> at
> java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:269)
> at java.util.concurrent.FutureTask.run(FutureTask.java:123)
> at
> java.util.concurrent.ThreadPoolExecutor$Worker.runTask(
> ThreadPoolExecutor.java:650)
> at
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java
> :675)
> at java.lang.Thread.run(Thread.java:595)
> 09:46:37,772 ERROR [ExternalService] Error sending message
> (mex={PartnerRoleMex#hqejbhcnphr2kvk6gstpxw [PID {http://ecli
> pse.org/bpel/sample}ECRProcess-9] calling
> org.apache.ode.bpel.epr.WSAEndpoint@11dca40.setAttribute(...)}):
> java.lang.Nul
> lPointerException
> org.apache.axis2.AxisFault: java.lang.NullPointerException
> at
> org.apache.axis2.util.Utils.getInboundFaultFromMessageContext(Utils.java
> :486)
> at
> org.apache.axis2.description.OutInAxisOperationClient.handleResponse(
> OutInAxisOperation.java:343)
> at
> org.apache.axis2.description.OutInAxisOperationClient.send(
> OutInAxisOperation.java:389)
> at
> org.apache.axis2.description.OutInAxisOperationClient.executeImpl(
> OutInAxisOperation.java:211)
> at
> org.apache.axis2.client.OperationClient.execute(OperationClient.java:163)
> at
> org.apache.ode.axis2.ExternalService$1$1.call(ExternalService.java:150)
> at
> java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:269)
> at java.util.concurrent.FutureTask.run(FutureTask.java:123)
> at
> java.util.concurrent.ThreadPoolExecutor$Worker.runTask(
> ThreadPoolExecutor.java:650)
> at
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java
> :675)
> at java.lang.Thread.run(Thread.java:595)
> DEBUG - GeronimoLog.trace(54) | Mex[hqejbhcnphr2kvk6gstpxw].setPortOp(...)
> 09:46:37,803 DEBUG [MessageExchangeImpl]
> Mex[hqejbhcnphr2kvk6gstpxw].setPortOp(...)
> DEBUG - GeronimoLog.debug(66) | replyWithFailure
> mex=hqejbhcnphr2kvk6gstpxw
> failureType=COMMUNICATION_ERROR description=
> Error sending message (mex={PartnerRoleMex#hqejbhcnphr2kvk6gstpxw [PID
> {http://eclipse.org/bpel/sample}ECRProcess-9] cal
> ling org.apache.ode.bpel.epr.WSAEndpoint@11dca40.setAttribute(...)}):
> java.lang.NullPointerException details=null
> 09:46:37,803 DEBUG [PartnerRoleMessageExchangeImpl] replyWithFailure
> mex=hqejbhcnphr2kvk6gstpxw failureType=COMMUNICATIO
> N_ERROR description=Error sending message
> (mex={PartnerRoleMex#hqejbhcnphr2kvk6gstpxw [PID
> {http://eclipse.org/bpel/samp
> le}ECRProcess-9] calling
> org.apache.ode.bpel.epr.WSAEndpoint@11dca40.setAttribute(...)}):
> java.lang.NullPointerException
> details=null
> DEBUG - GeronimoLog.debug(66) | create work event for
> mex=hqejbhcnphr2kvk6gstpxw
> 09:46:37,803 DEBUG [PartnerRoleMessageExchangeImpl] create work event for
> mex=hqejbhcnphr2kvk6gstpxw
> DEBUG - GeronimoLog.debug(66) | Thread[pool-2-thread-2,5,main]:
> lock(iid=1202, time=1MICROSECONDS)
> 09:46:37,864 DEBUG [InstanceLockManager] Thread[pool-2-thread-2,5,main]:
> lock(iid=1202, time=1MICROSECONDS)
> DEBUG - GeronimoLog.debug(66) | Thread[pool-2-thread-2,5,main]:
> lock(iid=1202, time=1MICROSECONDS)-->GRANTED
> 09:46:37,864 DEBUG [InstanceLockManager] Thread[pool-2-thread-2,5,main]:
> lock(iid=1202, time=1MICROSECONDS)-->GRANTED
> DEBUG - GeronimoLog.debug(66) | >>
> handleWorkEvent(jobData={type=INVOKE_RESPONSE,
> mexid=hqejbhcnphr2kvk6gstpxw,
> channel=
> 54, iid=1202})
> 09:46:37,874 DEBUG [BpelProcess] >>
> handleWorkEvent(jobData={type=INVOKE_RESPONSE,
> mexid=hqejbhcnphr2kvk6gstpxw,
> channel
> =54, iid=1202})
> DEBUG - GeronimoLog.debug(66) | BpelRuntimeContextImpl created for
> instance
> 1202. INDEXED STATE={OSequence#45-main::1=[A
> CTIVITYGUARD(...)], OInvoke#145-UpdateCBPWorkflow::32=[INVOKE(...)],
> OSequence#47-HiddenSequence::6=[SEQUENCE(self=(OSeq
> uence#47-HiddenSequence,TerminationChannel#9,ParentScopeChannel#11),
> linkframe=org.apache.ode.bpel.runtime.LinkFrame@6c7
> d22, remaining=[{OScope 'UpdateCBPWorkflow' id=144}, {OScope
> 'callbackClient' id=151}])], OSequence#47-HiddenSequence::5
> =[ACTIVITYGUARD(...)], {OScope 'Design Change Proposal'
> id=46}::4=[SCOPE(...)], {OScope '__PROCESS_SCOPE:ECRProcess' id=
> 3}::0=[ACTIVE(...)], {OScope 'UpdateCBPWorkflow' id=144}::30=[SCOPE(...)],
> {OScope 'UpdateCBPWorkflow' id=144}::30=[ACTI
> VE(...)], OInvoke#145-UpdateCBPWorkflow::31=[ACTIVITYGUARD(...)], {OScope
> 'UpdateCBPWorkflow' id=144}::29=[ACTIVITYGUARD
> (...)], {OScope 'Design Change Proposal' id=46}::3=[ACTIVITYGUARD(...)],
> {OScope 'Design Change Proposal' id=46}::4=[ACT
> IVE(...)], {OScope '__PROCESS_SCOPE:ECRProcess' id=3}::0=[SCOPE(...)],
> OSequence#45-main::2=[SEQUENCE(self=(OSequence#45
> -main,TerminationChannel#3,ParentScopeChannel#5),
> linkframe=org.apache.ode.bpel.runtime.LinkFrame@6c7d22, remaining=[{OS
> cope 'Design Change Proposal' id=46}])]}
> 09:46:37,895 DEBUG [BpelRuntimeContextImpl] BpelRuntimeContextImpl created
> for instance 1202. INDEXED STATE={OSequence#4
> 5-main::1=[ACTIVITYGUARD(...)],
> OInvoke#145-UpdateCBPWorkflow::32=[INVOKE(...)],
> OSequence#47-HiddenSequence::6=[SEQUENC
>
> E(self=(OSequence#47-HiddenSequence,TerminationChannel#9,ParentScopeChannel#11),
> linkframe=org.apache.ode.bpel.runtime.L
> inkFrame@6c7d22, remaining=[{OScope 'UpdateCBPWorkflow' id=144}, {OScope
> 'callbackClient' id=151}])], OSequence#47-Hidde
> nSequence::5=[ACTIVITYGUARD(...)], {OScope 'Design Change Proposal'
> id=46}::4=[SCOPE(...)], {OScope '__PROCESS_SCOPE:ECR
> Process' id=3}::0=[ACTIVE(...)], {OScope 'UpdateCBPWorkflow'
> id=144}::30=[SCOPE(...)], {OScope 'UpdateCBPWorkflow' id=14
> 4}::30=[ACTIVE(...)],
> OInvoke#145-UpdateCBPWorkflow::31=[ACTIVITYGUARD(...)], {OScope
> 'UpdateCBPWorkflow' id=144}::29=[A
> CTIVITYGUARD(...)], {OScope 'Design Change Proposal'
> id=46}::3=[ACTIVITYGUARD(...)], {OScope 'Design Change Proposal' id
> =46}::4=[ACTIVE(...)], {OScope '__PROCESS_SCOPE:ECRProcess'
> id=3}::0=[SCOPE(...)], OSequence#45-main::2=[SEQUENCE(self=(
> OSequence#45-main,TerminationChannel#3,ParentScopeChannel#5),
> linkframe=org.apache.ode.bpel.runtime.LinkFrame@6c7d22, re
> maining=[{OScope 'Design Change Proposal' id=46}])]}
> DEBUG - GeronimoLog.debug(66) | InvokeResponse event for iid 1202
> 09:46:37,905 DEBUG [BpelProcess] InvokeResponse event for iid 1202
> DEBUG - GeronimoLog.debug(66) | Invoking message response for mexid
> hqejbhcnphr2kvk6gstpxw and channel 54
> 09:46:37,905 DEBUG [BpelRuntimeContextImpl] Invoking message response for
> mexid hqejbhcnphr2kvk6gstpxw and channel 54
> DEBUG - GeronimoLog.debug(66) | Triggering response
> 09:46:37,905 DEBUG [BpelRuntimeContextImpl] Triggering response
> INFO - GeronimoLog.info(79) | ActivityRecovery: Registering activity 31,
> failure reason: Error sending message (mex={Par
> tnerRoleMex#hqejbhcnphr2kvk6gstpxw [PID
> {http://eclipse.org/bpel/sample}ECRProcess-9] calling
> org.apache.ode.bpel.epr.WS
> AEndpoint@11dca40.setAttribute(...)}): java.lang.NullPointerException on
> channel 55
> 09:46:37,915 INFO [BpelRuntimeContextImpl] ActivityRecovery: Registering
> activity 31, failure reason: Error sending mes
> sage (mex={PartnerRoleMex#hqejbhcnphr2kvk6gstpxw [PID
> {http://eclipse.org/bpel/sample}ECRProcess-9] calling org.apache.o
> de.bpel.epr.WSAEndpoint@11dca40.setAttribute(...)}):
> java.lang.NullPointerException on channel 55
> DEBUG - GeronimoLog.debug(66) | Setting execution state on instance 1202
> 09:46:38,068 DEBUG [BpelRuntimeContextImpl] Setting execution state on
> instance 1202
> DEBUG - GeronimoLog.debug(66) | Thread[pool-2-thread-2,5,main]:
> unlock(iid=1202)
> 09:46:38,201 DEBUG [InstanceLockManager] Thread[pool-2-thread-2,5,main]:
> unlock(iid=1202)
> DEBUG - GeronimoLog.debug(66) | Connection reclaimed by garbage collector,
> hostConfig=HostConfiguration[host=http://loca
> lhost:8080]
> 09:47:31,939 DEBUG [MultiThreadedHttpConnectionManager] Connection
> reclaimed
> by garbage collector, hostConfig=HostConfig
> uration[host=http://localhost:8080]
> DEBUG - GeronimoLog.trace(54) | enter
> HttpConnectionManager.ConnectionPool.getHostPool(HostConfiguration)
> 09:47:40,293 DEBUG [MultiThreadedHttpConnectionManager] enter
> HttpConnectionManager.ConnectionPool.getHostPool(HostConfi
> guration)
> DEBUG - GeronimoLog.trace(54) | enter
> HttpConnectionManager.ConnectionPool.getHostPool(HostConfiguration)
> 09:47:40,303 DEBUG [MultiThreadedHttpConnectionManager] enter
> HttpConnectionManager.ConnectionPool.getHostPool(HostConfi
> guration)
> DEBUG - GeronimoLog.debug(66) | Notifying no-one, there are no waiting
> threads
> 09:47:40,303 DEBUG [MultiThreadedHttpConnectionManager] Notifying no-one,
> there are no waiting threads
> DEBUG - GeronimoLog.debug(66) | Connection reclaimed by garbage collector,
> hostConfig=HostConfiguration[host=http://loca
> lhost:8080]
> 09:47:40,303 DEBUG [MultiThreadedHttpConnectionManager] Connection
> reclaimed
> by garbage collector, hostConfig=HostConfig
> uration[host=http://localhost:8080]
> DEBUG - GeronimoLog.trace(54) | enter
> HttpConnectionManager.ConnectionPool.getHostPool(HostConfiguration)
> 09:47:40,303 DEBUG [MultiThreadedHttpConnectionManager] enter
> HttpConnectionManager.ConnectionPool.getHostPool(HostConfi
> guration)
> DEBUG - GeronimoLog.trace(54) | enter
> HttpConnectionManager.ConnectionPool.getHostPool(HostConfiguration)
> 09:47:40,314 DEBUG [MultiThreadedHttpConnectionManager] enter
> HttpConnectionManager.ConnectionPool.getHostPool(HostConfi
>
>
>
> Anup
>
>
>
>
> Alex Boisvert wrote:
> >
> > You're most likely getting some sort of failure from the service you're
> > invoking, and Axis2 has a hard time parsing the resulting fault message.
> > I
> > would recommend setting the "httpclient" log category to DEBUG to see
> > what's
> > going on the wire.
> >
> > alex
> >
> >
> > On 9/10/07, Anup Chandran <an...@3ds.com> wrote:
> >>
> >>
> >> Alex/Matthieu,
> >>
> >> I know this is pretty silly but cant figure what is the issue
> here......
> >> I
> >> have a runtime error with the following trace..... If i remove the
> >> invoke.
> >> from BPEL.. the process runs without errors. Can you tell me what is
> >> going
> >> on from the trace? Thanks...
> >>
> >> DEBUG - GeronimoLog.debug(66) | InvokeResponse event for iid 1057
> >> 17:40:22,965 DEBUG [BpelProcess] InvokeResponse event for iid 1057
> >> DEBUG - GeronimoLog.debug(66) | Invoking message response for mexid
> >> hqejbhcnphr2kte2v4jbl5 and channel 40
> >> 17:40:22,965 DEBUG [BpelRuntimeContextImpl] Invoking message response
> for
> >> mexid hqejbhcnphr2kte2v4jbl5 and channel 40
> >> DEBUG - GeronimoLog.debug(66) | Triggering response
> >> 17:40:22,965 DEBUG [BpelRuntimeContextImpl] Triggering response
> >> DEBUG - GeronimoLog.trace(54) | >>
> >> createScopeInstance(parentScopeId=1059,scope={OScope
> 'UpdateCBPWorkflow'
> >> id=144})
> >> 17:40:23,255 DEBUG [BpelProcess] >>
> >> createScopeInstance(parentScopeId=1059,scope={OScope
> 'UpdateCBPWorkflow'
> >> id=144})
> >> DEBUG - GeronimoLog.trace(54) | >>
> >> initializeEndpointReferences(parentScopeId=1125,partnerLinks=[])
> >> 17:40:23,506 DEBUG [BpelProcess] >>
> >> initializeEndpointReferences(parentScopeId=1125,partnerLinks=[])
> >> DEBUG - GeronimoLog.debug(66) | INVOKING PARTNER:
> >> partnerLink={PartnerLinkInstance partnerLinkDecl=OPartnerLink#44,scope
> >> InstanceId=1058}, op=setAttribute channel=InvokeResponseChannel#54)
> >> 17:40:23,526 DEBUG [BpelProcess] INVOKING PARTNER:
> >> partnerLink={PartnerLinkInstance partnerLinkDecl=OPartnerLink#44,scop
> >> eInstanceId=1058}, op=setAttribute channel=InvokeResponseChannel#54)
> >> DEBUG - GeronimoLog.debug(66) | INVOKE PARTNER (SEP): sessionId=null
> >> partnerSessionId=null
> >> 17:40:23,526 DEBUG [BpelRuntimeContextImpl] INVOKE PARTNER (SEP):
> >> sessionId=null partnerSessionId=null
> >> DEBUG - GeronimoLog.trace(54) |
> >> Mex[hqejbhcnphr2kte2v4jbl8].setPortOp(...)
> >> 17:40:23,526 DEBUG [MessageExchangeImpl]
> >> Mex[hqejbhcnphr2kte2v4jbl8].setPortOp(...)
> >> DEBUG - GeronimoLog.debug(66) | Routed: svcQname
> >> {http://client.engineering.cbp.jpo}CBPWorkflowService --> null
> >> 17:40:23,526 DEBUG [BpelEngineImpl] Routed: svcQname
> >> {http://client.engineering.cbp.jpo}CBPWorkflowService --> null
> >> DEBUG - GeronimoLog.debug(66) | Invoking a partner operation:
> >> setAttribute
> >> 17:40:23,526 DEBUG [MessageExchangeContextImpl] Invoking a partner
> >> operation: setAttribute
> >> DEBUG - GeronimoLog.debug(66) | The service to invoke is the external
> >> service org.apache.ode.axis2.ExternalService@1858f
> >> 02
> >> 17:40:23,536 DEBUG [MessageExchangeContextImpl] The service to invoke
> is
> >> the
> >> external service org.apache.ode.axis2.Exter
> >> nalService@1858f02
> >> DEBUG - GeronimoLog.debug(66) | Resolving endpoint reference <?xml
> >> version="1.0" encoding="UTF-8"?>
> >> <service-ref
> >> xmlns="http://docs.oasis-open.org/wsbpel/2.0/serviceref
> >> "><EndpointReference
> >> xmlns="http://www.w3.org/2005/0
> >> 8/addressing"><Metadata><ServiceName
> >> xmlns="http://www.w3.org/2006/05/addressing/wsdl"
> >> EndpointName="JpoCbpEngineeringCB
> >> PWorkflow"
> >> xmlns:servicens="http://client.engineering.cbp.jpo
> >> ">servicens:CBPWorkflowService</ServiceName></Metadata><Add
> >> ress>
> http://localhost:8080/ematrix/services/JpoCbpEngineeringCBPWorkflow
> >> </Address></EndpointReference></service-ref>
> >> 17:40:23,536 DEBUG [EndpointReferenceContextImpl] Resolving endpoint
> >> reference <?xml version="1.0" encoding="UTF-8"?>
> >> <service-ref
> >> xmlns="http://docs.oasis-open.org/wsbpel/2.0/serviceref
> >> "><EndpointReference
> >> xmlns="http://www.w3.org/2005/0
> >> 8/addressing"><Metadata><ServiceName
> >> xmlns="http://www.w3.org/2006/05/addressing/wsdl"
> >> EndpointName="JpoCbpEngineeringCB
> >> PWorkflow"
> >> xmlns:servicens="http://client.engineering.cbp.jpo
> >> ">servicens:CBPWorkflowService</ServiceName></Metadata><Add
> >> ress>
> http://localhost:8080/ematrix/services/JpoCbpEngineeringCBPWorkflow
> >> </Address></EndpointReference></service-ref>
> >> DEBUG - GeronimoLog.debug(66) | GET MEX property
> >> org.apache.ode.bpel.partnerRoleSessionId = null
> >> 17:40:23,536 DEBUG [MessageExchangeImpl] GET MEX property
> >> org.apache.ode.bpel.partnerRoleSessionId = null
> >> DEBUG - GeronimoLog.debug(66) | GET MEX property
> >> org.apache.ode.bpel.myRoleSessionId = null
> >> 17:40:23,536 DEBUG [MessageExchangeImpl] GET MEX property
> >> org.apache.ode.bpel.myRoleSessionId = null
> >> DEBUG - GeronimoLog.debug(66) | My-Role EPR not specified, SEP will not
> >> be
> >> used.
> >> 17:40:23,536 DEBUG [ExternalService] My-Role EPR not specified, SEP
> will
> >> not
> >> be used.
> >> DEBUG - GeronimoLog.debug(66) | Axis2 sending message to
> >> http://localhost:8080/ematrix/services/JpoCbpEngineeringCBPWork
> >> flow using MEX {PartnerRoleMex#hqejbhcnphr2kte2v4jbl8 [PID
> >> {http://eclipse.org/bpel/sample}ECRProcess-9] calling org.apa
> >> che.ode.bpel.epr.WSAEndpoint@16fd757.setAttribute(...)}
> >> 17:40:23,536 DEBUG [ExternalService] Axis2 sending message to
> >> http://localhost:8080/ematrix/services/JpoCbpEngineeringCB
> >> PWorkflow using MEX {PartnerRoleMex#hqejbhcnphr2kte2v4jbl8 [PID
> >> {http://eclipse.org/bpel/sample}ECRProcess-9] calling or
> >> g.apache.ode.bpel.epr.WSAEndpoint@16fd757.setAttribute(...)}
> >> DEBUG - GeronimoLog.debug(66) | Message: <?xml version='1.0'
> >> encoding='utf-8'?><soapenv:Envelope xmlns:soapenv="http://s
> >> chemas.xmlsoap.org/soap/envelope/
> "><soapenv:Body><axis2ns16:setAttribute
> >> xmlns:axis2ns16="http://engineering.cbp.jpo" xm
> >> lns:tns1="http://engineering.cbp.jpo">
> >> <axis2ns16:in2
> >> xmlns:ns="http://www.apache.org/ode/pmapi/types/2006/08/02/"
> >> xmlns="http://www.apache.
> >> org/ode/pmapi/types/2006/08/02/">1057</axis2ns16:in2>
> >>
> >>
> >> </axis2ns16:setAttribute></soapenv:Body></soapenv:Envelope>
> >> 17:40:23,536 DEBUG [ExternalService] Message: <?xml version='1.0'
> >> encoding='utf-8'?><soapenv:Envelope xmlns:soapenv="htt
> >>
> >>
> p://schemas.xmlsoap.org/soap/envelope/"><soapenv:Body><axis2ns16:setAttribute
> >> xmlns:axis2ns16="http://engineering.cbp.jp
> >> o" xmlns:tns1="http://engineering.cbp.jpo">
> >> <axis2ns16:in2
> >> xmlns:ns="http://www.apache.org/ode/pmapi/types/2006/08/02/"
> >> xmlns="http://www.apache.
> >> org/ode/pmapi/types/2006/08/02/">1057</axis2ns16:in2>
> >>
> >>
> >> </axis2ns16:setAttribute></soapenv:Body></soapenv:Envelope>
> >> DEBUG - GeronimoLog.debug(66) | replyAsync mex=hqejbhcnphr2kte2v4jbl8
> >> 17:40:23,536 DEBUG [PartnerRoleMessageExchangeImpl] replyAsync
> >> mex=hqejbhcnphr2kte2v4jbl8
> >> DEBUG - GeronimoLog.debug(66) | Setting execution state on instance
> 1057
> >> 17:40:23,546 DEBUG [BpelRuntimeContextImpl] Setting execution state on
> >> instance 1057
> >> DEBUG - GeronimoLog.debug(66) | Thread[pool-2-thread-9,5,main]:
> >> unlock(iid=1057)
> >> 17:40:23,707 DEBUG [InstanceLockManager]
> Thread[pool-2-thread-9,5,main]:
> >> unlock(iid=1057)
> >> DEBUG - GeronimoLog.debug(66) | Sending stateful TO epr in message
> header
> >> using session null
> >> 17:40:23,717 DEBUG [SessionOutHandler] Sending stateful TO epr in
> message
> >> header using session null
> >> DEBUG - GeronimoLog.debug(66) | Sending a message containing wsa
> >> endpoints
> >> in headers for session passing.
> >> 17:40:23,717 DEBUG [SessionOutHandler] Sending a message containing wsa
> >> endpoints in headers for session passing.
> >> DEBUG - GeronimoLog.debug(66) | <?xml version='1.0'
> >> encoding='utf-8'?><soapenv:Envelope xmlns:soapenv="http://schemas.xm
> >> lsoap.org/soap/envelope/"><soapenv:Header><addr:To
> >> xmlns:addr="http://www.w3.org/2005/08/addressing">http://localhost:80
> >> 80/ematrix/services/JpoCbpEngineeringCBPWorkflow</addr:To><addr:Action
> >> xmlns:addr="http://www.w3.org/2005/08/addressing"
> >> ></addr:Action><addr:ReplyTo
> >> xmlns:addr="http://www.w3.org/2005/08/addressing"><addr:Address>
> >> http://www.w3.org/2005/08/a
> >> ddressing/anonymous</addr:Address></addr:ReplyTo><addr:MessageID
> >> xmlns:addr="http://www.w3.org/2005/08/addressing">uuid:
> >>
> >>
> hqejbhcnphr2kte2v4jbl9</addr:MessageID></soapenv:Header><soapenv:Body><axis2ns16:setAttribute
> >> xmlns:axis2ns16="http://en
> >> gineering.cbp.jpo" xmlns:tns1="http://engineering.cbp.jpo">
> >> <axis2ns16:in2
> >> xmlns:ns="http://www.apache.org/ode/pmapi/types/2006/08/02/"
> >> xmlns="http://www.apache.
> >> org/ode/pmapi/types/2006/08/02/">1057</axis2ns16:in2>
> >>
> >>
> >> </axis2ns16:setAttribute></soapenv:Body></soapenv:Envelope>
> >> 17:40:23,717 DEBUG [SessionOutHandler] <?xml version='1.0'
> >> encoding='utf-8'?><soapenv:Envelope xmlns:soapenv="http://sch
> >> emas.xmlsoap.org/soap/envelope/"><soapenv:Header><addr:To
> >> xmlns:addr="http://www.w3.org/2005/08/addressing">http://local
> >>
> >>
> host:8080/ematrix/services/JpoCbpEngineeringCBPWorkflow</addr:To><addr:Action
> >> xmlns:addr="http://www.w3.org/2005/08/addr
> >> essing"></addr:Action><addr:ReplyTo
> >> xmlns:addr="http://www.w3.org/2005/08/addressing"><addr:Address>
> >> http://www.w3.org/20
> >> 05/08/addressing/anonymous</addr:Address></addr:ReplyTo><addr:MessageID
> >> xmlns:addr="http://www.w3.org/2005/08/addressing
> >>
> >>
> ">uuid:hqejbhcnphr2kte2v4jbl9</addr:MessageID></soapenv:Header><soapenv:Body><axis2ns16:setAttribute
> >> xmlns:axis2ns16="ht
> >> tp://engineering.cbp.jpo" xmlns:tns1="http://engineering.cbp.jpo">
> >> <axis2ns16:in2
> >> xmlns:ns="http://www.apache.org/ode/pmapi/types/2006/08/02/"
> >> xmlns="http://www.apache.
> >> org/ode/pmapi/types/2006/08/02/">1057</axis2ns16:in2>
> >>
> >>
> >> </axis2ns16:setAttribute></soapenv:Body></soapenv:Envelope>
> >> ERROR - GeronimoLog.error(108) | Error sending message
> >> (mex={PartnerRoleMex#hqejbhcnphr2kte2v4jbl8 [PID {http://eclipse.
> >> org/bpel/sample}ECRProcess-9] calling
> >> org.apache.ode.bpel.epr.WSAEndpoint@16fd757.setAttribute(...)}):
> >> java.lang.NullPoi
> >> nterException
> >> org.apache.axis2.AxisFault: java.lang.NullPointerException
> >> at
> >> org.apache.axis2.util.Utils.getInboundFaultFromMessageContext(
> Utils.java
> >> :486)
> >> at
> >> org.apache.axis2.description.OutInAxisOperationClient.handleResponse(
> >> OutInAxisOperation.java:343)
> >> at
> >> org.apache.axis2.description.OutInAxisOperationClient.send(
> >> OutInAxisOperation.java:389)
> >> at
> >> org.apache.axis2.description.OutInAxisOperationClient.executeImpl(
> >> OutInAxisOperation.java:211)
> >> at
> >> org.apache.axis2.client.OperationClient.execute(OperationClient.java
> :163)
> >> at
> >> org.apache.ode.axis2.ExternalService$1$1.call(ExternalService.java:150)
> >> at
> >> java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:269)
> >> at java.util.concurrent.FutureTask.run(FutureTask.java:123)
> >> at
> >> java.util.concurrent.ThreadPoolExecutor$Worker.runTask(
> >> ThreadPoolExecutor.java:650)
> >> at
> >> java.util.concurrent.ThreadPoolExecutor$Worker.run(
> ThreadPoolExecutor.java
> >> :675)
> >> at java.lang.Thread.run(Thread.java:595)
> >> 17:40:23,737 ERROR [ExternalService] Error sending message
> >> (mex={PartnerRoleMex#hqejbhcnphr2kte2v4jbl8 [PID {http://ecli
> >> pse.org/bpel/sample}ECRProcess-9] calling
> >> org.apache.ode.bpel.epr.WSAEndpoint@16fd757.setAttribute(...)}):
> >> java.lang.Nul
> >> lPointerException
> >> org.apache.axis2.AxisFault: java.lang.NullPointerException
> >> at
> >> org.apache.axis2.util.Utils.getInboundFaultFromMessageContext(
> Utils.java
> >> :486)
> >> at
> >> org.apache.axis2.description.OutInAxisOperationClient.handleResponse(
> >> OutInAxisOperation.java:343)
> >> at
> >> org.apache.axis2.description.OutInAxisOperationClient.send(
> >> OutInAxisOperation.java:389)
> >> at
> >> org.apache.axis2.description.OutInAxisOperationClient.executeImpl(
> >> OutInAxisOperation.java:211)
> >> at
> >> org.apache.axis2.client.OperationClient.execute(OperationClient.java
> :163)
> >> at
> >> org.apache.ode.axis2.ExternalService$1$1.call(ExternalService.java:150)
> >> at
> >> java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:269)
> >> at java.util.concurrent.FutureTask.run(FutureTask.java:123)
> >> at
> >> java.util.concurrent.ThreadPoolExecutor$Worker.runTask(
> >> ThreadPoolExecutor.java:650)
> >> at
> >> java.util.concurrent.ThreadPoolExecutor$Worker.run(
> ThreadPoolExecutor.java
> >> :675)
> >> at java.lang.Thread.run(Thread.java:595)
> >> DEBUG - GeronimoLog.trace(54) |
> >> Mex[hqejbhcnphr2kte2v4jbl8].setPortOp(...)
> >> 17:40:23,747 DEBUG [MessageExchangeImpl]
> >> Mex[hqejbhcnphr2kte2v4jbl8].setPortOp(...)
> >> DEBUG - GeronimoLog.debug(66) | replyWithFailure
> >> mex=hqejbhcnphr2kte2v4jbl8
> >> failureType=COMMUNICATION_ERROR description=
> >> Error sending message (mex={PartnerRoleMex#hqejbhcnphr2kte2v4jbl8 [PID
> >> {http://eclipse.org/bpel/sample}ECRProcess-9] cal
> >> ling org.apache.ode.bpel.epr.WSAEndpoint@16fd757.setAttribute(...)}):
> >> java.lang.NullPointerException details=null
> >> 17:40:23,747 DEBUG [PartnerRoleMessageExchangeImpl] replyWithFailure
> >> mex=hqejbhcnphr2kte2v4jbl8 failureType=COMMUNICATIO
> >> N_ERROR description=Error sending message
> >> (mex={PartnerRoleMex#hqejbhcnphr2kte2v4jbl8 [PID
> >> {http://eclipse.org/bpel/samp
> >> le}ECRProcess-9] calling
> >> org.apache.ode.bpel.epr.WSAEndpoint@16fd757.setAttribute(...)}):
> >> java.lang.NullPointerException
> >> details=null
> >> DEBUG - GeronimoLog.debug(66) | create work event for
> >> mex=hqejbhcnphr2kte2v4jbl8
> >> 17:40:23,747 DEBUG [PartnerRoleMessageExchangeImpl] create work event
> for
> >> mex=hqejbhcnphr2kte2v4jbl8
> >> DEBUG - GeronimoLog.debug(66) | Thread[pool-2-thread-9,5,main]:
> >> lock(iid=1057, time=1MICROSECONDS)
> >> 17:40:23,757 DEBUG [InstanceLockManager]
> Thread[pool-2-thread-9,5,main]:
> >> lock(iid=1057, time=1MICROSECONDS)
> >> DEBUG - GeronimoLog.debug(66) | Thread[pool-2-thread-9,5,main]:
> >> lock(iid=1057, time=1MICROSECONDS)-->GRANTED
> >> 17:40:23,757 DEBUG [InstanceLockManager]
> Thread[pool-2-thread-9,5,main]:
> >> lock(iid=1057, time=1MICROSECONDS)-->GRANTED
> >> DEBUG - GeronimoLog.debug(66) | >>
> >> handleWorkEvent(jobData={type=INVOKE_RESPONSE,
> >> mexid=hqejbhcnphr2kte2v4jbl8,
> >> channel=
> >> 54, iid=1057})
> >> 17:40:23,757 DEBUG [BpelProcess] >>
> >> handleWorkEvent(jobData={type=INVOKE_RESPONSE,
> >> mexid=hqejbhcnphr2kte2v4jbl8,
> >> channel
> >> =54, iid=1057})
> >> DEBUG - GeronimoLog.debug(66) | BpelRuntimeContextImpl created for
> >> instance
> >> 1057. INDEXED STATE={{OScope 'Design Change
> >> Proposal' id=46}::4=[ACTIVE(...)], {OScope 'Design Change Proposal'
> >> id=46}::4=[SCOPE(...)], {OScope 'UpdateCBPWorkflow'
> >> id=144}::29=[ACTIVITYGUARD(...)],
> >>
> >>
> OSequence#47-HiddenSequence::6=[SEQUENCE(self=(OSequence#47-HiddenSequence,Termination
> >> Channel#9,ParentScopeChannel#11),
> >> linkframe=org.apache.ode.bpel.runtime.LinkFrame@1c90d2c,
> >> remaining=[{OScope
> >> 'UpdateCBP
> >> Workflow' id=144}, {OScope 'callbackClient' id=151}])],
> >> OSequence#45-main::2=[SEQUENCE(self=(OSequence#45-main,Terminati
> >> onChannel#3,ParentScopeChannel#5),
> >> linkframe=org.apache.ode.bpel.runtime.LinkFrame@1c90d2c,
> >> remaining=[{OScope
> >> 'Design C
> >> hange Proposal' id=46}])], {OScope 'UpdateCBPWorkflow'
> >> id=144}::30=[ACTIVE(...)], OInvoke#145-UpdateCBPWorkflow::31=[ACT
> >> IVITYGUARD(...)], {OScope 'UpdateCBPWorkflow' id=144}::30=[SCOPE(...)],
> >> {OScope '__PROCESS_SCOPE:ECRProcess' id=3}::0=[S
> >> COPE(...)], {OScope '__PROCESS_SCOPE:ECRProcess'
> id=3}::0=[ACTIVE(...)],
> >> OSequence#47-HiddenSequence::5=[ACTIVITYGUARD(.
> >> ..)], OSequence#45-main::1=[ACTIVITYGUARD(...)],
> >> OInvoke#145-UpdateCBPWorkflow::32=[INVOKE(...)], {OScope 'Design Change
> >> Proposal' id=46}::3=[ACTIVITYGUARD(...)]}
> >> 17:40:23,777 DEBUG [BpelRuntimeContextImpl] BpelRuntimeContextImpl
> >> created
> >> for instance 1057. INDEXED STATE={{OScope 'De
> >> sign Change Proposal' id=46}::4=[ACTIVE(...)], {OScope 'Design Change
> >> Proposal' id=46}::4=[SCOPE(...)], {OScope 'UpdateC
> >> BPWorkflow' id=144}::29=[ACTIVITYGUARD(...)],
> >>
> OSequence#47-HiddenSequence::6=[SEQUENCE(self=(OSequence#47-HiddenSequence
> >> ,TerminationChannel#9,ParentScopeChannel#11),
> >> linkframe=org.apache.ode.bpel.runtime.LinkFrame@1c90d2c,
> >> remaining=[{OScop
> >> e 'UpdateCBPWorkflow' id=144}, {OScope 'callbackClient' id=151}])],
> >> OSequence#45-main::2=[SEQUENCE(self=(OSequence#45-ma
> >> in,TerminationChannel#3,ParentScopeChannel#5),
> >> linkframe=org.apache.ode.bpel.runtime.LinkFrame@1c90d2c,
> remaining=[{OSco
> >> pe 'Design Change Proposal' id=46}])], {OScope 'UpdateCBPWorkflow'
> >> id=144}::30=[ACTIVE(...)], OInvoke#145-UpdateCBPWorkf
> >> low::31=[ACTIVITYGUARD(...)], {OScope 'UpdateCBPWorkflow'
> >> id=144}::30=[SCOPE(...)], {OScope '__PROCESS_SCOPE:ECRProcess'
> >> id=3}::0=[SCOPE(...)], {OScope '__PROCESS_SCOPE:ECRProcess'
> >> id=3}::0=[ACTIVE(...)], OSequence#47-HiddenSequence::5=[ACT
> >> IVITYGUARD(...)], OSequence#45-main::1=[ACTIVITYGUARD(...)],
> >> OInvoke#145-UpdateCBPWorkflow::32=[INVOKE(...)], {OScope 'D
> >> esign Change Proposal' id=46}::3=[ACTIVITYGUARD(...)]}
> >> DEBUG - GeronimoLog.debug(66) | InvokeResponse event for iid 1057
> >> 17:40:23,777 DEBUG [BpelProcess] InvokeResponse event for iid 1057
> >> DEBUG - GeronimoLog.debug(66) | Invoking message response for mexid
> >> hqejbhcnphr2kte2v4jbl8 and channel 54
> >> --
> >> View this message in context:
> >>
> http://www.nabble.com/Invoke---with-communication-error-tf4418802.html#a12603692
> >> Sent from the Apache Ode User mailing list archive at Nabble.com.
> >>
> >>
> >
> >
>
> --
> View this message in context:
> http://www.nabble.com/Invoke---with-communication-error-tf4418802.html#a12615259
> Sent from the Apache Ode User mailing list archive at Nabble.com.
>
>
Re: Invoke - with communication error
Posted by Anup Chandran <an...@3ds.com>.
The Service works fine when i send request via soapUI.
I turned on the httpclient DEBUG.
This is trace..
DEBUG - GeronimoLog.debug(66) | InvokeResponse event for iid 1202
09:46:35,240 DEBUG [BpelProcess] InvokeResponse event for iid 1202
DEBUG - GeronimoLog.debug(66) | Invoking message response for mexid
hqejbhcnphr2kvk6gstpxt and channel 40
09:46:35,240 DEBUG [BpelRuntimeContextImpl] Invoking message response for
mexid hqejbhcnphr2kvk6gstpxt and channel 40
DEBUG - GeronimoLog.debug(66) | Triggering response
09:46:35,240 DEBUG [BpelRuntimeContextImpl] Triggering response
DEBUG - GeronimoLog.trace(54) | >>
createScopeInstance(parentScopeId=1204,scope={OScope 'UpdateCBPWorkflow'
id=144})
09:46:35,536 DEBUG [BpelProcess] >>
createScopeInstance(parentScopeId=1204,scope={OScope 'UpdateCBPWorkflow'
id=144})
DEBUG - GeronimoLog.trace(54) | >>
initializeEndpointReferences(parentScopeId=1270,partnerLinks=[])
09:46:35,546 DEBUG [BpelProcess] >>
initializeEndpointReferences(parentScopeId=1270,partnerLinks=[])
DEBUG - GeronimoLog.debug(66) | INVOKING PARTNER:
partnerLink={PartnerLinkInstance partnerLinkDecl=OPartnerLink#44,scope
InstanceId=1203}, op=setAttribute channel=InvokeResponseChannel#54)
09:46:35,566 DEBUG [BpelProcess] INVOKING PARTNER:
partnerLink={PartnerLinkInstance partnerLinkDecl=OPartnerLink#44,scop
eInstanceId=1203}, op=setAttribute channel=InvokeResponseChannel#54)
DEBUG - GeronimoLog.debug(66) | INVOKE PARTNER (SEP): sessionId=null
partnerSessionId=null
09:46:35,566 DEBUG [BpelRuntimeContextImpl] INVOKE PARTNER (SEP):
sessionId=null partnerSessionId=null
DEBUG - GeronimoLog.trace(54) | Mex[hqejbhcnphr2kvk6gstpxw].setPortOp(...)
09:46:35,566 DEBUG [MessageExchangeImpl]
Mex[hqejbhcnphr2kvk6gstpxw].setPortOp(...)
DEBUG - GeronimoLog.debug(66) | Routed: svcQname
{http://client.engineering.cbp.jpo}CBPWorkflowService --> null
09:46:35,566 DEBUG [BpelEngineImpl] Routed: svcQname
{http://client.engineering.cbp.jpo}CBPWorkflowService --> null
DEBUG - GeronimoLog.debug(66) | Invoking a partner operation: setAttribute
09:46:35,566 DEBUG [MessageExchangeContextImpl] Invoking a partner
operation: setAttribute
DEBUG - GeronimoLog.debug(66) | The service to invoke is the external
service org.apache.ode.axis2.ExternalService@d3852
5
09:46:35,566 DEBUG [MessageExchangeContextImpl] The service to invoke is the
external service org.apache.ode.axis2.Exter
nalService@d38525
DEBUG - GeronimoLog.debug(66) | Resolving endpoint reference <?xml
version="1.0" encoding="UTF-8"?>
<service-ref
xmlns="http://docs.oasis-open.org/wsbpel/2.0/serviceref"><EndpointReference
xmlns="http://www.w3.org/2005/0
8/addressing"><Metadata><ServiceName
xmlns="http://www.w3.org/2006/05/addressing/wsdl"
EndpointName="JpoCbpEngineeringCB
PWorkflow"
xmlns:servicens="http://client.engineering.cbp.jpo">servicens:CBPWorkflowService</ServiceName></Metadata><Add
ress>http://localhost:8080/ematrix/services/JpoCbpEngineeringCBPWorkflow</Address></EndpointReference></service-ref>
09:46:35,566 DEBUG [EndpointReferenceContextImpl] Resolving endpoint
reference <?xml version="1.0" encoding="UTF-8"?>
<service-ref
xmlns="http://docs.oasis-open.org/wsbpel/2.0/serviceref"><EndpointReference
xmlns="http://www.w3.org/2005/0
8/addressing"><Metadata><ServiceName
xmlns="http://www.w3.org/2006/05/addressing/wsdl"
EndpointName="JpoCbpEngineeringCB
PWorkflow"
xmlns:servicens="http://client.engineering.cbp.jpo">servicens:CBPWorkflowService</ServiceName></Metadata><Add
ress>http://localhost:8080/ematrix/services/JpoCbpEngineeringCBPWorkflow</Address></EndpointReference></service-ref>
DEBUG - GeronimoLog.debug(66) | GET MEX property
org.apache.ode.bpel.partnerRoleSessionId = null
09:46:35,566 DEBUG [MessageExchangeImpl] GET MEX property
org.apache.ode.bpel.partnerRoleSessionId = null
DEBUG - GeronimoLog.debug(66) | GET MEX property
org.apache.ode.bpel.myRoleSessionId = null
09:46:35,566 DEBUG [MessageExchangeImpl] GET MEX property
org.apache.ode.bpel.myRoleSessionId = null
DEBUG - GeronimoLog.debug(66) | My-Role EPR not specified, SEP will not be
used.
09:46:35,566 DEBUG [ExternalService] My-Role EPR not specified, SEP will not
be used.
DEBUG - GeronimoLog.debug(66) | Axis2 sending message to
http://localhost:8080/ematrix/services/JpoCbpEngineeringCBPWork
flow using MEX {PartnerRoleMex#hqejbhcnphr2kvk6gstpxw [PID
{http://eclipse.org/bpel/sample}ECRProcess-9] calling org.apa
che.ode.bpel.epr.WSAEndpoint@11dca40.setAttribute(...)}
09:46:35,566 DEBUG [ExternalService] Axis2 sending message to
http://localhost:8080/ematrix/services/JpoCbpEngineeringCB
PWorkflow using MEX {PartnerRoleMex#hqejbhcnphr2kvk6gstpxw [PID
{http://eclipse.org/bpel/sample}ECRProcess-9] calling or
g.apache.ode.bpel.epr.WSAEndpoint@11dca40.setAttribute(...)}
DEBUG - GeronimoLog.debug(66) | Message: <?xml version='1.0'
encoding='utf-8'?><soapenv:Envelope xmlns:soapenv="http://s
chemas.xmlsoap.org/soap/envelope/"><soapenv:Body><axis2ns4:setAttribute
xmlns:axis2ns4="http://engineering.cbp.jpo" xmln
s:tns1="http://engineering.cbp.jpo">
<tns1:in2
xmlns:ns="http://www.apache.org/ode/pmapi/types/2006/08/02/"
xmlns="http://www.apache.org/o
de/pmapi/types/2006/08/02/">1202</tns1:in2>
</axis2ns4:setAttribute></soapenv:Body></soapenv:Envelope>
09:46:35,577 DEBUG [ExternalService] Message: <?xml version='1.0'
encoding='utf-8'?><soapenv:Envelope xmlns:soapenv="htt
p://schemas.xmlsoap.org/soap/envelope/"><soapenv:Body><axis2ns4:setAttribute
xmlns:axis2ns4="http://engineering.cbp.jpo"
xmlns:tns1="http://engineering.cbp.jpo">
<tns1:in2
xmlns:ns="http://www.apache.org/ode/pmapi/types/2006/08/02/"
xmlns="http://www.apache.org/o
de/pmapi/types/2006/08/02/">1202</tns1:in2>
</axis2ns4:setAttribute></soapenv:Body></soapenv:Envelope>
DEBUG - GeronimoLog.debug(66) | replyAsync mex=hqejbhcnphr2kvk6gstpxw
09:46:35,577 DEBUG [PartnerRoleMessageExchangeImpl] replyAsync
mex=hqejbhcnphr2kvk6gstpxw
DEBUG - GeronimoLog.debug(66) | Setting execution state on instance 1202
09:46:35,577 DEBUG [BpelRuntimeContextImpl] Setting execution state on
instance 1202
DEBUG - GeronimoLog.debug(66) | Thread[pool-2-thread-2,5,main]:
unlock(iid=1202)
09:46:36,230 DEBUG [InstanceLockManager] Thread[pool-2-thread-2,5,main]:
unlock(iid=1202)
DEBUG - GeronimoLog.debug(66) | Sending stateful TO epr in message header
using session null
09:46:36,251 DEBUG [SessionOutHandler] Sending stateful TO epr in message
header using session null
DEBUG - GeronimoLog.debug(66) | Sending a message containing wsa endpoints
in headers for session passing.
09:46:36,251 DEBUG [SessionOutHandler] Sending a message containing wsa
endpoints in headers for session passing.
DEBUG - GeronimoLog.debug(66) | <?xml version='1.0'
encoding='utf-8'?><soapenv:Envelope xmlns:soapenv="http://schemas.xm
lsoap.org/soap/envelope/"><soapenv:Header><addr:To
xmlns:addr="http://www.w3.org/2005/08/addressing">http://localhost:80
80/ematrix/services/JpoCbpEngineeringCBPWorkflow</addr:To><addr:Action
xmlns:addr="http://www.w3.org/2005/08/addressing"
></addr:Action><addr:ReplyTo
xmlns:addr="http://www.w3.org/2005/08/addressing"><addr:Address>http://www.w3.org/2005/08/a
ddressing/anonymous</addr:Address></addr:ReplyTo><addr:MessageID
xmlns:addr="http://www.w3.org/2005/08/addressing">uuid:
hqejbhcnphr2kvk6gstpxx</addr:MessageID></soapenv:Header><soapenv:Body><axis2ns4:setAttribute
xmlns:axis2ns4="http://engi
neering.cbp.jpo" xmlns:tns1="http://engineering.cbp.jpo">
<tns1:in2
xmlns:ns="http://www.apache.org/ode/pmapi/types/2006/08/02/"
xmlns="http://www.apache.org/o
de/pmapi/types/2006/08/02/">1202</tns1:in2>
</axis2ns4:setAttribute></soapenv:Body></soapenv:Envelope>
09:46:36,271 DEBUG [SessionOutHandler] <?xml version='1.0'
encoding='utf-8'?><soapenv:Envelope xmlns:soapenv="http://sch
emas.xmlsoap.org/soap/envelope/"><soapenv:Header><addr:To
xmlns:addr="http://www.w3.org/2005/08/addressing">http://local
host:8080/ematrix/services/JpoCbpEngineeringCBPWorkflow</addr:To><addr:Action
xmlns:addr="http://www.w3.org/2005/08/addr
essing"></addr:Action><addr:ReplyTo
xmlns:addr="http://www.w3.org/2005/08/addressing"><addr:Address>http://www.w3.org/20
05/08/addressing/anonymous</addr:Address></addr:ReplyTo><addr:MessageID
xmlns:addr="http://www.w3.org/2005/08/addressing
">uuid:hqejbhcnphr2kvk6gstpxx</addr:MessageID></soapenv:Header><soapenv:Body><axis2ns4:setAttribute
xmlns:axis2ns4="http
://engineering.cbp.jpo" xmlns:tns1="http://engineering.cbp.jpo">
<tns1:in2
xmlns:ns="http://www.apache.org/ode/pmapi/types/2006/08/02/"
xmlns="http://www.apache.org/o
de/pmapi/types/2006/08/02/">1202</tns1:in2>
</axis2ns4:setAttribute></soapenv:Body></soapenv:Envelope>
DEBUG - GeronimoLog.debug(66) | Set parameter http.connection.timeout =
60000
09:46:36,271 DEBUG [DefaultHttpParams] Set parameter http.connection.timeout
= 60000
DEBUG - GeronimoLog.debug(66) | Set parameter http.socket.timeout = 60000
09:46:36,271 DEBUG [DefaultHttpParams] Set parameter http.socket.timeout =
60000
DEBUG - GeronimoLog.debug(66) | Set parameter http.socket.timeout = 60000
09:46:36,271 DEBUG [DefaultHttpParams] Set parameter http.socket.timeout =
60000
DEBUG - GeronimoLog.trace(54) | enter PostMethod.clearRequestBody()
09:46:36,271 DEBUG [PostMethod] enter PostMethod.clearRequestBody()
DEBUG - GeronimoLog.trace(54) | enter
EntityEnclosingMethod.clearRequestBody()
09:46:36,271 DEBUG [EntityEnclosingMethod] enter
EntityEnclosingMethod.clearRequestBody()
DEBUG - GeronimoLog.trace(54) | enter
HttpClient.executeMethod(HostConfiguration,HttpMethod)
09:46:36,281 DEBUG [HttpClient] enter
HttpClient.executeMethod(HostConfiguration,HttpMethod)
DEBUG - GeronimoLog.trace(54) | enter
HttpClient.executeMethod(HostConfiguration,HttpMethod,HttpState)
09:46:36,281 DEBUG [HttpClient] enter
HttpClient.executeMethod(HostConfiguration,HttpMethod,HttpState)
DEBUG - GeronimoLog.trace(54) | enter
HttpConnectionManager.getConnectionWithTimeout(HostConfiguration, long)
09:46:36,281 DEBUG [MultiThreadedHttpConnectionManager] enter
HttpConnectionManager.getConnectionWithTimeout(HostConfigu
ration, long)
DEBUG - GeronimoLog.debug(66) | HttpConnectionManager.getConnection: config
= HostConfiguration[host=http://localhost:8
080], timeout = 0
09:46:36,281 DEBUG [MultiThreadedHttpConnectionManager]
HttpConnectionManager.getConnection: config = HostConfiguration
[host=http://localhost:8080], timeout = 0
DEBUG - GeronimoLog.trace(54) | enter
HttpConnectionManager.ConnectionPool.getHostPool(HostConfiguration)
09:46:36,281 DEBUG [MultiThreadedHttpConnectionManager] enter
HttpConnectionManager.ConnectionPool.getHostPool(HostConfi
guration)
DEBUG - GeronimoLog.trace(54) | enter
HttpConnectionManager.ConnectionPool.getHostPool(HostConfiguration)
09:46:36,281 DEBUG [MultiThreadedHttpConnectionManager] enter
HttpConnectionManager.ConnectionPool.getHostPool(HostConfi
guration)
DEBUG - GeronimoLog.debug(66) | Allocating new connection,
hostConfig=HostConfiguration[host=http://localhost:8080]
09:46:36,281 DEBUG [MultiThreadedHttpConnectionManager] Allocating new
connection, hostConfig=HostConfiguration[host=htt
p://localhost:8080]
DEBUG - GeronimoLog.trace(54) | Attempt number 1 to process request
09:46:36,281 DEBUG [HttpMethodDirector] Attempt number 1 to process request
DEBUG - GeronimoLog.trace(54) | enter HttpConnection.open()
09:46:36,281 DEBUG [HttpConnection] enter HttpConnection.open()
DEBUG - GeronimoLog.debug(66) | Open connection to localhost:8080
09:46:36,281 DEBUG [HttpConnection] Open connection to localhost:8080
DEBUG - GeronimoLog.trace(54) | enter HttpMethodBase.execute(HttpState,
HttpConnection)
09:46:36,281 DEBUG [HttpMethodBase] enter HttpMethodBase.execute(HttpState,
HttpConnection)
DEBUG - GeronimoLog.trace(54) | enter HttpMethodBase.writeRequest(HttpState,
HttpConnection)
09:46:36,281 DEBUG [HttpMethodBase] enter
HttpMethodBase.writeRequest(HttpState, HttpConnection)
DEBUG - GeronimoLog.trace(54) | enter
HttpMethodBase.writeRequestLine(HttpState, HttpConnection)
09:46:36,291 DEBUG [HttpMethodBase] enter
HttpMethodBase.writeRequestLine(HttpState, HttpConnection)
DEBUG - GeronimoLog.trace(54) | enter
HttpMethodBase.generateRequestLine(HttpConnection, String, String, String,
String)
09:46:36,291 DEBUG [HttpMethodBase] enter
HttpMethodBase.generateRequestLine(HttpConnection, String, String, String,
Str
ing)
DEBUG - GeronimoLog.debug(66) | >> "POST
/ematrix/services/JpoCbpEngineeringCBPWorkflow HTTP/1.1[\r][\n]"
09:46:36,291 DEBUG [header] >> "POST
/ematrix/services/JpoCbpEngineeringCBPWorkflow HTTP/1.1[\r][\n]"
DEBUG - GeronimoLog.trace(54) | enter HttpConnection.print(String)
09:46:36,291 DEBUG [HttpConnection] enter HttpConnection.print(String)
DEBUG - GeronimoLog.trace(54) | enter HttpConnection.write(byte[])
09:46:36,291 DEBUG [HttpConnection] enter HttpConnection.write(byte[])
DEBUG - GeronimoLog.trace(54) | enter HttpConnection.write(byte[], int, int)
09:46:36,291 DEBUG [HttpConnection] enter HttpConnection.write(byte[], int,
int)
DEBUG - GeronimoLog.trace(54) | enter
HttpMethodBase.writeRequestHeaders(HttpState,HttpConnection)
09:46:36,291 DEBUG [HttpMethodBase] enter
HttpMethodBase.writeRequestHeaders(HttpState,HttpConnection)
DEBUG - GeronimoLog.trace(54) | enter
EntityEnclosingMethod.addRequestHeaders(HttpState, HttpConnection)
09:46:36,291 DEBUG [EntityEnclosingMethod] enter
EntityEnclosingMethod.addRequestHeaders(HttpState, HttpConnection)
DEBUG - GeronimoLog.trace(54) | enter
ExpectContinueMethod.addRequestHeaders(HttpState, HttpConnection)
09:46:36,291 DEBUG [ExpectContinueMethod] enter
ExpectContinueMethod.addRequestHeaders(HttpState, HttpConnection)
DEBUG - GeronimoLog.trace(54) | enter
HttpMethodBase.addRequestHeaders(HttpState, HttpConnection)
09:46:36,291 DEBUG [HttpMethodBase] enter
HttpMethodBase.addRequestHeaders(HttpState, HttpConnection)
DEBUG - GeronimoLog.trace(54) | enter
HttpMethodBase.addUserAgentRequestHeaders(HttpState, HttpConnection)
09:46:36,312 DEBUG [HttpMethodBase] enter
HttpMethodBase.addUserAgentRequestHeaders(HttpState, HttpConnection)
DEBUG - GeronimoLog.trace(54) | enter
HttpMethodBase.addHostRequestHeader(HttpState, HttpConnection)
09:46:36,312 DEBUG [HttpMethodBase] enter
HttpMethodBase.addHostRequestHeader(HttpState, HttpConnection)
DEBUG - GeronimoLog.debug(66) | Adding Host request header
09:46:36,312 DEBUG [HttpMethodBase] Adding Host request header
DEBUG - GeronimoLog.trace(54) | enter
HttpMethodBase.addCookieRequestHeader(HttpState, HttpConnection)
09:46:36,312 DEBUG [HttpMethodBase] enter
HttpMethodBase.addCookieRequestHeader(HttpState, HttpConnection)
DEBUG - GeronimoLog.trace(54) | enter HttpState.getCookies()
09:46:36,312 DEBUG [HttpState] enter HttpState.getCookies()
DEBUG - GeronimoLog.trace(54) | enter CookieSpecBase.match(String, int,
String, boolean, Cookie[])
09:46:36,312 DEBUG [CookieSpec] enter CookieSpecBase.match(String, int,
String, boolean, Cookie[])
DEBUG - GeronimoLog.trace(54) | enter
HttpMethodBase.addProxyConnectionHeader(HttpState, HttpConnection)
09:46:36,322 DEBUG [HttpMethodBase] enter
HttpMethodBase.addProxyConnectionHeader(HttpState, HttpConnection)
DEBUG - GeronimoLog.trace(54) | enter
EntityEnclosingMethod.addContentLengthRequestHeader(HttpState,
HttpConnection)
09:46:36,322 DEBUG [EntityEnclosingMethod] enter
EntityEnclosingMethod.addContentLengthRequestHeader(HttpState, HttpConn
ection)
DEBUG - GeronimoLog.trace(54) | enter
EntityEnclosingMethod.getRequestContentLength()
09:46:36,322 DEBUG [EntityEnclosingMethod] enter
EntityEnclosingMethod.getRequestContentLength()
DEBUG - GeronimoLog.trace(54) | enter PostMethod.hasRequestContent()
09:46:36,322 DEBUG [PostMethod] enter PostMethod.hasRequestContent()
DEBUG - GeronimoLog.trace(54) | enter
EntityEnclosingMethod.hasRequestContent()
09:46:36,322 DEBUG [EntityEnclosingMethod] enter
EntityEnclosingMethod.hasRequestContent()
DEBUG - GeronimoLog.trace(54) | HttpMethodBase.addRequestHeader(Header)
09:46:36,322 DEBUG [HttpMethodBase] HttpMethodBase.addRequestHeader(Header)
DEBUG - GeronimoLog.debug(66) | >> "Content-Type: text/xml;
charset=UTF-8[\r][\n]"
09:46:36,322 DEBUG [header] >> "Content-Type: text/xml;
charset=UTF-8[\r][\n]"
DEBUG - GeronimoLog.trace(54) | enter HttpConnection.print(String)
09:46:36,322 DEBUG [HttpConnection] enter HttpConnection.print(String)
DEBUG - GeronimoLog.trace(54) | enter HttpConnection.write(byte[])
09:46:36,322 DEBUG [HttpConnection] enter HttpConnection.write(byte[])
DEBUG - GeronimoLog.trace(54) | enter HttpConnection.write(byte[], int, int)
09:46:36,322 DEBUG [HttpConnection] enter HttpConnection.write(byte[], int,
int)
DEBUG - GeronimoLog.debug(66) | >> "SOAPAction: "urn:anonOutInOp"[\r][\n]"
09:46:36,322 DEBUG [header] >> "SOAPAction: "urn:anonOutInOp"[\r][\n]"
DEBUG - GeronimoLog.trace(54) | enter HttpConnection.print(String)
09:46:36,322 DEBUG [HttpConnection] enter HttpConnection.print(String)
DEBUG - GeronimoLog.trace(54) | enter HttpConnection.write(byte[])
09:46:36,322 DEBUG [HttpConnection] enter HttpConnection.write(byte[])
DEBUG - GeronimoLog.trace(54) | enter HttpConnection.write(byte[], int, int)
09:46:36,322 DEBUG [HttpConnection] enter HttpConnection.write(byte[], int,
int)
DEBUG - GeronimoLog.debug(66) | >> "User-Agent: Axis2[\r][\n]"
09:46:36,322 DEBUG [header] >> "User-Agent: Axis2[\r][\n]"
DEBUG - GeronimoLog.trace(54) | enter HttpConnection.print(String)
09:46:36,322 DEBUG [HttpConnection] enter HttpConnection.print(String)
DEBUG - GeronimoLog.trace(54) | enter HttpConnection.write(byte[])
09:46:36,332 DEBUG [HttpConnection] enter HttpConnection.write(byte[])
DEBUG - GeronimoLog.trace(54) | enter HttpConnection.write(byte[], int, int)
09:46:36,332 DEBUG [HttpConnection] enter HttpConnection.write(byte[], int,
int)
DEBUG - GeronimoLog.debug(66) | >> "Host: localhost:8080[\r][\n]"
09:46:36,332 DEBUG [header] >> "Host: localhost:8080[\r][\n]"
DEBUG - GeronimoLog.trace(54) | enter HttpConnection.print(String)
09:46:36,332 DEBUG [HttpConnection] enter HttpConnection.print(String)
DEBUG - GeronimoLog.trace(54) | enter HttpConnection.write(byte[])
09:46:36,332 DEBUG [HttpConnection] enter HttpConnection.write(byte[])
DEBUG - GeronimoLog.trace(54) | enter HttpConnection.write(byte[], int, int)
09:46:36,332 DEBUG [HttpConnection] enter HttpConnection.write(byte[], int,
int)
DEBUG - GeronimoLog.debug(66) | >> "Transfer-Encoding: chunked[\r][\n]"
09:46:36,343 DEBUG [header] >> "Transfer-Encoding: chunked[\r][\n]"
DEBUG - GeronimoLog.trace(54) | enter HttpConnection.print(String)
09:46:36,343 DEBUG [HttpConnection] enter HttpConnection.print(String)
DEBUG - GeronimoLog.trace(54) | enter HttpConnection.write(byte[])
09:46:36,343 DEBUG [HttpConnection] enter HttpConnection.write(byte[])
DEBUG - GeronimoLog.trace(54) | enter HttpConnection.write(byte[], int, int)
09:46:36,343 DEBUG [HttpConnection] enter HttpConnection.write(byte[], int,
int)
DEBUG - GeronimoLog.trace(54) | enter HttpConnection.writeLine()
09:46:36,343 DEBUG [HttpConnection] enter HttpConnection.writeLine()
DEBUG - GeronimoLog.trace(54) | enter HttpConnection.write(byte[])
09:46:36,343 DEBUG [HttpConnection] enter HttpConnection.write(byte[])
DEBUG - GeronimoLog.trace(54) | enter HttpConnection.write(byte[], int, int)
09:46:36,343 DEBUG [HttpConnection] enter HttpConnection.write(byte[], int,
int)
DEBUG - GeronimoLog.debug(66) | >> "[\r][\n]"
09:46:36,343 DEBUG [header] >> "[\r][\n]"
DEBUG - GeronimoLog.trace(54) | enter
EntityEnclosingMethod.writeRequestBody(HttpState, HttpConnection)
09:46:36,343 DEBUG [EntityEnclosingMethod] enter
EntityEnclosingMethod.writeRequestBody(HttpState, HttpConnection)
DEBUG - GeronimoLog.trace(54) | enter PostMethod.hasRequestContent()
09:46:36,343 DEBUG [PostMethod] enter PostMethod.hasRequestContent()
DEBUG - GeronimoLog.trace(54) | enter
EntityEnclosingMethod.hasRequestContent()
09:46:36,343 DEBUG [EntityEnclosingMethod] enter
EntityEnclosingMethod.hasRequestContent()
DEBUG - GeronimoLog.trace(54) | enter
EntityEnclosingMethod.getRequestContentLength()
09:46:36,343 DEBUG [EntityEnclosingMethod] enter
EntityEnclosingMethod.getRequestContentLength()
DEBUG - GeronimoLog.trace(54) | enter PostMethod.hasRequestContent()
09:46:36,343 DEBUG [PostMethod] enter PostMethod.hasRequestContent()
DEBUG - GeronimoLog.trace(54) | enter
EntityEnclosingMethod.hasRequestContent()
09:46:36,343 DEBUG [EntityEnclosingMethod] enter
EntityEnclosingMethod.hasRequestContent()
DEBUG - GeronimoLog.trace(54) | enter
HttpConnection.getRequestOutputStream()
09:46:36,343 DEBUG [HttpConnection] enter
HttpConnection.getRequestOutputStream()
DEBUG - GeronimoLog.debug(66) | Request body sent
09:46:36,353 DEBUG [EntityEnclosingMethod] Request body sent
DEBUG - GeronimoLog.trace(54) | enter
HttpConnection.flushRequestOutputStream()
09:46:36,363 DEBUG [HttpConnection] enter
HttpConnection.flushRequestOutputStream()
DEBUG - GeronimoLog.trace(54) | enter HttpMethodBase.readResponse(HttpState,
HttpConnection)
09:46:36,394 DEBUG [HttpMethodBase] enter
HttpMethodBase.readResponse(HttpState, HttpConnection)
DEBUG - GeronimoLog.trace(54) | enter
HttpMethodBase.readStatusLine(HttpState, HttpConnection)
09:46:36,394 DEBUG [HttpMethodBase] enter
HttpMethodBase.readStatusLine(HttpState, HttpConnection)
DEBUG - GeronimoLog.trace(54) | enter HttpConnection.readLine()
09:46:36,394 DEBUG [HttpConnection] enter HttpConnection.readLine()
DEBUG - GeronimoLog.trace(54) | enter HttpParser.readLine(InputStream,
String)
09:46:36,496 DEBUG [HttpParser] enter HttpParser.readLine(InputStream,
String)
DEBUG - GeronimoLog.trace(54) | enter HttpParser.readRawLine()
09:46:36,506 DEBUG [HttpParser] enter HttpParser.readRawLine()
DEBUG - GeronimoLog.debug(66) | << "HTTP/1.1 500 Internal Server
Error[\r][\n]"
09:46:37,507 DEBUG [header] << "HTTP/1.1 500 Internal Server Error[\r][\n]"
DEBUG - GeronimoLog.trace(54) | enter
HttpMethodBase.readResponseHeaders(HttpState,HttpConnection)
09:46:37,517 DEBUG [HttpMethodBase] enter
HttpMethodBase.readResponseHeaders(HttpState,HttpConnection)
DEBUG - GeronimoLog.trace(54) | enter
HttpConnection.getResponseInputStream()
09:46:37,527 DEBUG [HttpConnection] enter
HttpConnection.getResponseInputStream()
DEBUG - GeronimoLog.trace(54) | enter HeaderParser.parseHeaders(InputStream,
String)
09:46:37,527 DEBUG [HttpParser] enter HeaderParser.parseHeaders(InputStream,
String)
DEBUG - GeronimoLog.trace(54) | enter HttpParser.readLine(InputStream,
String)
09:46:37,537 DEBUG [HttpParser] enter HttpParser.readLine(InputStream,
String)
DEBUG - GeronimoLog.trace(54) | enter HttpParser.readRawLine()
09:46:37,537 DEBUG [HttpParser] enter HttpParser.readRawLine()
DEBUG - GeronimoLog.trace(54) | enter HttpParser.readLine(InputStream,
String)
09:46:37,537 DEBUG [HttpParser] enter HttpParser.readLine(InputStream,
String)
DEBUG - GeronimoLog.trace(54) | enter HttpParser.readRawLine()
09:46:37,537 DEBUG [HttpParser] enter HttpParser.readRawLine()
DEBUG - GeronimoLog.trace(54) | enter HttpParser.readLine(InputStream,
String)
09:46:37,537 DEBUG [HttpParser] enter HttpParser.readLine(InputStream,
String)
DEBUG - GeronimoLog.trace(54) | enter HttpParser.readRawLine()
09:46:37,537 DEBUG [HttpParser] enter HttpParser.readRawLine()
DEBUG - GeronimoLog.trace(54) | enter HttpParser.readLine(InputStream,
String)
09:46:37,537 DEBUG [HttpParser] enter HttpParser.readLine(InputStream,
String)
DEBUG - GeronimoLog.trace(54) | enter HttpParser.readRawLine()
09:46:37,548 DEBUG [HttpParser] enter HttpParser.readRawLine()
DEBUG - GeronimoLog.trace(54) | enter HttpParser.readLine(InputStream,
String)
09:46:37,548 DEBUG [HttpParser] enter HttpParser.readLine(InputStream,
String)
DEBUG - GeronimoLog.trace(54) | enter HttpParser.readRawLine()
09:46:37,548 DEBUG [HttpParser] enter HttpParser.readRawLine()
DEBUG - GeronimoLog.trace(54) | enter HttpParser.readLine(InputStream,
String)
09:46:37,548 DEBUG [HttpParser] enter HttpParser.readLine(InputStream,
String)
DEBUG - GeronimoLog.trace(54) | enter HttpParser.readRawLine()
09:46:37,548 DEBUG [HttpParser] enter HttpParser.readRawLine()
DEBUG - GeronimoLog.debug(66) | << "Server: Apache-Coyote/1.1[\r][\n]"
09:46:37,548 DEBUG [header] << "Server: Apache-Coyote/1.1[\r][\n]"
DEBUG - GeronimoLog.debug(66) | << "Content-Type:
text/xml;charset=utf-8[\r][\n]"
09:46:37,548 DEBUG [header] << "Content-Type:
text/xml;charset=utf-8[\r][\n]"
DEBUG - GeronimoLog.debug(66) | << "Transfer-Encoding: chunked[\r][\n]"
09:46:37,548 DEBUG [header] << "Transfer-Encoding: chunked[\r][\n]"
DEBUG - GeronimoLog.debug(66) | << "Date: Tue, 11 Sep 2007 13:46:37
GMT[\r][\n]"
09:46:37,558 DEBUG [header] << "Date: Tue, 11 Sep 2007 13:46:37 GMT[\r][\n]"
DEBUG - GeronimoLog.debug(66) | << "Connection: close[\r][\n]"
09:46:37,558 DEBUG [header] << "Connection: close[\r][\n]"
DEBUG - GeronimoLog.trace(54) | enter
HttpMethodBase.processResponseHeaders(HttpState, HttpConnection)
09:46:37,558 DEBUG [HttpMethodBase] enter
HttpMethodBase.processResponseHeaders(HttpState, HttpConnection)
DEBUG - GeronimoLog.trace(54) | enter
HttpMethodBase.readResponseBody(HttpState, HttpConnection)
09:46:37,558 DEBUG [HttpMethodBase] enter
HttpMethodBase.readResponseBody(HttpState, HttpConnection)
DEBUG - GeronimoLog.trace(54) | enter
HttpMethodBase.readResponseBody(HttpConnection)
09:46:37,578 DEBUG [HttpMethodBase] enter
HttpMethodBase.readResponseBody(HttpConnection)
DEBUG - GeronimoLog.trace(54) | enter
HttpConnection.getResponseInputStream()
09:46:37,578 DEBUG [HttpConnection] enter
HttpConnection.getResponseInputStream()
DEBUG - GeronimoLog.trace(54) | enter
HttpMethodBase.canResponseHaveBody(int)
09:46:37,578 DEBUG [HttpMethodBase] enter
HttpMethodBase.canResponseHaveBody(int)
DEBUG - GeronimoLog.trace(54) | enter HeaderElement.parseElements(String)
09:46:37,578 DEBUG [HeaderElement] enter HeaderElement.parseElements(String)
DEBUG - GeronimoLog.trace(54) | enter HeaderElement.parseElements(char[])
09:46:37,578 DEBUG [HeaderElement] enter HeaderElement.parseElements(char[])
DEBUG - GeronimoLog.trace(54) | enter
HttpConnection.isResponseAvailable(int)
09:46:37,691 DEBUG [HttpConnection] enter
HttpConnection.isResponseAvailable(int)
DEBUG - GeronimoLog.trace(54) | enter HeaderElement.parseElements(String)
09:46:37,701 DEBUG [HeaderElement] enter HeaderElement.parseElements(String)
DEBUG - GeronimoLog.trace(54) | enter HeaderElement.parseElements(char[])
09:46:37,701 DEBUG [HeaderElement] enter HeaderElement.parseElements(char[])
DEBUG - GeronimoLog.trace(54) | enter
HeaderElement.getParameterByName(String)
09:46:37,701 DEBUG [HeaderElement] enter
HeaderElement.getParameterByName(String)
ERROR - GeronimoLog.error(108) | Error sending message
(mex={PartnerRoleMex#hqejbhcnphr2kvk6gstpxw [PID {http://eclipse.
org/bpel/sample}ECRProcess-9] calling
org.apache.ode.bpel.epr.WSAEndpoint@11dca40.setAttribute(...)}):
java.lang.NullPoi
nterException
org.apache.axis2.AxisFault: java.lang.NullPointerException
at
org.apache.axis2.util.Utils.getInboundFaultFromMessageContext(Utils.java:486)
at
org.apache.axis2.description.OutInAxisOperationClient.handleResponse(OutInAxisOperation.java:343)
at
org.apache.axis2.description.OutInAxisOperationClient.send(OutInAxisOperation.java:389)
at
org.apache.axis2.description.OutInAxisOperationClient.executeImpl(OutInAxisOperation.java:211)
at
org.apache.axis2.client.OperationClient.execute(OperationClient.java:163)
at
org.apache.ode.axis2.ExternalService$1$1.call(ExternalService.java:150)
at
java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:269)
at java.util.concurrent.FutureTask.run(FutureTask.java:123)
at
java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:650)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:675)
at java.lang.Thread.run(Thread.java:595)
09:46:37,772 ERROR [ExternalService] Error sending message
(mex={PartnerRoleMex#hqejbhcnphr2kvk6gstpxw [PID {http://ecli
pse.org/bpel/sample}ECRProcess-9] calling
org.apache.ode.bpel.epr.WSAEndpoint@11dca40.setAttribute(...)}):
java.lang.Nul
lPointerException
org.apache.axis2.AxisFault: java.lang.NullPointerException
at
org.apache.axis2.util.Utils.getInboundFaultFromMessageContext(Utils.java:486)
at
org.apache.axis2.description.OutInAxisOperationClient.handleResponse(OutInAxisOperation.java:343)
at
org.apache.axis2.description.OutInAxisOperationClient.send(OutInAxisOperation.java:389)
at
org.apache.axis2.description.OutInAxisOperationClient.executeImpl(OutInAxisOperation.java:211)
at
org.apache.axis2.client.OperationClient.execute(OperationClient.java:163)
at
org.apache.ode.axis2.ExternalService$1$1.call(ExternalService.java:150)
at
java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:269)
at java.util.concurrent.FutureTask.run(FutureTask.java:123)
at
java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:650)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:675)
at java.lang.Thread.run(Thread.java:595)
DEBUG - GeronimoLog.trace(54) | Mex[hqejbhcnphr2kvk6gstpxw].setPortOp(...)
09:46:37,803 DEBUG [MessageExchangeImpl]
Mex[hqejbhcnphr2kvk6gstpxw].setPortOp(...)
DEBUG - GeronimoLog.debug(66) | replyWithFailure mex=hqejbhcnphr2kvk6gstpxw
failureType=COMMUNICATION_ERROR description=
Error sending message (mex={PartnerRoleMex#hqejbhcnphr2kvk6gstpxw [PID
{http://eclipse.org/bpel/sample}ECRProcess-9] cal
ling org.apache.ode.bpel.epr.WSAEndpoint@11dca40.setAttribute(...)}):
java.lang.NullPointerException details=null
09:46:37,803 DEBUG [PartnerRoleMessageExchangeImpl] replyWithFailure
mex=hqejbhcnphr2kvk6gstpxw failureType=COMMUNICATIO
N_ERROR description=Error sending message
(mex={PartnerRoleMex#hqejbhcnphr2kvk6gstpxw [PID
{http://eclipse.org/bpel/samp
le}ECRProcess-9] calling
org.apache.ode.bpel.epr.WSAEndpoint@11dca40.setAttribute(...)}):
java.lang.NullPointerException
details=null
DEBUG - GeronimoLog.debug(66) | create work event for
mex=hqejbhcnphr2kvk6gstpxw
09:46:37,803 DEBUG [PartnerRoleMessageExchangeImpl] create work event for
mex=hqejbhcnphr2kvk6gstpxw
DEBUG - GeronimoLog.debug(66) | Thread[pool-2-thread-2,5,main]:
lock(iid=1202, time=1MICROSECONDS)
09:46:37,864 DEBUG [InstanceLockManager] Thread[pool-2-thread-2,5,main]:
lock(iid=1202, time=1MICROSECONDS)
DEBUG - GeronimoLog.debug(66) | Thread[pool-2-thread-2,5,main]:
lock(iid=1202, time=1MICROSECONDS)-->GRANTED
09:46:37,864 DEBUG [InstanceLockManager] Thread[pool-2-thread-2,5,main]:
lock(iid=1202, time=1MICROSECONDS)-->GRANTED
DEBUG - GeronimoLog.debug(66) | >>
handleWorkEvent(jobData={type=INVOKE_RESPONSE, mexid=hqejbhcnphr2kvk6gstpxw,
channel=
54, iid=1202})
09:46:37,874 DEBUG [BpelProcess] >>
handleWorkEvent(jobData={type=INVOKE_RESPONSE, mexid=hqejbhcnphr2kvk6gstpxw,
channel
=54, iid=1202})
DEBUG - GeronimoLog.debug(66) | BpelRuntimeContextImpl created for instance
1202. INDEXED STATE={OSequence#45-main::1=[A
CTIVITYGUARD(...)], OInvoke#145-UpdateCBPWorkflow::32=[INVOKE(...)],
OSequence#47-HiddenSequence::6=[SEQUENCE(self=(OSeq
uence#47-HiddenSequence,TerminationChannel#9,ParentScopeChannel#11),
linkframe=org.apache.ode.bpel.runtime.LinkFrame@6c7
d22, remaining=[{OScope 'UpdateCBPWorkflow' id=144}, {OScope
'callbackClient' id=151}])], OSequence#47-HiddenSequence::5
=[ACTIVITYGUARD(...)], {OScope 'Design Change Proposal'
id=46}::4=[SCOPE(...)], {OScope '__PROCESS_SCOPE:ECRProcess' id=
3}::0=[ACTIVE(...)], {OScope 'UpdateCBPWorkflow' id=144}::30=[SCOPE(...)],
{OScope 'UpdateCBPWorkflow' id=144}::30=[ACTI
VE(...)], OInvoke#145-UpdateCBPWorkflow::31=[ACTIVITYGUARD(...)], {OScope
'UpdateCBPWorkflow' id=144}::29=[ACTIVITYGUARD
(...)], {OScope 'Design Change Proposal' id=46}::3=[ACTIVITYGUARD(...)],
{OScope 'Design Change Proposal' id=46}::4=[ACT
IVE(...)], {OScope '__PROCESS_SCOPE:ECRProcess' id=3}::0=[SCOPE(...)],
OSequence#45-main::2=[SEQUENCE(self=(OSequence#45
-main,TerminationChannel#3,ParentScopeChannel#5),
linkframe=org.apache.ode.bpel.runtime.LinkFrame@6c7d22, remaining=[{OS
cope 'Design Change Proposal' id=46}])]}
09:46:37,895 DEBUG [BpelRuntimeContextImpl] BpelRuntimeContextImpl created
for instance 1202. INDEXED STATE={OSequence#4
5-main::1=[ACTIVITYGUARD(...)],
OInvoke#145-UpdateCBPWorkflow::32=[INVOKE(...)],
OSequence#47-HiddenSequence::6=[SEQUENC
E(self=(OSequence#47-HiddenSequence,TerminationChannel#9,ParentScopeChannel#11),
linkframe=org.apache.ode.bpel.runtime.L
inkFrame@6c7d22, remaining=[{OScope 'UpdateCBPWorkflow' id=144}, {OScope
'callbackClient' id=151}])], OSequence#47-Hidde
nSequence::5=[ACTIVITYGUARD(...)], {OScope 'Design Change Proposal'
id=46}::4=[SCOPE(...)], {OScope '__PROCESS_SCOPE:ECR
Process' id=3}::0=[ACTIVE(...)], {OScope 'UpdateCBPWorkflow'
id=144}::30=[SCOPE(...)], {OScope 'UpdateCBPWorkflow' id=14
4}::30=[ACTIVE(...)],
OInvoke#145-UpdateCBPWorkflow::31=[ACTIVITYGUARD(...)], {OScope
'UpdateCBPWorkflow' id=144}::29=[A
CTIVITYGUARD(...)], {OScope 'Design Change Proposal'
id=46}::3=[ACTIVITYGUARD(...)], {OScope 'Design Change Proposal' id
=46}::4=[ACTIVE(...)], {OScope '__PROCESS_SCOPE:ECRProcess'
id=3}::0=[SCOPE(...)], OSequence#45-main::2=[SEQUENCE(self=(
OSequence#45-main,TerminationChannel#3,ParentScopeChannel#5),
linkframe=org.apache.ode.bpel.runtime.LinkFrame@6c7d22, re
maining=[{OScope 'Design Change Proposal' id=46}])]}
DEBUG - GeronimoLog.debug(66) | InvokeResponse event for iid 1202
09:46:37,905 DEBUG [BpelProcess] InvokeResponse event for iid 1202
DEBUG - GeronimoLog.debug(66) | Invoking message response for mexid
hqejbhcnphr2kvk6gstpxw and channel 54
09:46:37,905 DEBUG [BpelRuntimeContextImpl] Invoking message response for
mexid hqejbhcnphr2kvk6gstpxw and channel 54
DEBUG - GeronimoLog.debug(66) | Triggering response
09:46:37,905 DEBUG [BpelRuntimeContextImpl] Triggering response
INFO - GeronimoLog.info(79) | ActivityRecovery: Registering activity 31,
failure reason: Error sending message (mex={Par
tnerRoleMex#hqejbhcnphr2kvk6gstpxw [PID
{http://eclipse.org/bpel/sample}ECRProcess-9] calling
org.apache.ode.bpel.epr.WS
AEndpoint@11dca40.setAttribute(...)}): java.lang.NullPointerException on
channel 55
09:46:37,915 INFO [BpelRuntimeContextImpl] ActivityRecovery: Registering
activity 31, failure reason: Error sending mes
sage (mex={PartnerRoleMex#hqejbhcnphr2kvk6gstpxw [PID
{http://eclipse.org/bpel/sample}ECRProcess-9] calling org.apache.o
de.bpel.epr.WSAEndpoint@11dca40.setAttribute(...)}):
java.lang.NullPointerException on channel 55
DEBUG - GeronimoLog.debug(66) | Setting execution state on instance 1202
09:46:38,068 DEBUG [BpelRuntimeContextImpl] Setting execution state on
instance 1202
DEBUG - GeronimoLog.debug(66) | Thread[pool-2-thread-2,5,main]:
unlock(iid=1202)
09:46:38,201 DEBUG [InstanceLockManager] Thread[pool-2-thread-2,5,main]:
unlock(iid=1202)
DEBUG - GeronimoLog.debug(66) | Connection reclaimed by garbage collector,
hostConfig=HostConfiguration[host=http://loca
lhost:8080]
09:47:31,939 DEBUG [MultiThreadedHttpConnectionManager] Connection reclaimed
by garbage collector, hostConfig=HostConfig
uration[host=http://localhost:8080]
DEBUG - GeronimoLog.trace(54) | enter
HttpConnectionManager.ConnectionPool.getHostPool(HostConfiguration)
09:47:40,293 DEBUG [MultiThreadedHttpConnectionManager] enter
HttpConnectionManager.ConnectionPool.getHostPool(HostConfi
guration)
DEBUG - GeronimoLog.trace(54) | enter
HttpConnectionManager.ConnectionPool.getHostPool(HostConfiguration)
09:47:40,303 DEBUG [MultiThreadedHttpConnectionManager] enter
HttpConnectionManager.ConnectionPool.getHostPool(HostConfi
guration)
DEBUG - GeronimoLog.debug(66) | Notifying no-one, there are no waiting
threads
09:47:40,303 DEBUG [MultiThreadedHttpConnectionManager] Notifying no-one,
there are no waiting threads
DEBUG - GeronimoLog.debug(66) | Connection reclaimed by garbage collector,
hostConfig=HostConfiguration[host=http://loca
lhost:8080]
09:47:40,303 DEBUG [MultiThreadedHttpConnectionManager] Connection reclaimed
by garbage collector, hostConfig=HostConfig
uration[host=http://localhost:8080]
DEBUG - GeronimoLog.trace(54) | enter
HttpConnectionManager.ConnectionPool.getHostPool(HostConfiguration)
09:47:40,303 DEBUG [MultiThreadedHttpConnectionManager] enter
HttpConnectionManager.ConnectionPool.getHostPool(HostConfi
guration)
DEBUG - GeronimoLog.trace(54) | enter
HttpConnectionManager.ConnectionPool.getHostPool(HostConfiguration)
09:47:40,314 DEBUG [MultiThreadedHttpConnectionManager] enter
HttpConnectionManager.ConnectionPool.getHostPool(HostConfi
Anup
Alex Boisvert wrote:
>
> You're most likely getting some sort of failure from the service you're
> invoking, and Axis2 has a hard time parsing the resulting fault message.
> I
> would recommend setting the "httpclient" log category to DEBUG to see
> what's
> going on the wire.
>
> alex
>
>
> On 9/10/07, Anup Chandran <an...@3ds.com> wrote:
>>
>>
>> Alex/Matthieu,
>>
>> I know this is pretty silly but cant figure what is the issue here......
>> I
>> have a runtime error with the following trace..... If i remove the
>> invoke.
>> from BPEL.. the process runs without errors. Can you tell me what is
>> going
>> on from the trace? Thanks...
>>
>> DEBUG - GeronimoLog.debug(66) | InvokeResponse event for iid 1057
>> 17:40:22,965 DEBUG [BpelProcess] InvokeResponse event for iid 1057
>> DEBUG - GeronimoLog.debug(66) | Invoking message response for mexid
>> hqejbhcnphr2kte2v4jbl5 and channel 40
>> 17:40:22,965 DEBUG [BpelRuntimeContextImpl] Invoking message response for
>> mexid hqejbhcnphr2kte2v4jbl5 and channel 40
>> DEBUG - GeronimoLog.debug(66) | Triggering response
>> 17:40:22,965 DEBUG [BpelRuntimeContextImpl] Triggering response
>> DEBUG - GeronimoLog.trace(54) | >>
>> createScopeInstance(parentScopeId=1059,scope={OScope 'UpdateCBPWorkflow'
>> id=144})
>> 17:40:23,255 DEBUG [BpelProcess] >>
>> createScopeInstance(parentScopeId=1059,scope={OScope 'UpdateCBPWorkflow'
>> id=144})
>> DEBUG - GeronimoLog.trace(54) | >>
>> initializeEndpointReferences(parentScopeId=1125,partnerLinks=[])
>> 17:40:23,506 DEBUG [BpelProcess] >>
>> initializeEndpointReferences(parentScopeId=1125,partnerLinks=[])
>> DEBUG - GeronimoLog.debug(66) | INVOKING PARTNER:
>> partnerLink={PartnerLinkInstance partnerLinkDecl=OPartnerLink#44,scope
>> InstanceId=1058}, op=setAttribute channel=InvokeResponseChannel#54)
>> 17:40:23,526 DEBUG [BpelProcess] INVOKING PARTNER:
>> partnerLink={PartnerLinkInstance partnerLinkDecl=OPartnerLink#44,scop
>> eInstanceId=1058}, op=setAttribute channel=InvokeResponseChannel#54)
>> DEBUG - GeronimoLog.debug(66) | INVOKE PARTNER (SEP): sessionId=null
>> partnerSessionId=null
>> 17:40:23,526 DEBUG [BpelRuntimeContextImpl] INVOKE PARTNER (SEP):
>> sessionId=null partnerSessionId=null
>> DEBUG - GeronimoLog.trace(54) |
>> Mex[hqejbhcnphr2kte2v4jbl8].setPortOp(...)
>> 17:40:23,526 DEBUG [MessageExchangeImpl]
>> Mex[hqejbhcnphr2kte2v4jbl8].setPortOp(...)
>> DEBUG - GeronimoLog.debug(66) | Routed: svcQname
>> {http://client.engineering.cbp.jpo}CBPWorkflowService --> null
>> 17:40:23,526 DEBUG [BpelEngineImpl] Routed: svcQname
>> {http://client.engineering.cbp.jpo}CBPWorkflowService --> null
>> DEBUG - GeronimoLog.debug(66) | Invoking a partner operation:
>> setAttribute
>> 17:40:23,526 DEBUG [MessageExchangeContextImpl] Invoking a partner
>> operation: setAttribute
>> DEBUG - GeronimoLog.debug(66) | The service to invoke is the external
>> service org.apache.ode.axis2.ExternalService@1858f
>> 02
>> 17:40:23,536 DEBUG [MessageExchangeContextImpl] The service to invoke is
>> the
>> external service org.apache.ode.axis2.Exter
>> nalService@1858f02
>> DEBUG - GeronimoLog.debug(66) | Resolving endpoint reference <?xml
>> version="1.0" encoding="UTF-8"?>
>> <service-ref
>> xmlns="http://docs.oasis-open.org/wsbpel/2.0/serviceref
>> "><EndpointReference
>> xmlns="http://www.w3.org/2005/0
>> 8/addressing"><Metadata><ServiceName
>> xmlns="http://www.w3.org/2006/05/addressing/wsdl"
>> EndpointName="JpoCbpEngineeringCB
>> PWorkflow"
>> xmlns:servicens="http://client.engineering.cbp.jpo
>> ">servicens:CBPWorkflowService</ServiceName></Metadata><Add
>> ress>http://localhost:8080/ematrix/services/JpoCbpEngineeringCBPWorkflow
>> </Address></EndpointReference></service-ref>
>> 17:40:23,536 DEBUG [EndpointReferenceContextImpl] Resolving endpoint
>> reference <?xml version="1.0" encoding="UTF-8"?>
>> <service-ref
>> xmlns="http://docs.oasis-open.org/wsbpel/2.0/serviceref
>> "><EndpointReference
>> xmlns="http://www.w3.org/2005/0
>> 8/addressing"><Metadata><ServiceName
>> xmlns="http://www.w3.org/2006/05/addressing/wsdl"
>> EndpointName="JpoCbpEngineeringCB
>> PWorkflow"
>> xmlns:servicens="http://client.engineering.cbp.jpo
>> ">servicens:CBPWorkflowService</ServiceName></Metadata><Add
>> ress>http://localhost:8080/ematrix/services/JpoCbpEngineeringCBPWorkflow
>> </Address></EndpointReference></service-ref>
>> DEBUG - GeronimoLog.debug(66) | GET MEX property
>> org.apache.ode.bpel.partnerRoleSessionId = null
>> 17:40:23,536 DEBUG [MessageExchangeImpl] GET MEX property
>> org.apache.ode.bpel.partnerRoleSessionId = null
>> DEBUG - GeronimoLog.debug(66) | GET MEX property
>> org.apache.ode.bpel.myRoleSessionId = null
>> 17:40:23,536 DEBUG [MessageExchangeImpl] GET MEX property
>> org.apache.ode.bpel.myRoleSessionId = null
>> DEBUG - GeronimoLog.debug(66) | My-Role EPR not specified, SEP will not
>> be
>> used.
>> 17:40:23,536 DEBUG [ExternalService] My-Role EPR not specified, SEP will
>> not
>> be used.
>> DEBUG - GeronimoLog.debug(66) | Axis2 sending message to
>> http://localhost:8080/ematrix/services/JpoCbpEngineeringCBPWork
>> flow using MEX {PartnerRoleMex#hqejbhcnphr2kte2v4jbl8 [PID
>> {http://eclipse.org/bpel/sample}ECRProcess-9] calling org.apa
>> che.ode.bpel.epr.WSAEndpoint@16fd757.setAttribute(...)}
>> 17:40:23,536 DEBUG [ExternalService] Axis2 sending message to
>> http://localhost:8080/ematrix/services/JpoCbpEngineeringCB
>> PWorkflow using MEX {PartnerRoleMex#hqejbhcnphr2kte2v4jbl8 [PID
>> {http://eclipse.org/bpel/sample}ECRProcess-9] calling or
>> g.apache.ode.bpel.epr.WSAEndpoint@16fd757.setAttribute(...)}
>> DEBUG - GeronimoLog.debug(66) | Message: <?xml version='1.0'
>> encoding='utf-8'?><soapenv:Envelope xmlns:soapenv="http://s
>> chemas.xmlsoap.org/soap/envelope/"><soapenv:Body><axis2ns16:setAttribute
>> xmlns:axis2ns16="http://engineering.cbp.jpo" xm
>> lns:tns1="http://engineering.cbp.jpo">
>> <axis2ns16:in2
>> xmlns:ns="http://www.apache.org/ode/pmapi/types/2006/08/02/"
>> xmlns="http://www.apache.
>> org/ode/pmapi/types/2006/08/02/">1057</axis2ns16:in2>
>>
>>
>> </axis2ns16:setAttribute></soapenv:Body></soapenv:Envelope>
>> 17:40:23,536 DEBUG [ExternalService] Message: <?xml version='1.0'
>> encoding='utf-8'?><soapenv:Envelope xmlns:soapenv="htt
>>
>> p://schemas.xmlsoap.org/soap/envelope/"><soapenv:Body><axis2ns16:setAttribute
>> xmlns:axis2ns16="http://engineering.cbp.jp
>> o" xmlns:tns1="http://engineering.cbp.jpo">
>> <axis2ns16:in2
>> xmlns:ns="http://www.apache.org/ode/pmapi/types/2006/08/02/"
>> xmlns="http://www.apache.
>> org/ode/pmapi/types/2006/08/02/">1057</axis2ns16:in2>
>>
>>
>> </axis2ns16:setAttribute></soapenv:Body></soapenv:Envelope>
>> DEBUG - GeronimoLog.debug(66) | replyAsync mex=hqejbhcnphr2kte2v4jbl8
>> 17:40:23,536 DEBUG [PartnerRoleMessageExchangeImpl] replyAsync
>> mex=hqejbhcnphr2kte2v4jbl8
>> DEBUG - GeronimoLog.debug(66) | Setting execution state on instance 1057
>> 17:40:23,546 DEBUG [BpelRuntimeContextImpl] Setting execution state on
>> instance 1057
>> DEBUG - GeronimoLog.debug(66) | Thread[pool-2-thread-9,5,main]:
>> unlock(iid=1057)
>> 17:40:23,707 DEBUG [InstanceLockManager] Thread[pool-2-thread-9,5,main]:
>> unlock(iid=1057)
>> DEBUG - GeronimoLog.debug(66) | Sending stateful TO epr in message header
>> using session null
>> 17:40:23,717 DEBUG [SessionOutHandler] Sending stateful TO epr in message
>> header using session null
>> DEBUG - GeronimoLog.debug(66) | Sending a message containing wsa
>> endpoints
>> in headers for session passing.
>> 17:40:23,717 DEBUG [SessionOutHandler] Sending a message containing wsa
>> endpoints in headers for session passing.
>> DEBUG - GeronimoLog.debug(66) | <?xml version='1.0'
>> encoding='utf-8'?><soapenv:Envelope xmlns:soapenv="http://schemas.xm
>> lsoap.org/soap/envelope/"><soapenv:Header><addr:To
>> xmlns:addr="http://www.w3.org/2005/08/addressing">http://localhost:80
>> 80/ematrix/services/JpoCbpEngineeringCBPWorkflow</addr:To><addr:Action
>> xmlns:addr="http://www.w3.org/2005/08/addressing"
>> ></addr:Action><addr:ReplyTo
>> xmlns:addr="http://www.w3.org/2005/08/addressing"><addr:Address>
>> http://www.w3.org/2005/08/a
>> ddressing/anonymous</addr:Address></addr:ReplyTo><addr:MessageID
>> xmlns:addr="http://www.w3.org/2005/08/addressing">uuid:
>>
>> hqejbhcnphr2kte2v4jbl9</addr:MessageID></soapenv:Header><soapenv:Body><axis2ns16:setAttribute
>> xmlns:axis2ns16="http://en
>> gineering.cbp.jpo" xmlns:tns1="http://engineering.cbp.jpo">
>> <axis2ns16:in2
>> xmlns:ns="http://www.apache.org/ode/pmapi/types/2006/08/02/"
>> xmlns="http://www.apache.
>> org/ode/pmapi/types/2006/08/02/">1057</axis2ns16:in2>
>>
>>
>> </axis2ns16:setAttribute></soapenv:Body></soapenv:Envelope>
>> 17:40:23,717 DEBUG [SessionOutHandler] <?xml version='1.0'
>> encoding='utf-8'?><soapenv:Envelope xmlns:soapenv="http://sch
>> emas.xmlsoap.org/soap/envelope/"><soapenv:Header><addr:To
>> xmlns:addr="http://www.w3.org/2005/08/addressing">http://local
>>
>> host:8080/ematrix/services/JpoCbpEngineeringCBPWorkflow</addr:To><addr:Action
>> xmlns:addr="http://www.w3.org/2005/08/addr
>> essing"></addr:Action><addr:ReplyTo
>> xmlns:addr="http://www.w3.org/2005/08/addressing"><addr:Address>
>> http://www.w3.org/20
>> 05/08/addressing/anonymous</addr:Address></addr:ReplyTo><addr:MessageID
>> xmlns:addr="http://www.w3.org/2005/08/addressing
>>
>> ">uuid:hqejbhcnphr2kte2v4jbl9</addr:MessageID></soapenv:Header><soapenv:Body><axis2ns16:setAttribute
>> xmlns:axis2ns16="ht
>> tp://engineering.cbp.jpo" xmlns:tns1="http://engineering.cbp.jpo">
>> <axis2ns16:in2
>> xmlns:ns="http://www.apache.org/ode/pmapi/types/2006/08/02/"
>> xmlns="http://www.apache.
>> org/ode/pmapi/types/2006/08/02/">1057</axis2ns16:in2>
>>
>>
>> </axis2ns16:setAttribute></soapenv:Body></soapenv:Envelope>
>> ERROR - GeronimoLog.error(108) | Error sending message
>> (mex={PartnerRoleMex#hqejbhcnphr2kte2v4jbl8 [PID {http://eclipse.
>> org/bpel/sample}ECRProcess-9] calling
>> org.apache.ode.bpel.epr.WSAEndpoint@16fd757.setAttribute(...)}):
>> java.lang.NullPoi
>> nterException
>> org.apache.axis2.AxisFault: java.lang.NullPointerException
>> at
>> org.apache.axis2.util.Utils.getInboundFaultFromMessageContext(Utils.java
>> :486)
>> at
>> org.apache.axis2.description.OutInAxisOperationClient.handleResponse(
>> OutInAxisOperation.java:343)
>> at
>> org.apache.axis2.description.OutInAxisOperationClient.send(
>> OutInAxisOperation.java:389)
>> at
>> org.apache.axis2.description.OutInAxisOperationClient.executeImpl(
>> OutInAxisOperation.java:211)
>> at
>> org.apache.axis2.client.OperationClient.execute(OperationClient.java:163)
>> at
>> org.apache.ode.axis2.ExternalService$1$1.call(ExternalService.java:150)
>> at
>> java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:269)
>> at java.util.concurrent.FutureTask.run(FutureTask.java:123)
>> at
>> java.util.concurrent.ThreadPoolExecutor$Worker.runTask(
>> ThreadPoolExecutor.java:650)
>> at
>> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java
>> :675)
>> at java.lang.Thread.run(Thread.java:595)
>> 17:40:23,737 ERROR [ExternalService] Error sending message
>> (mex={PartnerRoleMex#hqejbhcnphr2kte2v4jbl8 [PID {http://ecli
>> pse.org/bpel/sample}ECRProcess-9] calling
>> org.apache.ode.bpel.epr.WSAEndpoint@16fd757.setAttribute(...)}):
>> java.lang.Nul
>> lPointerException
>> org.apache.axis2.AxisFault: java.lang.NullPointerException
>> at
>> org.apache.axis2.util.Utils.getInboundFaultFromMessageContext(Utils.java
>> :486)
>> at
>> org.apache.axis2.description.OutInAxisOperationClient.handleResponse(
>> OutInAxisOperation.java:343)
>> at
>> org.apache.axis2.description.OutInAxisOperationClient.send(
>> OutInAxisOperation.java:389)
>> at
>> org.apache.axis2.description.OutInAxisOperationClient.executeImpl(
>> OutInAxisOperation.java:211)
>> at
>> org.apache.axis2.client.OperationClient.execute(OperationClient.java:163)
>> at
>> org.apache.ode.axis2.ExternalService$1$1.call(ExternalService.java:150)
>> at
>> java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:269)
>> at java.util.concurrent.FutureTask.run(FutureTask.java:123)
>> at
>> java.util.concurrent.ThreadPoolExecutor$Worker.runTask(
>> ThreadPoolExecutor.java:650)
>> at
>> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java
>> :675)
>> at java.lang.Thread.run(Thread.java:595)
>> DEBUG - GeronimoLog.trace(54) |
>> Mex[hqejbhcnphr2kte2v4jbl8].setPortOp(...)
>> 17:40:23,747 DEBUG [MessageExchangeImpl]
>> Mex[hqejbhcnphr2kte2v4jbl8].setPortOp(...)
>> DEBUG - GeronimoLog.debug(66) | replyWithFailure
>> mex=hqejbhcnphr2kte2v4jbl8
>> failureType=COMMUNICATION_ERROR description=
>> Error sending message (mex={PartnerRoleMex#hqejbhcnphr2kte2v4jbl8 [PID
>> {http://eclipse.org/bpel/sample}ECRProcess-9] cal
>> ling org.apache.ode.bpel.epr.WSAEndpoint@16fd757.setAttribute(...)}):
>> java.lang.NullPointerException details=null
>> 17:40:23,747 DEBUG [PartnerRoleMessageExchangeImpl] replyWithFailure
>> mex=hqejbhcnphr2kte2v4jbl8 failureType=COMMUNICATIO
>> N_ERROR description=Error sending message
>> (mex={PartnerRoleMex#hqejbhcnphr2kte2v4jbl8 [PID
>> {http://eclipse.org/bpel/samp
>> le}ECRProcess-9] calling
>> org.apache.ode.bpel.epr.WSAEndpoint@16fd757.setAttribute(...)}):
>> java.lang.NullPointerException
>> details=null
>> DEBUG - GeronimoLog.debug(66) | create work event for
>> mex=hqejbhcnphr2kte2v4jbl8
>> 17:40:23,747 DEBUG [PartnerRoleMessageExchangeImpl] create work event for
>> mex=hqejbhcnphr2kte2v4jbl8
>> DEBUG - GeronimoLog.debug(66) | Thread[pool-2-thread-9,5,main]:
>> lock(iid=1057, time=1MICROSECONDS)
>> 17:40:23,757 DEBUG [InstanceLockManager] Thread[pool-2-thread-9,5,main]:
>> lock(iid=1057, time=1MICROSECONDS)
>> DEBUG - GeronimoLog.debug(66) | Thread[pool-2-thread-9,5,main]:
>> lock(iid=1057, time=1MICROSECONDS)-->GRANTED
>> 17:40:23,757 DEBUG [InstanceLockManager] Thread[pool-2-thread-9,5,main]:
>> lock(iid=1057, time=1MICROSECONDS)-->GRANTED
>> DEBUG - GeronimoLog.debug(66) | >>
>> handleWorkEvent(jobData={type=INVOKE_RESPONSE,
>> mexid=hqejbhcnphr2kte2v4jbl8,
>> channel=
>> 54, iid=1057})
>> 17:40:23,757 DEBUG [BpelProcess] >>
>> handleWorkEvent(jobData={type=INVOKE_RESPONSE,
>> mexid=hqejbhcnphr2kte2v4jbl8,
>> channel
>> =54, iid=1057})
>> DEBUG - GeronimoLog.debug(66) | BpelRuntimeContextImpl created for
>> instance
>> 1057. INDEXED STATE={{OScope 'Design Change
>> Proposal' id=46}::4=[ACTIVE(...)], {OScope 'Design Change Proposal'
>> id=46}::4=[SCOPE(...)], {OScope 'UpdateCBPWorkflow'
>> id=144}::29=[ACTIVITYGUARD(...)],
>>
>> OSequence#47-HiddenSequence::6=[SEQUENCE(self=(OSequence#47-HiddenSequence,Termination
>> Channel#9,ParentScopeChannel#11),
>> linkframe=org.apache.ode.bpel.runtime.LinkFrame@1c90d2c,
>> remaining=[{OScope
>> 'UpdateCBP
>> Workflow' id=144}, {OScope 'callbackClient' id=151}])],
>> OSequence#45-main::2=[SEQUENCE(self=(OSequence#45-main,Terminati
>> onChannel#3,ParentScopeChannel#5),
>> linkframe=org.apache.ode.bpel.runtime.LinkFrame@1c90d2c,
>> remaining=[{OScope
>> 'Design C
>> hange Proposal' id=46}])], {OScope 'UpdateCBPWorkflow'
>> id=144}::30=[ACTIVE(...)], OInvoke#145-UpdateCBPWorkflow::31=[ACT
>> IVITYGUARD(...)], {OScope 'UpdateCBPWorkflow' id=144}::30=[SCOPE(...)],
>> {OScope '__PROCESS_SCOPE:ECRProcess' id=3}::0=[S
>> COPE(...)], {OScope '__PROCESS_SCOPE:ECRProcess' id=3}::0=[ACTIVE(...)],
>> OSequence#47-HiddenSequence::5=[ACTIVITYGUARD(.
>> ..)], OSequence#45-main::1=[ACTIVITYGUARD(...)],
>> OInvoke#145-UpdateCBPWorkflow::32=[INVOKE(...)], {OScope 'Design Change
>> Proposal' id=46}::3=[ACTIVITYGUARD(...)]}
>> 17:40:23,777 DEBUG [BpelRuntimeContextImpl] BpelRuntimeContextImpl
>> created
>> for instance 1057. INDEXED STATE={{OScope 'De
>> sign Change Proposal' id=46}::4=[ACTIVE(...)], {OScope 'Design Change
>> Proposal' id=46}::4=[SCOPE(...)], {OScope 'UpdateC
>> BPWorkflow' id=144}::29=[ACTIVITYGUARD(...)],
>> OSequence#47-HiddenSequence::6=[SEQUENCE(self=(OSequence#47-HiddenSequence
>> ,TerminationChannel#9,ParentScopeChannel#11),
>> linkframe=org.apache.ode.bpel.runtime.LinkFrame@1c90d2c,
>> remaining=[{OScop
>> e 'UpdateCBPWorkflow' id=144}, {OScope 'callbackClient' id=151}])],
>> OSequence#45-main::2=[SEQUENCE(self=(OSequence#45-ma
>> in,TerminationChannel#3,ParentScopeChannel#5),
>> linkframe=org.apache.ode.bpel.runtime.LinkFrame@1c90d2c, remaining=[{OSco
>> pe 'Design Change Proposal' id=46}])], {OScope 'UpdateCBPWorkflow'
>> id=144}::30=[ACTIVE(...)], OInvoke#145-UpdateCBPWorkf
>> low::31=[ACTIVITYGUARD(...)], {OScope 'UpdateCBPWorkflow'
>> id=144}::30=[SCOPE(...)], {OScope '__PROCESS_SCOPE:ECRProcess'
>> id=3}::0=[SCOPE(...)], {OScope '__PROCESS_SCOPE:ECRProcess'
>> id=3}::0=[ACTIVE(...)], OSequence#47-HiddenSequence::5=[ACT
>> IVITYGUARD(...)], OSequence#45-main::1=[ACTIVITYGUARD(...)],
>> OInvoke#145-UpdateCBPWorkflow::32=[INVOKE(...)], {OScope 'D
>> esign Change Proposal' id=46}::3=[ACTIVITYGUARD(...)]}
>> DEBUG - GeronimoLog.debug(66) | InvokeResponse event for iid 1057
>> 17:40:23,777 DEBUG [BpelProcess] InvokeResponse event for iid 1057
>> DEBUG - GeronimoLog.debug(66) | Invoking message response for mexid
>> hqejbhcnphr2kte2v4jbl8 and channel 54
>> --
>> View this message in context:
>> http://www.nabble.com/Invoke---with-communication-error-tf4418802.html#a12603692
>> Sent from the Apache Ode User mailing list archive at Nabble.com.
>>
>>
>
>
--
View this message in context: http://www.nabble.com/Invoke---with-communication-error-tf4418802.html#a12615259
Sent from the Apache Ode User mailing list archive at Nabble.com.
Re: Invoke - with communication error
Posted by Alex Boisvert <bo...@intalio.com>.
You're most likely getting some sort of failure from the service you're
invoking, and Axis2 has a hard time parsing the resulting fault message. I
would recommend setting the "httpclient" log category to DEBUG to see what's
going on the wire.
alex
On 9/10/07, Anup Chandran <an...@3ds.com> wrote:
>
>
> Alex/Matthieu,
>
> I know this is pretty silly but cant figure what is the issue here...... I
> have a runtime error with the following trace..... If i remove the invoke.
> from BPEL.. the process runs without errors. Can you tell me what is going
> on from the trace? Thanks...
>
> DEBUG - GeronimoLog.debug(66) | InvokeResponse event for iid 1057
> 17:40:22,965 DEBUG [BpelProcess] InvokeResponse event for iid 1057
> DEBUG - GeronimoLog.debug(66) | Invoking message response for mexid
> hqejbhcnphr2kte2v4jbl5 and channel 40
> 17:40:22,965 DEBUG [BpelRuntimeContextImpl] Invoking message response for
> mexid hqejbhcnphr2kte2v4jbl5 and channel 40
> DEBUG - GeronimoLog.debug(66) | Triggering response
> 17:40:22,965 DEBUG [BpelRuntimeContextImpl] Triggering response
> DEBUG - GeronimoLog.trace(54) | >>
> createScopeInstance(parentScopeId=1059,scope={OScope 'UpdateCBPWorkflow'
> id=144})
> 17:40:23,255 DEBUG [BpelProcess] >>
> createScopeInstance(parentScopeId=1059,scope={OScope 'UpdateCBPWorkflow'
> id=144})
> DEBUG - GeronimoLog.trace(54) | >>
> initializeEndpointReferences(parentScopeId=1125,partnerLinks=[])
> 17:40:23,506 DEBUG [BpelProcess] >>
> initializeEndpointReferences(parentScopeId=1125,partnerLinks=[])
> DEBUG - GeronimoLog.debug(66) | INVOKING PARTNER:
> partnerLink={PartnerLinkInstance partnerLinkDecl=OPartnerLink#44,scope
> InstanceId=1058}, op=setAttribute channel=InvokeResponseChannel#54)
> 17:40:23,526 DEBUG [BpelProcess] INVOKING PARTNER:
> partnerLink={PartnerLinkInstance partnerLinkDecl=OPartnerLink#44,scop
> eInstanceId=1058}, op=setAttribute channel=InvokeResponseChannel#54)
> DEBUG - GeronimoLog.debug(66) | INVOKE PARTNER (SEP): sessionId=null
> partnerSessionId=null
> 17:40:23,526 DEBUG [BpelRuntimeContextImpl] INVOKE PARTNER (SEP):
> sessionId=null partnerSessionId=null
> DEBUG - GeronimoLog.trace(54) | Mex[hqejbhcnphr2kte2v4jbl8].setPortOp(...)
> 17:40:23,526 DEBUG [MessageExchangeImpl]
> Mex[hqejbhcnphr2kte2v4jbl8].setPortOp(...)
> DEBUG - GeronimoLog.debug(66) | Routed: svcQname
> {http://client.engineering.cbp.jpo}CBPWorkflowService --> null
> 17:40:23,526 DEBUG [BpelEngineImpl] Routed: svcQname
> {http://client.engineering.cbp.jpo}CBPWorkflowService --> null
> DEBUG - GeronimoLog.debug(66) | Invoking a partner operation: setAttribute
> 17:40:23,526 DEBUG [MessageExchangeContextImpl] Invoking a partner
> operation: setAttribute
> DEBUG - GeronimoLog.debug(66) | The service to invoke is the external
> service org.apache.ode.axis2.ExternalService@1858f
> 02
> 17:40:23,536 DEBUG [MessageExchangeContextImpl] The service to invoke is
> the
> external service org.apache.ode.axis2.Exter
> nalService@1858f02
> DEBUG - GeronimoLog.debug(66) | Resolving endpoint reference <?xml
> version="1.0" encoding="UTF-8"?>
> <service-ref
> xmlns="http://docs.oasis-open.org/wsbpel/2.0/serviceref
> "><EndpointReference
> xmlns="http://www.w3.org/2005/0
> 8/addressing"><Metadata><ServiceName
> xmlns="http://www.w3.org/2006/05/addressing/wsdl"
> EndpointName="JpoCbpEngineeringCB
> PWorkflow"
> xmlns:servicens="http://client.engineering.cbp.jpo
> ">servicens:CBPWorkflowService</ServiceName></Metadata><Add
> ress>http://localhost:8080/ematrix/services/JpoCbpEngineeringCBPWorkflow
> </Address></EndpointReference></service-ref>
> 17:40:23,536 DEBUG [EndpointReferenceContextImpl] Resolving endpoint
> reference <?xml version="1.0" encoding="UTF-8"?>
> <service-ref
> xmlns="http://docs.oasis-open.org/wsbpel/2.0/serviceref
> "><EndpointReference
> xmlns="http://www.w3.org/2005/0
> 8/addressing"><Metadata><ServiceName
> xmlns="http://www.w3.org/2006/05/addressing/wsdl"
> EndpointName="JpoCbpEngineeringCB
> PWorkflow"
> xmlns:servicens="http://client.engineering.cbp.jpo
> ">servicens:CBPWorkflowService</ServiceName></Metadata><Add
> ress>http://localhost:8080/ematrix/services/JpoCbpEngineeringCBPWorkflow
> </Address></EndpointReference></service-ref>
> DEBUG - GeronimoLog.debug(66) | GET MEX property
> org.apache.ode.bpel.partnerRoleSessionId = null
> 17:40:23,536 DEBUG [MessageExchangeImpl] GET MEX property
> org.apache.ode.bpel.partnerRoleSessionId = null
> DEBUG - GeronimoLog.debug(66) | GET MEX property
> org.apache.ode.bpel.myRoleSessionId = null
> 17:40:23,536 DEBUG [MessageExchangeImpl] GET MEX property
> org.apache.ode.bpel.myRoleSessionId = null
> DEBUG - GeronimoLog.debug(66) | My-Role EPR not specified, SEP will not be
> used.
> 17:40:23,536 DEBUG [ExternalService] My-Role EPR not specified, SEP will
> not
> be used.
> DEBUG - GeronimoLog.debug(66) | Axis2 sending message to
> http://localhost:8080/ematrix/services/JpoCbpEngineeringCBPWork
> flow using MEX {PartnerRoleMex#hqejbhcnphr2kte2v4jbl8 [PID
> {http://eclipse.org/bpel/sample}ECRProcess-9] calling org.apa
> che.ode.bpel.epr.WSAEndpoint@16fd757.setAttribute(...)}
> 17:40:23,536 DEBUG [ExternalService] Axis2 sending message to
> http://localhost:8080/ematrix/services/JpoCbpEngineeringCB
> PWorkflow using MEX {PartnerRoleMex#hqejbhcnphr2kte2v4jbl8 [PID
> {http://eclipse.org/bpel/sample}ECRProcess-9] calling or
> g.apache.ode.bpel.epr.WSAEndpoint@16fd757.setAttribute(...)}
> DEBUG - GeronimoLog.debug(66) | Message: <?xml version='1.0'
> encoding='utf-8'?><soapenv:Envelope xmlns:soapenv="http://s
> chemas.xmlsoap.org/soap/envelope/"><soapenv:Body><axis2ns16:setAttribute
> xmlns:axis2ns16="http://engineering.cbp.jpo" xm
> lns:tns1="http://engineering.cbp.jpo">
> <axis2ns16:in2
> xmlns:ns="http://www.apache.org/ode/pmapi/types/2006/08/02/"
> xmlns="http://www.apache.
> org/ode/pmapi/types/2006/08/02/">1057</axis2ns16:in2>
>
> </axis2ns16:setAttribute></soapenv:Body></soapenv:Envelope>
> 17:40:23,536 DEBUG [ExternalService] Message: <?xml version='1.0'
> encoding='utf-8'?><soapenv:Envelope xmlns:soapenv="htt
>
> p://schemas.xmlsoap.org/soap/envelope/"><soapenv:Body><axis2ns16:setAttribute
> xmlns:axis2ns16="http://engineering.cbp.jp
> o" xmlns:tns1="http://engineering.cbp.jpo">
> <axis2ns16:in2
> xmlns:ns="http://www.apache.org/ode/pmapi/types/2006/08/02/"
> xmlns="http://www.apache.
> org/ode/pmapi/types/2006/08/02/">1057</axis2ns16:in2>
>
> </axis2ns16:setAttribute></soapenv:Body></soapenv:Envelope>
> DEBUG - GeronimoLog.debug(66) | replyAsync mex=hqejbhcnphr2kte2v4jbl8
> 17:40:23,536 DEBUG [PartnerRoleMessageExchangeImpl] replyAsync
> mex=hqejbhcnphr2kte2v4jbl8
> DEBUG - GeronimoLog.debug(66) | Setting execution state on instance 1057
> 17:40:23,546 DEBUG [BpelRuntimeContextImpl] Setting execution state on
> instance 1057
> DEBUG - GeronimoLog.debug(66) | Thread[pool-2-thread-9,5,main]:
> unlock(iid=1057)
> 17:40:23,707 DEBUG [InstanceLockManager] Thread[pool-2-thread-9,5,main]:
> unlock(iid=1057)
> DEBUG - GeronimoLog.debug(66) | Sending stateful TO epr in message header
> using session null
> 17:40:23,717 DEBUG [SessionOutHandler] Sending stateful TO epr in message
> header using session null
> DEBUG - GeronimoLog.debug(66) | Sending a message containing wsa endpoints
> in headers for session passing.
> 17:40:23,717 DEBUG [SessionOutHandler] Sending a message containing wsa
> endpoints in headers for session passing.
> DEBUG - GeronimoLog.debug(66) | <?xml version='1.0'
> encoding='utf-8'?><soapenv:Envelope xmlns:soapenv="http://schemas.xm
> lsoap.org/soap/envelope/"><soapenv:Header><addr:To
> xmlns:addr="http://www.w3.org/2005/08/addressing">http://localhost:80
> 80/ematrix/services/JpoCbpEngineeringCBPWorkflow</addr:To><addr:Action
> xmlns:addr="http://www.w3.org/2005/08/addressing"
> ></addr:Action><addr:ReplyTo
> xmlns:addr="http://www.w3.org/2005/08/addressing"><addr:Address>
> http://www.w3.org/2005/08/a
> ddressing/anonymous</addr:Address></addr:ReplyTo><addr:MessageID
> xmlns:addr="http://www.w3.org/2005/08/addressing">uuid:
>
> hqejbhcnphr2kte2v4jbl9</addr:MessageID></soapenv:Header><soapenv:Body><axis2ns16:setAttribute
> xmlns:axis2ns16="http://en
> gineering.cbp.jpo" xmlns:tns1="http://engineering.cbp.jpo">
> <axis2ns16:in2
> xmlns:ns="http://www.apache.org/ode/pmapi/types/2006/08/02/"
> xmlns="http://www.apache.
> org/ode/pmapi/types/2006/08/02/">1057</axis2ns16:in2>
>
> </axis2ns16:setAttribute></soapenv:Body></soapenv:Envelope>
> 17:40:23,717 DEBUG [SessionOutHandler] <?xml version='1.0'
> encoding='utf-8'?><soapenv:Envelope xmlns:soapenv="http://sch
> emas.xmlsoap.org/soap/envelope/"><soapenv:Header><addr:To
> xmlns:addr="http://www.w3.org/2005/08/addressing">http://local
>
> host:8080/ematrix/services/JpoCbpEngineeringCBPWorkflow</addr:To><addr:Action
> xmlns:addr="http://www.w3.org/2005/08/addr
> essing"></addr:Action><addr:ReplyTo
> xmlns:addr="http://www.w3.org/2005/08/addressing"><addr:Address>
> http://www.w3.org/20
> 05/08/addressing/anonymous</addr:Address></addr:ReplyTo><addr:MessageID
> xmlns:addr="http://www.w3.org/2005/08/addressing
>
> ">uuid:hqejbhcnphr2kte2v4jbl9</addr:MessageID></soapenv:Header><soapenv:Body><axis2ns16:setAttribute
> xmlns:axis2ns16="ht
> tp://engineering.cbp.jpo" xmlns:tns1="http://engineering.cbp.jpo">
> <axis2ns16:in2
> xmlns:ns="http://www.apache.org/ode/pmapi/types/2006/08/02/"
> xmlns="http://www.apache.
> org/ode/pmapi/types/2006/08/02/">1057</axis2ns16:in2>
>
> </axis2ns16:setAttribute></soapenv:Body></soapenv:Envelope>
> ERROR - GeronimoLog.error(108) | Error sending message
> (mex={PartnerRoleMex#hqejbhcnphr2kte2v4jbl8 [PID {http://eclipse.
> org/bpel/sample}ECRProcess-9] calling
> org.apache.ode.bpel.epr.WSAEndpoint@16fd757.setAttribute(...)}):
> java.lang.NullPoi
> nterException
> org.apache.axis2.AxisFault: java.lang.NullPointerException
> at
> org.apache.axis2.util.Utils.getInboundFaultFromMessageContext(Utils.java
> :486)
> at
> org.apache.axis2.description.OutInAxisOperationClient.handleResponse(
> OutInAxisOperation.java:343)
> at
> org.apache.axis2.description.OutInAxisOperationClient.send(
> OutInAxisOperation.java:389)
> at
> org.apache.axis2.description.OutInAxisOperationClient.executeImpl(
> OutInAxisOperation.java:211)
> at
> org.apache.axis2.client.OperationClient.execute(OperationClient.java:163)
> at
> org.apache.ode.axis2.ExternalService$1$1.call(ExternalService.java:150)
> at
> java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:269)
> at java.util.concurrent.FutureTask.run(FutureTask.java:123)
> at
> java.util.concurrent.ThreadPoolExecutor$Worker.runTask(
> ThreadPoolExecutor.java:650)
> at
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java
> :675)
> at java.lang.Thread.run(Thread.java:595)
> 17:40:23,737 ERROR [ExternalService] Error sending message
> (mex={PartnerRoleMex#hqejbhcnphr2kte2v4jbl8 [PID {http://ecli
> pse.org/bpel/sample}ECRProcess-9] calling
> org.apache.ode.bpel.epr.WSAEndpoint@16fd757.setAttribute(...)}):
> java.lang.Nul
> lPointerException
> org.apache.axis2.AxisFault: java.lang.NullPointerException
> at
> org.apache.axis2.util.Utils.getInboundFaultFromMessageContext(Utils.java
> :486)
> at
> org.apache.axis2.description.OutInAxisOperationClient.handleResponse(
> OutInAxisOperation.java:343)
> at
> org.apache.axis2.description.OutInAxisOperationClient.send(
> OutInAxisOperation.java:389)
> at
> org.apache.axis2.description.OutInAxisOperationClient.executeImpl(
> OutInAxisOperation.java:211)
> at
> org.apache.axis2.client.OperationClient.execute(OperationClient.java:163)
> at
> org.apache.ode.axis2.ExternalService$1$1.call(ExternalService.java:150)
> at
> java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:269)
> at java.util.concurrent.FutureTask.run(FutureTask.java:123)
> at
> java.util.concurrent.ThreadPoolExecutor$Worker.runTask(
> ThreadPoolExecutor.java:650)
> at
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java
> :675)
> at java.lang.Thread.run(Thread.java:595)
> DEBUG - GeronimoLog.trace(54) | Mex[hqejbhcnphr2kte2v4jbl8].setPortOp(...)
> 17:40:23,747 DEBUG [MessageExchangeImpl]
> Mex[hqejbhcnphr2kte2v4jbl8].setPortOp(...)
> DEBUG - GeronimoLog.debug(66) | replyWithFailure
> mex=hqejbhcnphr2kte2v4jbl8
> failureType=COMMUNICATION_ERROR description=
> Error sending message (mex={PartnerRoleMex#hqejbhcnphr2kte2v4jbl8 [PID
> {http://eclipse.org/bpel/sample}ECRProcess-9] cal
> ling org.apache.ode.bpel.epr.WSAEndpoint@16fd757.setAttribute(...)}):
> java.lang.NullPointerException details=null
> 17:40:23,747 DEBUG [PartnerRoleMessageExchangeImpl] replyWithFailure
> mex=hqejbhcnphr2kte2v4jbl8 failureType=COMMUNICATIO
> N_ERROR description=Error sending message
> (mex={PartnerRoleMex#hqejbhcnphr2kte2v4jbl8 [PID
> {http://eclipse.org/bpel/samp
> le}ECRProcess-9] calling
> org.apache.ode.bpel.epr.WSAEndpoint@16fd757.setAttribute(...)}):
> java.lang.NullPointerException
> details=null
> DEBUG - GeronimoLog.debug(66) | create work event for
> mex=hqejbhcnphr2kte2v4jbl8
> 17:40:23,747 DEBUG [PartnerRoleMessageExchangeImpl] create work event for
> mex=hqejbhcnphr2kte2v4jbl8
> DEBUG - GeronimoLog.debug(66) | Thread[pool-2-thread-9,5,main]:
> lock(iid=1057, time=1MICROSECONDS)
> 17:40:23,757 DEBUG [InstanceLockManager] Thread[pool-2-thread-9,5,main]:
> lock(iid=1057, time=1MICROSECONDS)
> DEBUG - GeronimoLog.debug(66) | Thread[pool-2-thread-9,5,main]:
> lock(iid=1057, time=1MICROSECONDS)-->GRANTED
> 17:40:23,757 DEBUG [InstanceLockManager] Thread[pool-2-thread-9,5,main]:
> lock(iid=1057, time=1MICROSECONDS)-->GRANTED
> DEBUG - GeronimoLog.debug(66) | >>
> handleWorkEvent(jobData={type=INVOKE_RESPONSE,
> mexid=hqejbhcnphr2kte2v4jbl8,
> channel=
> 54, iid=1057})
> 17:40:23,757 DEBUG [BpelProcess] >>
> handleWorkEvent(jobData={type=INVOKE_RESPONSE,
> mexid=hqejbhcnphr2kte2v4jbl8,
> channel
> =54, iid=1057})
> DEBUG - GeronimoLog.debug(66) | BpelRuntimeContextImpl created for
> instance
> 1057. INDEXED STATE={{OScope 'Design Change
> Proposal' id=46}::4=[ACTIVE(...)], {OScope 'Design Change Proposal'
> id=46}::4=[SCOPE(...)], {OScope 'UpdateCBPWorkflow'
> id=144}::29=[ACTIVITYGUARD(...)],
>
> OSequence#47-HiddenSequence::6=[SEQUENCE(self=(OSequence#47-HiddenSequence,Termination
> Channel#9,ParentScopeChannel#11),
> linkframe=org.apache.ode.bpel.runtime.LinkFrame@1c90d2c,
> remaining=[{OScope
> 'UpdateCBP
> Workflow' id=144}, {OScope 'callbackClient' id=151}])],
> OSequence#45-main::2=[SEQUENCE(self=(OSequence#45-main,Terminati
> onChannel#3,ParentScopeChannel#5),
> linkframe=org.apache.ode.bpel.runtime.LinkFrame@1c90d2c,
> remaining=[{OScope
> 'Design C
> hange Proposal' id=46}])], {OScope 'UpdateCBPWorkflow'
> id=144}::30=[ACTIVE(...)], OInvoke#145-UpdateCBPWorkflow::31=[ACT
> IVITYGUARD(...)], {OScope 'UpdateCBPWorkflow' id=144}::30=[SCOPE(...)],
> {OScope '__PROCESS_SCOPE:ECRProcess' id=3}::0=[S
> COPE(...)], {OScope '__PROCESS_SCOPE:ECRProcess' id=3}::0=[ACTIVE(...)],
> OSequence#47-HiddenSequence::5=[ACTIVITYGUARD(.
> ..)], OSequence#45-main::1=[ACTIVITYGUARD(...)],
> OInvoke#145-UpdateCBPWorkflow::32=[INVOKE(...)], {OScope 'Design Change
> Proposal' id=46}::3=[ACTIVITYGUARD(...)]}
> 17:40:23,777 DEBUG [BpelRuntimeContextImpl] BpelRuntimeContextImpl created
> for instance 1057. INDEXED STATE={{OScope 'De
> sign Change Proposal' id=46}::4=[ACTIVE(...)], {OScope 'Design Change
> Proposal' id=46}::4=[SCOPE(...)], {OScope 'UpdateC
> BPWorkflow' id=144}::29=[ACTIVITYGUARD(...)],
> OSequence#47-HiddenSequence::6=[SEQUENCE(self=(OSequence#47-HiddenSequence
> ,TerminationChannel#9,ParentScopeChannel#11),
> linkframe=org.apache.ode.bpel.runtime.LinkFrame@1c90d2c, remaining=[{OScop
> e 'UpdateCBPWorkflow' id=144}, {OScope 'callbackClient' id=151}])],
> OSequence#45-main::2=[SEQUENCE(self=(OSequence#45-ma
> in,TerminationChannel#3,ParentScopeChannel#5),
> linkframe=org.apache.ode.bpel.runtime.LinkFrame@1c90d2c, remaining=[{OSco
> pe 'Design Change Proposal' id=46}])], {OScope 'UpdateCBPWorkflow'
> id=144}::30=[ACTIVE(...)], OInvoke#145-UpdateCBPWorkf
> low::31=[ACTIVITYGUARD(...)], {OScope 'UpdateCBPWorkflow'
> id=144}::30=[SCOPE(...)], {OScope '__PROCESS_SCOPE:ECRProcess'
> id=3}::0=[SCOPE(...)], {OScope '__PROCESS_SCOPE:ECRProcess'
> id=3}::0=[ACTIVE(...)], OSequence#47-HiddenSequence::5=[ACT
> IVITYGUARD(...)], OSequence#45-main::1=[ACTIVITYGUARD(...)],
> OInvoke#145-UpdateCBPWorkflow::32=[INVOKE(...)], {OScope 'D
> esign Change Proposal' id=46}::3=[ACTIVITYGUARD(...)]}
> DEBUG - GeronimoLog.debug(66) | InvokeResponse event for iid 1057
> 17:40:23,777 DEBUG [BpelProcess] InvokeResponse event for iid 1057
> DEBUG - GeronimoLog.debug(66) | Invoking message response for mexid
> hqejbhcnphr2kte2v4jbl8 and channel 54
> --
> View this message in context:
> http://www.nabble.com/Invoke---with-communication-error-tf4418802.html#a12603692
> Sent from the Apache Ode User mailing list archive at Nabble.com.
>
>