axis-java-user mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Pär Malmqvist <par_malmqv...@hotmail.com>
Subject analyze of my logfiles
Date Wed, 28 Oct 2009 10:20:35 GMT

Hello!

I have problems with my testclient that run thousands of calls to a service called getDrugByDrugId.
The client sends a different drugId value for each call.
If the drugId in the response object differs from the drugId that was sent in the request something is wrong.
That is unfortunately what has happened here.

When the client has done some thousands of requests something strange happens.

The last request, drugId = 19980123000089, never appears in the log on the server side, but stil the client logs a SOAPMessage it thinks is the reply.
But that SOAPMessage was the reply from the request just before, drugId = 20040607010594.


I really appreciate if I can get help with analyzing my Axis2 log files below.
(The service has a LogHandler added that logs soap messages at the same phases as the SOAPMonitor.)


________________________________________________________________________________________________________________
Environment:
I have a client and a service installed on my Windows XP laptop.
The client uses Axis2 1.5.1 with a generated xmlbeans client stub and running Java 1.5. 
The service uses Axis2 1.5.1 with an adb genenerated skeleton deployed on a Tomcat 6.0.20 running Java 1.6.
________________________________________________________________________________________________________________

Regards.
Pär Malmqvist



CLIENT LOG

**************************************************************************************************************

.
.
.
2009-10-26 16:47:41,916 [main] DEBUG httpclient.wire.content  - >> "158[\r][\n]"
2009-10-26 16:47:41,916 [main] DEBUG httpclient.wire.content  - >> "<?xml version='1.0' encoding='UTF-8'?><soapenv:Envelope xmlns:soapenv="http://schemas.xmlsoap.org/soap/envelope/"><soapenv:Body><main:getDrugByDrugId xmlns:main="http://main.axis2.sil"><main:param0>20040607010594</main:param0><main:param1>false</main:param1><main:param2>-1</main:param2></main:getDrugByDrugId></soapenv:Body></soapenv:Envelope>"
2009-10-26 16:47:41,916 [main] DEBUG httpclient.wire.content  - >> "[\r][\n]"
2009-10-26 16:47:41,916 [main] DEBUG httpclient.wire.content  - >> "0"
2009-10-26 16:47:41,916 [main] DEBUG httpclient.wire.content  - >> "[\r][\n]"
2009-10-26 16:47:41,916 [main] DEBUG httpclient.wire.content  - >> "[\r][\n]"
2009-10-26 16:47:41,916 [main] DEBUG org.apache.commons.httpclient.methods.EntityEnclosingMethod  - Request body sent
2009-10-26 16:47:41,916 [main] TRACE org.apache.commons.httpclient.HttpConnection  - enter HttpConnection.flushRequestOutputStream()
2009-10-26 16:47:41,916 [main] TRACE org.apache.commons.httpclient.HttpMethodBase  - enter HttpMethodBase.readResponse(HttpState, HttpConnection)
2009-10-26 16:47:41,916 [main] TRACE org.apache.commons.httpclient.HttpMethodBase  - enter HttpMethodBase.readStatusLine(HttpState, HttpConnection)
2009-10-26 16:47:41,916 [main] TRACE org.apache.commons.httpclient.HttpConnection  - enter HttpConnection.readLine()
2009-10-26 16:47:41,916 [main] TRACE org.apache.commons.httpclient.HttpParser  - enter HttpParser.readLine(InputStream, String)
2009-10-26 16:47:41,916 [main] TRACE org.apache.commons.httpclient.HttpParser  - enter HttpParser.readRawLine()
2009-10-26 16:48:02,806 [main] DEBUG httpclient.wire.header  - << "HTTP/1.1 200 OK[\r][\n]"
2009-10-26 16:48:02,806 [main] DEBUG httpclient.wire.header  - << "HTTP/1.1 200 OK[\r][\n]"
2009-10-26 16:48:02,806 [main] TRACE org.apache.commons.httpclient.HttpMethodBase  - enter HttpMethodBase.readResponseHeaders(HttpState,HttpConnection)
2009-10-26 16:48:02,806 [main] TRACE org.apache.commons.httpclient.HttpConnection  - enter HttpConnection.getResponseInputStream()
2009-10-26 16:48:02,806 [main] TRACE org.apache.commons.httpclient.HttpParser  - enter HeaderParser.parseHeaders(InputStream, String)
2009-10-26 16:48:02,806 [main] TRACE org.apache.commons.httpclient.HttpParser  - enter HttpParser.readLine(InputStream, String)
2009-10-26 16:48:02,806 [main] TRACE org.apache.commons.httpclient.HttpParser  - enter HttpParser.readRawLine()
2009-10-26 16:48:02,806 [main] DEBUG httpclient.wire.header  - << "Server: Apache-Coyote/1.1[\r][\n]"
2009-10-26 16:48:02,806 [main] TRACE org.apache.commons.httpclient.HttpParser  - enter HttpParser.readLine(InputStream, String)
2009-10-26 16:48:02,806 [main] TRACE org.apache.commons.httpclient.HttpParser  - enter HttpParser.readRawLine()
2009-10-26 16:48:02,806 [main] DEBUG httpclient.wire.header  - << "Content-Type: text/xml;charset=UTF-8[\r][\n]"
2009-10-26 16:48:02,806 [main] TRACE org.apache.commons.httpclient.HttpParser  - enter HttpParser.readLine(InputStream, String)
2009-10-26 16:48:02,806 [main] TRACE org.apache.commons.httpclient.HttpParser  - enter HttpParser.readRawLine()
2009-10-26 16:48:02,806 [main] DEBUG httpclient.wire.header  - << "Transfer-Encoding: chunked[\r][\n]"
2009-10-26 16:48:02,806 [main] TRACE org.apache.commons.httpclient.HttpParser  - enter HttpParser.readLine(InputStream, String)
2009-10-26 16:48:02,806 [main] TRACE org.apache.commons.httpclient.HttpParser  - enter HttpParser.readRawLine()
2009-10-26 16:48:02,806 [main] DEBUG httpclient.wire.header  - << "Date: Mon, 26 Oct 2009 15:47:41 GMT[\r][\n]"
2009-10-26 16:48:02,806 [main] TRACE org.apache.commons.httpclient.HttpParser  - enter HttpParser.readLine(InputStream, String)
2009-10-26 16:48:02,806 [main] TRACE org.apache.commons.httpclient.HttpParser  - enter HttpParser.readRawLine()
2009-10-26 16:48:02,806 [main] DEBUG httpclient.wire.header  - << "[\r][\n]"
2009-10-26 16:48:02,806 [main] TRACE org.apache.commons.httpclient.HttpMethodBase  - enter HttpMethodBase.processResponseHeaders(HttpState, HttpConnection)
2009-10-26 16:48:02,806 [main] TRACE org.apache.commons.httpclient.HttpMethodBase  - enter HttpMethodBase.processCookieHeaders(Header[], HttpState, HttpConnection)
2009-10-26 16:48:02,806 [main] TRACE org.apache.commons.httpclient.HttpMethodBase  - enter HttpMethodBase.readResponseBody(HttpState, HttpConnection)
2009-10-26 16:48:02,806 [main] TRACE org.apache.commons.httpclient.HttpMethodBase  - enter HttpMethodBase.readResponseBody(HttpConnection)
2009-10-26 16:48:02,806 [main] TRACE org.apache.commons.httpclient.HttpConnection  - enter HttpConnection.getResponseInputStream()
2009-10-26 16:48:02,806 [main] TRACE org.apache.commons.httpclient.HttpMethodBase  - enter HttpMethodBase.canResponseHaveBody(int)
2009-10-26 16:48:02,806 [main] TRACE org.apache.commons.httpclient.HeaderElement  - enter HeaderElement.parseElements(String)
2009-10-26 16:48:02,806 [main] TRACE org.apache.commons.httpclient.HeaderElement  - enter HeaderElement.parseElements(char[])
2009-10-26 16:48:02,806 [main] TRACE org.apache.commons.httpclient.HttpConnection  - enter HttpConnection.isResponseAvailable(int)
2009-10-26 16:48:02,806 [main] TRACE org.apache.axis2.transport.http.HTTPSender  - Handling response - 200
2009-10-26 16:48:02,806 [main] TRACE org.apache.commons.httpclient.HeaderElement  - enter HeaderElement.parseElements(String)
2009-10-26 16:48:02,806 [main] TRACE org.apache.commons.httpclient.HeaderElement  - enter HeaderElement.parseElements(char[])
2009-10-26 16:48:02,806 [main] TRACE org.apache.commons.httpclient.HeaderElement  - enter HeaderElement.getParameterByName(String)
2009-10-26 16:48:02,806 [main] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:D19A3745E4C2A334441256572102976] Invoking flowComplete() in Phase "Security"
2009-10-26 16:48:02,806 [main] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:D19A3745E4C2A334441256572102976] Invoking flowComplete() in Phase "MessageOut"
2009-10-26 16:48:02,806 [main] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:D19A3745E4C2A334441256572102976] Invoking flowComplete() in Phase "PolicyDetermination"
2009-10-26 16:48:02,806 [main] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:D19A3745E4C2A334441256572102976] Invoking flowComplete() in Phase "RMPhase"
2009-10-26 16:48:02,806 [main] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:D19A3745E4C2A334441256572102976] Invoking flowComplete() in Phase "OperationOutPhase"
2009-10-26 16:48:02,806 [main] DEBUG org.apache.axis2.transport.TransportUtils  - createSOAPEnvelope using Builder (class org.apache.axis2.builder.SOAPBuilder) selected from type (text/xml)
2009-10-26 16:48:02,806 [main] DEBUG httpclient.wire.content  - << "6"
2009-10-26 16:48:02,806 [main] DEBUG httpclient.wire.content  - << "2"
2009-10-26 16:48:02,806 [main] DEBUG httpclient.wire.content  - << "9"
2009-10-26 16:48:02,806 [main] DEBUG httpclient.wire.content  - << "[\r]"
2009-10-26 16:48:02,806 [main] DEBUG httpclient.wire.content  - << "[\n]"
2009-10-26 16:48:02,806 [main] DEBUG httpclient.wire.content  - << "<?xm"
2009-10-26 16:48:02,806 [main] DEBUG org.apache.axis2.builder.BuilderUtil  - char set encoding set from default =UTF-8
2009-10-26 16:48:02,806 [main] DEBUG httpclient.wire.content  - << "l version='1.0' encoding='UTF-8'?><soapenv:Envelope xmlns:soapenv="http://schemas.xmlsoap.org/soap/envelope/"><soapenv:Body><ns1:getDrugByDrugIdResponse xmlns:ns1="http://main.axis2.sil"><ns1:return><ns1:drugId>20040607010594</ns1:drugId><ns1:tradeName>Ramipril Durascan</ns1:tradeName><ns1:strengthNumeric>1.25</ns1:strengthNumeric><ns1:strengthNumericUnit>mg</ns1:strengthNumericUnit><ns1:strengthText>1,25 mg</ns1:strengthText><ns1:drugFormCode>CAPHAR</ns1:drugFormCode><ns1:drugFormTextSv>Kapsel, h[0xc3][0xa5]rd</ns1:drugFormTextSv><ns1:drugClassificationCode>-</ns1:drugClassificationCode><ns1:controlClassCode>0</ns1:controlClassCode><ns1:routeOfAdministrationCodes>-</ns1:routeOfAdministrationCodes><ns1:prescriberCodes>1</ns1:prescriberCodes><ns1:interchangeableFlag>N</ns1:interchangeableFlag><ns1:substanceGroupId>0</ns1:substanceGroupId><ns1:substanceGroupName></ns1:substanceGroupName><ns1:strengthGroupId>0</ns1:strengthGroupId><ns1:strengthGroupName></ns1:strengthGroupName><ns1:pharmaceuticalFormGroupId>0</ns1:pharmaceuticalFormGroupId><ns1:pharmaceuticalFormGroupName></ns1:pharmaceuticalFormGroupName><ns1:lactationGroup>?</ns1:lactationGroup><ns1:pregnancyCategory>?</ns1:pregnancyCategory><ns1:interactionStatus>1</ns1:interactionStatus><ns1:productTypeCode>MEP</ns1:productTypeCode><ns1:prescriptionCode>1</ns1:prescriptionCode><ns1:withdrawalDate>2005-02-28</ns1:withdrawalDate><ns1:hasRecommendedArticle>false</ns1:hasRecommendedArticle><ns1:silDeviationCode></ns1:silDeviationCode></ns1:return></ns1:getDrugByDrugIdResponse></soapenv:Body></soapenv:Envelope>"
2009-10-26 16:48:02,806 [main] DEBUG org.apache.axiom.om.util.StAXUtils  - XMLStreamReader is com.ctc.wstx.sr.ValidatingStreamReader
2009-10-26 16:48:02,806 [main] TRACE org.apache.axiom.om.impl.builder.StAXOMBuilder  - START_ELEMENT: 
2009-10-26 16:48:02,806 [main] TRACE org.apache.axiom.om.impl.builder.StAXOMBuilder  -   QName: {http://schemas.xmlsoap.org/soap/envelope/}Envelope
2009-10-26 16:48:02,806 [main] DEBUG org.apache.axiom.soap.impl.builder.StAXSOAPModelBuilder  - Starting to process SOAP 1.1 message
2009-10-26 16:48:02,806 [main] DEBUG org.apache.axiom.soap.impl.builder.StAXSOAPModelBuilder  - Build the OMElement Envelope by the StaxSOAPModelBuilder
2009-10-26 16:48:02,806 [main] TRACE org.apache.axis2.engine.AxisEngine  - [MessageContext: logID=urn:uuid:D19A3745E4C2A334441256572123882] receive:urn:uuid:D19A3745E4C2A334441256572102975
2009-10-26 16:48:02,806 [main] TRACE org.apache.axiom.om.impl.builder.StAXOMBuilder  - START_ELEMENT: 
2009-10-26 16:48:02,806 [main] TRACE org.apache.axiom.om.impl.builder.StAXOMBuilder  -   QName: {http://schemas.xmlsoap.org/soap/envelope/}Body
2009-10-26 16:48:02,806 [main] DEBUG org.apache.axiom.soap.impl.builder.StAXSOAPModelBuilder  - Build the OMElement Body by the StaxSOAPModelBuilder
2009-10-26 16:48:02,806 [main] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:D19A3745E4C2A334441256572123882] Checking pre-condition for Phase "Transport"
2009-10-26 16:48:02,806 [main] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:D19A3745E4C2A334441256572123882] Invoking phase "Transport"
2009-10-26 16:48:02,806 [main] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:D19A3745E4C2A334441256572123882] Invoking Handler 'RequestURIBasedDispatcher' in Phase 'Transport'
2009-10-26 16:48:02,806 [main] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:D19A3745E4C2A334441256572123882] Invoking Handler 'SOAPActionBasedDispatcher' in Phase 'Transport'
2009-10-26 16:48:02,806 [main] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:D19A3745E4C2A334441256572123882] Checking post-conditions for phase "Transport"
2009-10-26 16:48:02,806 [main] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:D19A3745E4C2A334441256572123882] Checking pre-condition for Phase "Addressing"
2009-10-26 16:48:02,806 [main] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:D19A3745E4C2A334441256572123882] Invoking phase "Addressing"
2009-10-26 16:48:02,806 [main] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:D19A3745E4C2A334441256572123882] Invoking Handler 'AddressingBasedDispatcher' in Phase 'Addressing'
2009-10-26 16:48:02,806 [main] TRACE org.apache.axis2.dispatchers.AddressingBasedDispatcher  - invoke: IS_ADDR_INFO_ALREADY_PROCESSED=null
2009-10-26 16:48:02,806 [main] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:D19A3745E4C2A334441256572123882] Checking post-conditions for phase "Addressing"
2009-10-26 16:48:02,806 [main] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:D19A3745E4C2A334441256572123882] Checking pre-condition for Phase "Security"
2009-10-26 16:48:02,806 [main] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:D19A3745E4C2A334441256572123882] Invoking phase "Security"
2009-10-26 16:48:02,806 [main] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:D19A3745E4C2A334441256572123882] Checking post-conditions for phase "Security"
2009-10-26 16:48:02,806 [main] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:D19A3745E4C2A334441256572123882] Checking pre-condition for Phase "PreDispatch"
2009-10-26 16:48:02,806 [main] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:D19A3745E4C2A334441256572123882] Invoking phase "PreDispatch"
2009-10-26 16:48:02,806 [main] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:D19A3745E4C2A334441256572123882] Checking post-conditions for phase "PreDispatch"
2009-10-26 16:48:02,806 [main] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:D19A3745E4C2A334441256572123882] Checking pre-condition for Phase "Dispatch"
2009-10-26 16:48:02,806 [main] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:D19A3745E4C2A334441256572123882] Invoking phase "Dispatch"
2009-10-26 16:48:02,806 [main] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:D19A3745E4C2A334441256572123882] Invoking Handler 'RequestURIBasedDispatcher' in Phase 'Dispatch'
2009-10-26 16:48:02,806 [main] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:D19A3745E4C2A334441256572123882] Invoking Handler 'SOAPActionBasedDispatcher' in Phase 'Dispatch'
2009-10-26 16:48:02,806 [main] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:D19A3745E4C2A334441256572123882] Invoking Handler 'RequestURIOperationDispatcher' in Phase 'Dispatch'
2009-10-26 16:48:02,806 [main] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:D19A3745E4C2A334441256572123882] Invoking Handler 'SOAPMessageBodyBasedDispatcher' in Phase 'Dispatch'
2009-10-26 16:48:02,806 [main] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:D19A3745E4C2A334441256572123882] Invoking Handler 'HTTPLocationBasedDispatcher' in Phase 'Dispatch'
2009-10-26 16:48:02,806 [main] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:D19A3745E4C2A334441256572123882] Checking post-conditions for phase "Dispatch"
2009-10-26 16:48:02,806 [main] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:D19A3745E4C2A334441256572123882] Checking pre-condition for Phase "RMPhase"
2009-10-26 16:48:02,806 [main] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:D19A3745E4C2A334441256572123882] Invoking phase "RMPhase"
2009-10-26 16:48:02,806 [main] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:D19A3745E4C2A334441256572123882] Checking post-conditions for phase "RMPhase"
2009-10-26 16:48:02,806 [main] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:D19A3745E4C2A334441256572123882] Checking pre-condition for Phase "OperationInPhase"
2009-10-26 16:48:02,806 [main] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:D19A3745E4C2A334441256572123882] Invoking phase "OperationInPhase"
2009-10-26 16:48:02,806 [main] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:D19A3745E4C2A334441256572123882] Checking post-conditions for phase "OperationInPhase"
2009-10-26 16:48:02,806 [main] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:D19A3745E4C2A334441256572123882] Invoking flowComplete() in Phase "OperationInPhase"
2009-10-26 16:48:02,806 [main] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:D19A3745E4C2A334441256572123882] Invoking flowComplete() in Phase "RMPhase"
2009-10-26 16:48:02,806 [main] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:D19A3745E4C2A334441256572123882] Invoking flowComplete() in Phase "Dispatch"
2009-10-26 16:48:02,806 [main] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:D19A3745E4C2A334441256572123882] Invoking flowComplete() for Handler 'HTTPLocationBasedDispatcher' in Phase 'Dispatch'
2009-10-26 16:48:02,806 [main] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:D19A3745E4C2A334441256572123882] Invoking flowComplete() for Handler 'SOAPMessageBodyBasedDispatcher' in Phase 'Dispatch'
2009-10-26 16:48:02,806 [main] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:D19A3745E4C2A334441256572123882] Invoking flowComplete() for Handler 'RequestURIOperationDispatcher' in Phase 'Dispatch'
2009-10-26 16:48:02,806 [main] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:D19A3745E4C2A334441256572123882] Invoking flowComplete() for Handler 'SOAPActionBasedDispatcher' in Phase 'Dispatch'
2009-10-26 16:48:02,806 [main] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:D19A3745E4C2A334441256572123882] Invoking flowComplete() for Handler 'RequestURIBasedDispatcher' in Phase 'Dispatch'
2009-10-26 16:48:02,806 [main] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:D19A3745E4C2A334441256572123882] Invoking flowComplete() in Phase "PreDispatch"
2009-10-26 16:48:02,806 [main] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:D19A3745E4C2A334441256572123882] Invoking flowComplete() in Phase "Security"
2009-10-26 16:48:02,806 [main] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:D19A3745E4C2A334441256572123882] Invoking flowComplete() in Phase "Addressing"
2009-10-26 16:48:02,806 [main] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:D19A3745E4C2A334441256572123882] Invoking flowComplete() for Handler 'AddressingBasedDispatcher' in Phase 'Addressing'
2009-10-26 16:48:02,806 [main] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:D19A3745E4C2A334441256572123882] Invoking flowComplete() in Phase "Transport"
2009-10-26 16:48:02,806 [main] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:D19A3745E4C2A334441256572123882] Invoking flowComplete() for Handler 'SOAPActionBasedDispatcher' in Phase 'Transport'
2009-10-26 16:48:02,806 [main] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:D19A3745E4C2A334441256572123882] Invoking flowComplete() for Handler 'RequestURIBasedDispatcher' in Phase 'Transport'
2009-10-26 16:48:02,806 [main] TRACE org.apache.axiom.om.impl.builder.StAXOMBuilder  - START_ELEMENT: 
2009-10-26 16:48:02,806 [main] TRACE org.apache.axiom.om.impl.builder.StAXOMBuilder  -   QName: {http://main.axis2.sil}getDrugByDrugIdResponse
2009-10-26 16:48:02,806 [main] DEBUG org.apache.axiom.soap.impl.builder.StAXSOAPModelBuilder  - Build the OMElement getDrugByDrugIdResponse by the StaxSOAPModelBuilder
2009-10-26 16:48:02,806 [main] TRACE org.apache.axiom.om.impl.builder.StAXOMBuilder  - START_ELEMENT: 
2009-10-26 16:48:02,806 [main] TRACE org.apache.axiom.om.impl.builder.StAXOMBuilder  -   QName: {http://main.axis2.sil}return
2009-10-26 16:48:02,806 [main] DEBUG org.apache.axiom.soap.impl.builder.StAXSOAPModelBuilder  - Build the OMElement return by the StaxSOAPModelBuilder
2009-10-26 16:48:02,806 [main] DEBUG httpclient.wire.content  - << "[\r]"
2009-10-26 16:48:02,806 [main] DEBUG httpclient.wire.content  - << "[\n]"
2009-10-26 16:48:02,806 [main] DEBUG httpclient.wire.content  - << "0"
2009-10-26 16:48:02,806 [main] DEBUG httpclient.wire.content  - << "[\r]"
2009-10-26 16:48:02,806 [main] DEBUG httpclient.wire.content  - << "[\n]"
2009-10-26 16:48:02,806 [main] TRACE org.apache.commons.httpclient.HttpParser  - enter HeaderParser.parseHeaders(InputStream, String)
2009-10-26 16:48:02,806 [main] TRACE org.apache.commons.httpclient.HttpParser  - enter HttpParser.readLine(InputStream, String)
2009-10-26 16:48:02,806 [main] TRACE org.apache.commons.httpclient.HttpParser  - enter HttpParser.readRawLine()
2009-10-26 16:48:02,806 [main] DEBUG httpclient.wire.content  - << "[\r]"
2009-10-26 16:48:02,806 [main] DEBUG httpclient.wire.content  - << "[\n]"
2009-10-26 16:48:02,806 [main] DEBUG httpclient.wire.header  - << "[\r][\n]"
2009-10-26 16:48:02,806 [main] DEBUG org.apache.commons.httpclient.HttpMethodBase  - Resorting to protocol version default close connection policy
2009-10-26 16:48:02,806 [main] DEBUG org.apache.commons.httpclient.HttpMethodBase  - Should NOT close connection, using HTTP/1.1
2009-10-26 16:48:02,806 [main] TRACE org.apache.commons.httpclient.HttpConnection  - enter HttpConnection.isResponseAvailable()
2009-10-26 16:48:02,806 [main] TRACE org.apache.commons.httpclient.HttpConnection  - enter HttpConnection.releaseConnection()
2009-10-26 16:48:02,806 [main] DEBUG org.apache.commons.httpclient.HttpConnection  - Releasing connection back to connection manager.
2009-10-26 16:48:02,806 [main] TRACE org.apache.commons.httpclient.MultiThreadedHttpConnectionManager  - enter HttpConnectionManager.releaseConnection(HttpConnection)
2009-10-26 16:48:02,806 [main] DEBUG org.apache.commons.httpclient.MultiThreadedHttpConnectionManager  - Freeing connection, hostConfig=HostConfiguration[host=http://192.168.18.18:8080]
2009-10-26 16:48:02,806 [main] TRACE org.apache.commons.httpclient.MultiThreadedHttpConnectionManager  - enter HttpConnectionManager.ConnectionPool.getHostPool(HostConfiguration)
2009-10-26 16:48:02,806 [main] DEBUG org.apache.commons.httpclient.util.IdleConnectionHandler  - Adding connection at: 1256572082806
2009-10-26 16:48:02,806 [main] DEBUG org.apache.commons.httpclient.MultiThreadedHttpConnectionManager  - Notifying no-one, there are no waiting threads
2009-10-26 16:48:02,806 [main] DEBUG org.apache.axis2.description.AxisService  - Get operation for {http://main.axis2.sil}getDrugByDrugId
2009-10-26 16:48:02,806 [main] DEBUG org.apache.axis2.description.AxisService  - Found axis operation:  org.apache.axis2.description.OutInAxisOperation@1bd2664
2009-10-26 16:48:02,806 [main] DEBUG org.apache.axis2.context.ConfigurationContext  - registerOperationContext (false): org.apache.axis2.context.OperationContext@8b61a3 with key: urn:uuid:D19A3745E4C2A334441256572123883
2009-10-26 16:48:02,806 [main] DEBUG org.apache.axis2.description.OutInAxisOperationClient  - Entry: OutInAxisOperationClient::execute, true
2009-10-26 16:48:02,806 [main] DEBUG org.apache.axis2.description.OutInAxisOperationClient  - OutInAxisOperationClient: useAsyncOption null
2009-10-26 16:48:02,806 [main] DEBUG org.apache.axis2.context.ConfigurationContext  - registerOperationContext (false): org.apache.axis2.context.OperationContext@8b61a3 with key: urn:uuid:D19A3745E4C2A334441256572123883
2009-10-26 16:48:02,806 [main] DEBUG org.apache.axis2.context.ConfigurationContext  - msgContext: [MessageContext: logID=urn:uuid:D19A3745E4C2A334441256572123884] action: http://main.axis2.sil/SilDB2/getDrugByDrugIdRequest
2009-10-26 16:48:02,806 [main] TRACE org.apache.axis2.engine.AxisEngine  - [MessageContext: logID=urn:uuid:D19A3745E4C2A334441256572123884] send:urn:uuid:D19A3745E4C2A334441256572123883
2009-10-26 16:48:02,806 [main] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:D19A3745E4C2A334441256572123884] Checking pre-condition for Phase "OperationOutPhase"
2009-10-26 16:48:02,806 [main] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:D19A3745E4C2A334441256572123884] Invoking phase "OperationOutPhase"
2009-10-26 16:48:02,806 [main] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:D19A3745E4C2A334441256572123884] Checking post-conditions for phase "OperationOutPhase"
2009-10-26 16:48:02,806 [main] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:D19A3745E4C2A334441256572123884] Checking pre-condition for Phase "RMPhase"
2009-10-26 16:48:02,806 [main] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:D19A3745E4C2A334441256572123884] Invoking phase "RMPhase"
2009-10-26 16:48:02,806 [main] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:D19A3745E4C2A334441256572123884] Checking post-conditions for phase "RMPhase"
2009-10-26 16:48:02,806 [main] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:D19A3745E4C2A334441256572123884] Checking pre-condition for Phase "PolicyDetermination"
2009-10-26 16:48:02,806 [main] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:D19A3745E4C2A334441256572123884] Invoking phase "PolicyDetermination"
2009-10-26 16:48:02,806 [main] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:D19A3745E4C2A334441256572123884] Checking post-conditions for phase "PolicyDetermination"
2009-10-26 16:48:02,806 [main] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:D19A3745E4C2A334441256572123884] Checking pre-condition for Phase "MessageOut"
2009-10-26 16:48:02,806 [main] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:D19A3745E4C2A334441256572123884] Invoking phase "MessageOut"
2009-10-26 16:48:02,806 [main] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:D19A3745E4C2A334441256572123884] Checking post-conditions for phase "MessageOut"
2009-10-26 16:48:02,806 [main] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:D19A3745E4C2A334441256572123884] Checking pre-condition for Phase "Security"
2009-10-26 16:48:02,806 [main] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:D19A3745E4C2A334441256572123884] Invoking phase "Security"
2009-10-26 16:48:02,822 [main] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:D19A3745E4C2A334441256572123884] Checking post-conditions for phase "Security"
2009-10-26 16:48:02,822 [main] TRACE org.apache.axis2.addressing.EndpointReference  - hasAnonymousAddress: http://192.168.18.18:8080/axis2/services/SilDB2 is Anonymous: false
2009-10-26 16:48:02,822 [main] TRACE org.apache.axis2.addressing.EndpointReference  - hasNoneAddress: http://192.168.18.18:8080/axis2/services/SilDB2 is None: false
2009-10-26 16:48:02,822 [main] DEBUG org.apache.commons.httpclient.params.DefaultHttpParams  - Set parameter http.connection.timeout = 99999999
2009-10-26 16:48:02,822 [main] DEBUG org.apache.commons.httpclient.params.DefaultHttpParams  - Set parameter http.socket.timeout = 99999999
2009-10-26 16:48:02,822 [main] DEBUG org.apache.commons.httpclient.params.DefaultHttpParams  - Set parameter http.socket.timeout = 99999999
2009-10-26 16:48:02,822 [main] TRACE org.apache.axis2.transport.http.HTTPSender  - Thread[main,5,main] PostMethod org.apache.commons.httpclient.methods.PostMethod@b7501b / org.apache.commons.httpclient.HttpClient@a2220f
2009-10-26 16:48:02,822 [main] DEBUG org.apache.axiom.om.OMOutputFormat  - Start getContentType: OMOutputFormat [ mimeBoundary =null rootContentId=null doOptimize=false doingSWA=false isSOAP11=true charSetEncoding=UTF-8 xmlVersion=null contentType=null ignoreXmlDeclaration=false autoCloseWriter=false actionProperty=null optimizedThreshold=0]
2009-10-26 16:48:02,822 [main] DEBUG org.apache.axiom.om.OMOutputFormat  - getContentType= {text/xml}   OMOutputFormat [ mimeBoundary =null rootContentId=null doOptimize=false doingSWA=false isSOAP11=true charSetEncoding=UTF-8 xmlVersion=null contentType=text/xml ignoreXmlDeclaration=false autoCloseWriter=false actionProperty=null optimizedThreshold=0]
2009-10-26 16:48:02,822 [main] DEBUG org.apache.axis2.transport.http.SOAPMessageFormatter  - contentType from the OMOutputFormat =text/xml
2009-10-26 16:48:02,822 [main] DEBUG org.apache.axis2.transport.http.SOAPMessageFormatter  - contentType returned =text/xml; charset=UTF-8
2009-10-26 16:48:02,822 [main] TRACE org.apache.commons.httpclient.methods.PostMethod  - enter PostMethod.clearRequestBody()
2009-10-26 16:48:02,822 [main] TRACE org.apache.commons.httpclient.methods.EntityEnclosingMethod  - enter EntityEnclosingMethod.clearRequestBody()
2009-10-26 16:48:02,822 [main] TRACE org.apache.commons.httpclient.HttpClient  - enter HttpClient.executeMethod(HostConfiguration,HttpMethod)
2009-10-26 16:48:02,822 [main] TRACE org.apache.commons.httpclient.HttpClient  - enter HttpClient.executeMethod(HostConfiguration,HttpMethod,HttpState)
2009-10-26 16:48:02,822 [main] TRACE org.apache.commons.httpclient.MultiThreadedHttpConnectionManager  - enter HttpConnectionManager.getConnectionWithTimeout(HostConfiguration, long)
2009-10-26 16:48:02,822 [main] DEBUG org.apache.commons.httpclient.MultiThreadedHttpConnectionManager  - HttpConnectionManager.getConnection:  config = HostConfiguration[host=http://192.168.18.18:8080], timeout = 30000
2009-10-26 16:48:02,822 [main] TRACE org.apache.commons.httpclient.MultiThreadedHttpConnectionManager  - enter HttpConnectionManager.ConnectionPool.getHostPool(HostConfiguration)
2009-10-26 16:48:02,822 [main] TRACE org.apache.commons.httpclient.MultiThreadedHttpConnectionManager  - enter HttpConnectionManager.ConnectionPool.getHostPool(HostConfiguration)
2009-10-26 16:48:02,822 [main] DEBUG org.apache.commons.httpclient.MultiThreadedHttpConnectionManager  - Getting free connection, hostConfig=HostConfiguration[host=http://192.168.18.18:8080]
2009-10-26 16:48:02,822 [main] TRACE org.apache.commons.httpclient.HttpMethodDirector  - Attempt number 1 to process request
2009-10-26 16:48:02,822 [main] TRACE org.apache.commons.httpclient.HttpMethodBase  - enter HttpMethodBase.execute(HttpState, HttpConnection)
2009-10-26 16:48:02,822 [main] TRACE org.apache.commons.httpclient.HttpMethodBase  - enter HttpMethodBase.writeRequest(HttpState, HttpConnection)
2009-10-26 16:48:02,822 [main] TRACE org.apache.commons.httpclient.HttpMethodBase  - enter HttpMethodBase.writeRequestLine(HttpState, HttpConnection)
2009-10-26 16:48:02,822 [main] TRACE org.apache.commons.httpclient.HttpMethodBase  - enter HttpMethodBase.generateRequestLine(HttpConnection, String, String, String, String)
2009-10-26 16:48:02,822 [main] DEBUG httpclient.wire.header  - >> "POST /axis2/services/SilDB2 HTTP/1.1[\r][\n]"
2009-10-26 16:48:02,822 [main] TRACE org.apache.commons.httpclient.HttpConnection  - enter HttpConnection.print(String)
2009-10-26 16:48:02,822 [main] TRACE org.apache.commons.httpclient.HttpConnection  - enter HttpConnection.write(byte[])
2009-10-26 16:48:02,822 [main] TRACE org.apache.commons.httpclient.HttpConnection  - enter HttpConnection.write(byte[], int, int)
2009-10-26 16:48:02,822 [main] TRACE org.apache.commons.httpclient.HttpMethodBase  - enter HttpMethodBase.writeRequestHeaders(HttpState,HttpConnection)
2009-10-26 16:48:02,822 [main] TRACE org.apache.commons.httpclient.methods.EntityEnclosingMethod  - enter EntityEnclosingMethod.addRequestHeaders(HttpState, HttpConnection)
2009-10-26 16:48:02,822 [main] TRACE org.apache.commons.httpclient.methods.ExpectContinueMethod  - enter ExpectContinueMethod.addRequestHeaders(HttpState, HttpConnection)
2009-10-26 16:48:02,822 [main] TRACE org.apache.commons.httpclient.HttpMethodBase  - enter HttpMethodBase.addRequestHeaders(HttpState, HttpConnection)
2009-10-26 16:48:02,822 [main] TRACE org.apache.commons.httpclient.HttpMethodBase  - enter HttpMethodBase.addUserAgentRequestHeaders(HttpState, HttpConnection)
2009-10-26 16:48:02,822 [main] TRACE org.apache.commons.httpclient.HttpMethodBase  - enter HttpMethodBase.addHostRequestHeader(HttpState, HttpConnection)
2009-10-26 16:48:02,822 [main] DEBUG org.apache.commons.httpclient.HttpMethodBase  - Adding Host request header
2009-10-26 16:48:02,822 [main] TRACE org.apache.commons.httpclient.HttpMethodBase  - enter HttpMethodBase.addCookieRequestHeader(HttpState, HttpConnection)
2009-10-26 16:48:02,822 [main] TRACE org.apache.commons.httpclient.HttpState  - enter HttpState.getCookies()
2009-10-26 16:48:02,822 [main] TRACE org.apache.commons.httpclient.cookie.CookieSpec  - enter CookieSpecBase.match(String, int, String, boolean, Cookie[])
2009-10-26 16:48:02,822 [main] TRACE org.apache.commons.httpclient.HttpMethodBase  - enter HttpMethodBase.addProxyConnectionHeader(HttpState, HttpConnection)
2009-10-26 16:48:02,822 [main] TRACE org.apache.commons.httpclient.methods.EntityEnclosingMethod  - enter EntityEnclosingMethod.addContentLengthRequestHeader(HttpState, HttpConnection)
2009-10-26 16:48:02,822 [main] TRACE org.apache.commons.httpclient.methods.EntityEnclosingMethod  - enter EntityEnclosingMethod.getRequestContentLength()
2009-10-26 16:48:02,822 [main] TRACE org.apache.commons.httpclient.methods.PostMethod  - enter PostMethod.hasRequestContent()
2009-10-26 16:48:02,822 [main] TRACE org.apache.commons.httpclient.methods.EntityEnclosingMethod  - enter EntityEnclosingMethod.hasRequestContent()
2009-10-26 16:48:02,822 [main] TRACE org.apache.commons.httpclient.HttpMethodBase  - HttpMethodBase.addRequestHeader(Header)
2009-10-26 16:48:02,822 [main] DEBUG httpclient.wire.header  - >> "Content-Type: text/xml; charset=UTF-8[\r][\n]"
2009-10-26 16:48:02,822 [main] TRACE org.apache.commons.httpclient.HttpConnection  - enter HttpConnection.print(String)
2009-10-26 16:48:02,822 [main] TRACE org.apache.commons.httpclient.HttpConnection  - enter HttpConnection.write(byte[])
2009-10-26 16:48:02,822 [main] TRACE org.apache.commons.httpclient.HttpConnection  - enter HttpConnection.write(byte[], int, int)
2009-10-26 16:48:02,822 [main] DEBUG httpclient.wire.header  - >> "SOAPAction: "http://main.axis2.sil/SilDB2/getDrugByDrugIdRequest"[\r][\n]"
2009-10-26 16:48:02,822 [main] TRACE org.apache.commons.httpclient.HttpConnection  - enter HttpConnection.print(String)
2009-10-26 16:48:02,822 [main] TRACE org.apache.commons.httpclient.HttpConnection  - enter HttpConnection.write(byte[])
2009-10-26 16:48:02,822 [main] TRACE org.apache.commons.httpclient.HttpConnection  - enter HttpConnection.write(byte[], int, int)
2009-10-26 16:48:02,822 [main] DEBUG httpclient.wire.header  - >> "User-Agent: Axis2[\r][\n]"
2009-10-26 16:48:02,822 [main] TRACE org.apache.commons.httpclient.HttpConnection  - enter HttpConnection.print(String)
2009-10-26 16:48:02,822 [main] TRACE org.apache.commons.httpclient.HttpConnection  - enter HttpConnection.write(byte[])
2009-10-26 16:48:02,837 [main] TRACE org.apache.commons.httpclient.HttpConnection  - enter HttpConnection.write(byte[], int, int)
2009-10-26 16:48:02,837 [main] DEBUG httpclient.wire.header  - >> "Host: 192.168.18.18:8080[\r][\n]"
2009-10-26 16:48:02,837 [main] TRACE org.apache.commons.httpclient.HttpConnection  - enter HttpConnection.print(String)
2009-10-26 16:48:02,837 [main] TRACE org.apache.commons.httpclient.HttpConnection  - enter HttpConnection.write(byte[])
2009-10-26 16:48:02,837 [main] TRACE org.apache.commons.httpclient.HttpConnection  - enter HttpConnection.write(byte[], int, int)
2009-10-26 16:48:02,837 [main] DEBUG httpclient.wire.header  - >> "Transfer-Encoding: chunked[\r][\n]"
2009-10-26 16:48:02,837 [main] TRACE org.apache.commons.httpclient.HttpConnection  - enter HttpConnection.print(String)
2009-10-26 16:48:02,837 [main] TRACE org.apache.commons.httpclient.HttpConnection  - enter HttpConnection.write(byte[])
2009-10-26 16:48:02,837 [main] TRACE org.apache.commons.httpclient.HttpConnection  - enter HttpConnection.write(byte[], int, int)
2009-10-26 16:48:02,837 [main] TRACE org.apache.commons.httpclient.HttpConnection  - enter HttpConnection.writeLine()
2009-10-26 16:48:02,837 [main] TRACE org.apache.commons.httpclient.HttpConnection  - enter HttpConnection.write(byte[])
2009-10-26 16:48:02,837 [main] TRACE org.apache.commons.httpclient.HttpConnection  - enter HttpConnection.write(byte[], int, int)
2009-10-26 16:48:02,837 [main] DEBUG httpclient.wire.header  - >> "[\r][\n]"
2009-10-26 16:48:02,837 [main] TRACE org.apache.commons.httpclient.methods.EntityEnclosingMethod  - enter EntityEnclosingMethod.writeRequestBody(HttpState, HttpConnection)
2009-10-26 16:48:02,837 [main] TRACE org.apache.commons.httpclient.methods.PostMethod  - enter PostMethod.hasRequestContent()
2009-10-26 16:48:02,837 [main] TRACE org.apache.commons.httpclient.methods.EntityEnclosingMethod  - enter EntityEnclosingMethod.hasRequestContent()
2009-10-26 16:48:02,837 [main] TRACE org.apache.commons.httpclient.methods.EntityEnclosingMethod  - enter EntityEnclosingMethod.getRequestContentLength()
2009-10-26 16:48:02,837 [main] TRACE org.apache.commons.httpclient.methods.PostMethod  - enter PostMethod.hasRequestContent()
2009-10-26 16:48:02,837 [main] TRACE org.apache.commons.httpclient.methods.EntityEnclosingMethod  - enter EntityEnclosingMethod.hasRequestContent()
2009-10-26 16:48:02,837 [main] TRACE org.apache.commons.httpclient.HttpConnection  - enter HttpConnection.getRequestOutputStream()
2009-10-26 16:48:02,837 [main] DEBUG org.apache.axis2.transport.http.SOAPMessageFormatter  - start writeTo()
2009-10-26 16:48:02,837 [main] DEBUG org.apache.axis2.transport.http.SOAPMessageFormatter  -   preserve=false
2009-10-26 16:48:02,837 [main] DEBUG org.apache.axis2.transport.http.SOAPMessageFormatter  -   isOptimized=false
2009-10-26 16:48:02,837 [main] DEBUG org.apache.axis2.transport.http.SOAPMessageFormatter  -   isDoingSWA=false
2009-10-26 16:48:02,837 [main] DEBUG org.apache.axis2.util.Utils  - MTOM optimized Threshold value =0
2009-10-26 16:48:02,837 [main] DEBUG org.apache.axiom.om.impl.MTOMXMLStreamWriter  - OutputStream =class org.apache.commons.httpclient.ChunkedOutputStream
2009-10-26 16:48:02,837 [main] DEBUG org.apache.axiom.om.impl.MTOMXMLStreamWriter  - OMFormat = OMOutputFormat [ mimeBoundary =null rootContentId=null doOptimize=false doingSWA=false isSOAP11=true charSetEncoding=UTF-8 xmlVersion=null contentType=text/xml ignoreXmlDeclaration=false autoCloseWriter=false actionProperty=null optimizedThreshold=0]
2009-10-26 16:48:02,837 [main] TRACE org.apache.axiom.om.impl.MTOMXMLStreamWriter  - Call Stack =DEBUG_FRAME = org.apache.axiom.om.util.CommonUtils.callStackToString(CommonUtils.java:80)
    DEBUG_FRAME = org.apache.axiom.om.impl.MTOMXMLStreamWriter.<init>(MTOMXMLStreamWriter.java:94)
    DEBUG_FRAME = org.apache.axiom.om.impl.llom.OMNodeImpl.serializeAndConsume(OMNodeImpl.java:485)
    DEBUG_FRAME = org.apache.axis2.transport.http.SOAPMessageFormatter.writeTo(SOAPMessageFormatter.java:79)
    DEBUG_FRAME = org.apache.axis2.transport.http.AxisRequestEntity.writeRequest(AxisRequestEntity.java:84)
    DEBUG_FRAME = org.apache.commons.httpclient.methods.EntityEnclosingMethod.writeRequestBody(EntityEnclosingMethod.java:499)
    DEBUG_FRAME = org.apache.commons.httpclient.HttpMethodBase.writeRequest(HttpMethodBase.java:2114)
    DEBUG_FRAME = org.apache.commons.httpclient.HttpMethodBase.execute(HttpMethodBase.java:1096)
    DEBUG_FRAME = org.apache.commons.httpclient.HttpMethodDirector.executeWithRetry(HttpMethodDirector.java:398)
    DEBUG_FRAME = org.apache.commons.httpclient.HttpMethodDirector.executeMethod(HttpMethodDirector.java:171)
    DEBUG_FRAME = org.apache.commons.httpclient.HttpClient.executeMethod(HttpClient.java:397)
    DEBUG_FRAME = org.apache.commons.httpclient.HttpClient.executeMethod(HttpClient.java:346)
    DEBUG_FRAME = org.apache.axis2.transport.http.AbstractHTTPSender.executeMethod(AbstractHTTPSender.java:542)
    DEBUG_FRAME = org.apache.axis2.transport.http.HTTPSender.sendViaPost(HTTPSender.java:199)
    DEBUG_FRAME = org.apache.axis2.transport.http.HTTPSender.send(HTTPSender.java:76)
    DEBUG_FRAME = org.apache.axis2.transport.http.CommonsHTTPTransportSender.writeMessageWithCommons(CommonsHTTPTransportSender.java:400)
    DEBUG_FRAME = org.apache.axis2.transport.http.CommonsHTTPTransportSender.invoke(CommonsHTTPTransportSender.java:225)
    DEBUG_FRAME = org.apache.axis2.engine.AxisEngine.send(AxisEngine.java:435)
    DEBUG_FRAME = org.apache.axis2.description.OutInAxisOperationClient.send(OutInAxisOperation.java:402)
    DEBUG_FRAME = org.apache.axis2.description.OutInAxisOperationClient.executeImpl(OutInAxisOperation.java:229)
    DEBUG_FRAME = org.apache.axis2.client.OperationClient.execute(OperationClient.java:165)
    DEBUG_FRAME = sil.axis2.client.main.SilDB2Stub.getDrugByDrugId(Unknown Source)
    DEBUG_FRAME = silor.prot.SilApiAxis2Handler.getDrugByDrugId(Unknown Source)
    DEBUG_FRAME = silor.cases.DrugBasic.DrugBasic20070821000(Unknown Source)
    DEBUG_FRAME = sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    DEBUG_FRAME = sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
    DEBUG_FRAME = sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
    DEBUG_FRAME = java.lang.reflect.Method.invoke(Method.java:585)
    DEBUG_FRAME = silor.main.Mexecute.execute(Unknown Source)
    DEBUG_FRAME = silor.main.CaseExecutor.run(Unknown Source)
    DEBUG_FRAME = silor.main.Main.init(Unknown Source)
    DEBUG_FRAME = silor.main.Main.main(Unknown Source)

2009-10-26 16:48:02,837 [main] DEBUG org.apache.axiom.om.util.StAXUtils  - XMLStreamWriter is com.ctc.wstx.sw.SimpleNsStreamWriter
2009-10-26 16:48:02,837 [main] DEBUG org.apache.axiom.om.impl.llom.OMSourcedElementImpl  - serialize {http://main.axis2.sil}getDrugByDrugId to XMLStreamWriter
2009-10-26 16:48:02,837 [main] DEBUG org.apache.axiom.om.impl.MTOMXMLStreamWriter  - Returning access to the original output stream: org.apache.commons.httpclient.ChunkedOutputStream@ec5359
2009-10-26 16:48:02,837 [main] DEBUG org.apache.axiom.om.impl.MTOMXMLStreamWriter  - Calling MTOMXMLStreamWriter.flush
2009-10-26 16:48:02,837 [main] DEBUG org.apache.axiom.om.impl.MTOMXMLStreamWriter  - Returning access to the original output stream: org.apache.commons.httpclient.ChunkedOutputStream@ec5359
2009-10-26 16:48:02,837 [main] DEBUG org.apache.axiom.om.impl.MTOMXMLStreamWriter  - Calling MTOMXMLStreamWriter.flush
2009-10-26 16:48:02,837 [main] DEBUG org.apache.axiom.om.impl.MTOMXMLStreamWriter  - Calling MTOMXMLStreamWriter.flush
2009-10-26 16:48:02,837 [main] DEBUG org.apache.axis2.transport.http.SOAPMessageFormatter  - end writeTo()
2009-10-26 16:48:02,837 [main] DEBUG httpclient.wire.content  - >> "158[\r][\n]"
2009-10-26 16:48:02,837 [main] DEBUG httpclient.wire.content  - >> "<?xml version='1.0' encoding='UTF-8'?><soapenv:Envelope xmlns:soapenv="http://schemas.xmlsoap.org/soap/envelope/"><soapenv:Body><main:getDrugByDrugId xmlns:main="http://main.axis2.sil"><main:param0>19980123000089</main:param0><main:param1>false</main:param1><main:param2>-1</main:param2></main:getDrugByDrugId></soapenv:Body></soapenv:Envelope>"
2009-10-26 16:48:02,837 [main] DEBUG httpclient.wire.content  - >> "[\r][\n]"
2009-10-26 16:48:02,837 [main] DEBUG httpclient.wire.content  - >> "0"
2009-10-26 16:48:02,837 [main] DEBUG httpclient.wire.content  - >> "[\r][\n]"
2009-10-26 16:48:02,837 [main] DEBUG httpclient.wire.content  - >> "[\r][\n]"
2009-10-26 16:48:02,837 [main] DEBUG org.apache.commons.httpclient.methods.EntityEnclosingMethod  - Request body sent
2009-10-26 16:48:02,837 [main] TRACE org.apache.commons.httpclient.HttpConnection  - enter HttpConnection.flushRequestOutputStream()
2009-10-26 16:48:02,837 [main] TRACE org.apache.commons.httpclient.HttpMethodBase  - enter HttpMethodBase.readResponse(HttpState, HttpConnection)
2009-10-26 16:48:02,837 [main] TRACE org.apache.commons.httpclient.HttpMethodBase  - enter HttpMethodBase.readStatusLine(HttpState, HttpConnection)
2009-10-26 16:48:02,837 [main] TRACE org.apache.commons.httpclient.HttpConnection  - enter HttpConnection.readLine()
2009-10-26 16:48:02,837 [main] TRACE org.apache.commons.httpclient.HttpParser  - enter HttpParser.readLine(InputStream, String)
2009-10-26 16:48:02,837 [main] TRACE org.apache.commons.httpclient.HttpParser  - enter HttpParser.readRawLine()
2009-10-26 16:48:02,837 [main] DEBUG httpclient.wire.header  - << "HTTP/1.1 200 OK[\r][\n]"
2009-10-26 16:48:02,837 [main] DEBUG httpclient.wire.header  - << "HTTP/1.1 200 OK[\r][\n]"
2009-10-26 16:48:02,837 [main] TRACE org.apache.commons.httpclient.HttpMethodBase  - enter HttpMethodBase.readResponseHeaders(HttpState,HttpConnection)
2009-10-26 16:48:02,837 [main] TRACE org.apache.commons.httpclient.HttpConnection  - enter HttpConnection.getResponseInputStream()
2009-10-26 16:48:02,837 [main] TRACE org.apache.commons.httpclient.HttpParser  - enter HeaderParser.parseHeaders(InputStream, String)
2009-10-26 16:48:02,837 [main] TRACE org.apache.commons.httpclient.HttpParser  - enter HttpParser.readLine(InputStream, String)
2009-10-26 16:48:02,837 [main] TRACE org.apache.commons.httpclient.HttpParser  - enter HttpParser.readRawLine()
2009-10-26 16:48:02,837 [main] DEBUG httpclient.wire.header  - << "Server: Apache-Coyote/1.1[\r][\n]"
2009-10-26 16:48:02,837 [main] TRACE org.apache.commons.httpclient.HttpParser  - enter HttpParser.readLine(InputStream, String)
2009-10-26 16:48:02,837 [main] TRACE org.apache.commons.httpclient.HttpParser  - enter HttpParser.readRawLine()
2009-10-26 16:48:02,837 [main] DEBUG httpclient.wire.header  - << "Content-Type: text/xml;charset=UTF-8[\r][\n]"
2009-10-26 16:48:02,837 [main] TRACE org.apache.commons.httpclient.HttpParser  - enter HttpParser.readLine(InputStream, String)
2009-10-26 16:48:02,837 [main] TRACE org.apache.commons.httpclient.HttpParser  - enter HttpParser.readRawLine()
2009-10-26 16:48:02,837 [main] DEBUG httpclient.wire.header  - << "Transfer-Encoding: chunked[\r][\n]"
2009-10-26 16:48:02,837 [main] TRACE org.apache.commons.httpclient.HttpParser  - enter HttpParser.readLine(InputStream, String)
2009-10-26 16:48:02,837 [main] TRACE org.apache.commons.httpclient.HttpParser  - enter HttpParser.readRawLine()
2009-10-26 16:48:02,837 [main] DEBUG httpclient.wire.header  - << "Date: Mon, 26 Oct 2009 15:47:41 GMT[\r][\n]"
2009-10-26 16:48:02,837 [main] TRACE org.apache.commons.httpclient.HttpParser  - enter HttpParser.readLine(InputStream, String)
2009-10-26 16:48:02,837 [main] TRACE org.apache.commons.httpclient.HttpParser  - enter HttpParser.readRawLine()
2009-10-26 16:48:02,837 [main] DEBUG httpclient.wire.header  - << "[\r][\n]"
2009-10-26 16:48:02,837 [main] TRACE org.apache.commons.httpclient.HttpMethodBase  - enter HttpMethodBase.processResponseHeaders(HttpState, HttpConnection)
2009-10-26 16:48:02,837 [main] TRACE org.apache.commons.httpclient.HttpMethodBase  - enter HttpMethodBase.processCookieHeaders(Header[], HttpState, HttpConnection)
2009-10-26 16:48:02,837 [main] TRACE org.apache.commons.httpclient.HttpMethodBase  - enter HttpMethodBase.readResponseBody(HttpState, HttpConnection)
2009-10-26 16:48:02,837 [main] TRACE org.apache.commons.httpclient.HttpMethodBase  - enter HttpMethodBase.readResponseBody(HttpConnection)
2009-10-26 16:48:02,837 [main] TRACE org.apache.commons.httpclient.HttpConnection  - enter HttpConnection.getResponseInputStream()
2009-10-26 16:48:02,837 [main] TRACE org.apache.commons.httpclient.HttpMethodBase  - enter HttpMethodBase.canResponseHaveBody(int)
2009-10-26 16:48:02,837 [main] TRACE org.apache.commons.httpclient.HeaderElement  - enter HeaderElement.parseElements(String)
2009-10-26 16:48:02,837 [main] TRACE org.apache.commons.httpclient.HeaderElement  - enter HeaderElement.parseElements(char[])
2009-10-26 16:48:02,837 [main] TRACE org.apache.commons.httpclient.HttpConnection  - enter HttpConnection.isResponseAvailable(int)
2009-10-26 16:48:02,837 [main] TRACE org.apache.axis2.transport.http.HTTPSender  - Handling response - 200
2009-10-26 16:48:02,837 [main] TRACE org.apache.commons.httpclient.HeaderElement  - enter HeaderElement.parseElements(String)
2009-10-26 16:48:02,837 [main] TRACE org.apache.commons.httpclient.HeaderElement  - enter HeaderElement.parseElements(char[])
2009-10-26 16:48:02,837 [main] TRACE org.apache.commons.httpclient.HeaderElement  - enter HeaderElement.getParameterByName(String)
2009-10-26 16:48:02,837 [main] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:D19A3745E4C2A334441256572123884] Invoking flowComplete() in Phase "Security"
2009-10-26 16:48:02,837 [main] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:D19A3745E4C2A334441256572123884] Invoking flowComplete() in Phase "MessageOut"
2009-10-26 16:48:02,837 [main] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:D19A3745E4C2A334441256572123884] Invoking flowComplete() in Phase "PolicyDetermination"
2009-10-26 16:48:02,837 [main] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:D19A3745E4C2A334441256572123884] Invoking flowComplete() in Phase "RMPhase"
2009-10-26 16:48:02,837 [main] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:D19A3745E4C2A334441256572123884] Invoking flowComplete() in Phase "OperationOutPhase"
2009-10-26 16:48:02,837 [main] DEBUG org.apache.axis2.transport.TransportUtils  - createSOAPEnvelope using Builder (class org.apache.axis2.builder.SOAPBuilder) selected from type (text/xml)
2009-10-26 16:48:02,837 [main] DEBUG httpclient.wire.content  - << "6"
2009-10-26 16:48:02,837 [main] DEBUG httpclient.wire.content  - << "2"
2009-10-26 16:48:02,837 [main] DEBUG httpclient.wire.content  - << "9"
2009-10-26 16:48:02,837 [main] DEBUG httpclient.wire.content  - << "[\r]"
2009-10-26 16:48:02,837 [main] DEBUG httpclient.wire.content  - << "[\n]"
2009-10-26 16:48:02,837 [main] DEBUG httpclient.wire.content  - << "<?xm"
2009-10-26 16:48:02,837 [main] DEBUG org.apache.axis2.builder.BuilderUtil  - char set encoding set from default =UTF-8
2009-10-26 16:48:02,837 [main] DEBUG httpclient.wire.content  - << "l version='1.0' encoding='UTF-8'?><soapenv:Envelope xmlns:soapenv="http://schemas.xmlsoap.org/soap/envelope/"><soapenv:Body><ns1:getDrugByDrugIdResponse xmlns:ns1="http://main.axis2.sil"><ns1:return><ns1:drugId>20040607010594</ns1:drugId><ns1:tradeName>Ramipril Durascan</ns1:tradeName><ns1:strengthNumeric>1.25</ns1:strengthNumeric><ns1:strengthNumericUnit>mg</ns1:strengthNumericUnit><ns1:strengthText>1,25 mg</ns1:strengthText><ns1:drugFormCode>CAPHAR</ns1:drugFormCode><ns1:drugFormTextSv>Kapsel, h[0xc3][0xa5]rd</ns1:drugFormTextSv><ns1:drugClassificationCode>-</ns1:drugClassificationCode><ns1:controlClassCode>0</ns1:controlClassCode><ns1:routeOfAdministrationCodes>-</ns1:routeOfAdministrationCodes><ns1:prescriberCodes>1</ns1:prescriberCodes><ns1:interchangeableFlag>N</ns1:interchangeableFlag><ns1:substanceGroupId>0</ns1:substanceGroupId><ns1:substanceGroupName></ns1:substanceGroupName><ns1:strengthGroupId>0</ns1:strengthGroupId><ns1:strengthGroupName></ns1:strengthGroupName><ns1:pharmaceuticalFormGroupId>0</ns1:pharmaceuticalFormGroupId><ns1:pharmaceuticalFormGroupName></ns1:pharmaceuticalFormGroupName><ns1:lactationGroup>?</ns1:lactationGroup><ns1:pregnancyCategory>?</ns1:pregnancyCategory><ns1:interactionStatus>1</ns1:interactionStatus><ns1:productTypeCode>MEP</ns1:productTypeCode><ns1:prescriptionCode>1</ns1:prescriptionCode><ns1:withdrawalDate>2005-02-28</ns1:withdrawalDate><ns1:hasRecommendedArticle>false</ns1:hasRecommendedArticle><ns1:silDeviationCode></ns1:silDeviationCode></ns1:return></ns1:getDrugByDrugIdResponse></soapenv:Body></soapenv:Envelope>"
2009-10-26 16:48:02,837 [main] DEBUG org.apache.axiom.om.util.StAXUtils  - XMLStreamReader is com.ctc.wstx.sr.ValidatingStreamReader
2009-10-26 16:48:02,837 [main] TRACE org.apache.axiom.om.impl.builder.StAXOMBuilder  - START_ELEMENT: 
2009-10-26 16:48:02,837 [main] TRACE org.apache.axiom.om.impl.builder.StAXOMBuilder  -   QName: {http://schemas.xmlsoap.org/soap/envelope/}Envelope
2009-10-26 16:48:02,837 [main] DEBUG org.apache.axiom.soap.impl.builder.StAXSOAPModelBuilder  - Starting to process SOAP 1.1 message
2009-10-26 16:48:02,837 [main] DEBUG org.apache.axiom.soap.impl.builder.StAXSOAPModelBuilder  - Build the OMElement Envelope by the StaxSOAPModelBuilder
2009-10-26 16:48:02,837 [main] TRACE org.apache.axis2.engine.AxisEngine  - [MessageContext: logID=urn:uuid:D19A3745E4C2A334441256572123916] receive:urn:uuid:D19A3745E4C2A334441256572123883
2009-10-26 16:48:02,837 [main] TRACE org.apache.axiom.om.impl.builder.StAXOMBuilder  - START_ELEMENT: 
2009-10-26 16:48:02,837 [main] TRACE org.apache.axiom.om.impl.builder.StAXOMBuilder  -   QName: {http://schemas.xmlsoap.org/soap/envelope/}Body
2009-10-26 16:48:02,837 [main] DEBUG org.apache.axiom.soap.impl.builder.StAXSOAPModelBuilder  - Build the OMElement Body by the StaxSOAPModelBuilder
2009-10-26 16:48:02,837 [main] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:D19A3745E4C2A334441256572123916] Checking pre-condition for Phase "Transport"
2009-10-26 16:48:02,837 [main] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:D19A3745E4C2A334441256572123916] Invoking phase "Transport"
2009-10-26 16:48:02,837 [main] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:D19A3745E4C2A334441256572123916] Invoking Handler 'RequestURIBasedDispatcher' in Phase 'Transport'
2009-10-26 16:48:02,837 [main] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:D19A3745E4C2A334441256572123916] Invoking Handler 'SOAPActionBasedDispatcher' in Phase 'Transport'
2009-10-26 16:48:02,837 [main] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:D19A3745E4C2A334441256572123916] Checking post-conditions for phase "Transport"
2009-10-26 16:48:02,837 [main] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:D19A3745E4C2A334441256572123916] Checking pre-condition for Phase "Addressing"
2009-10-26 16:48:02,837 [main] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:D19A3745E4C2A334441256572123916] Invoking phase "Addressing"
2009-10-26 16:48:02,837 [main] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:D19A3745E4C2A334441256572123916] Invoking Handler 'AddressingBasedDispatcher' in Phase 'Addressing'
2009-10-26 16:48:02,837 [main] TRACE org.apache.axis2.dispatchers.AddressingBasedDispatcher  - invoke: IS_ADDR_INFO_ALREADY_PROCESSED=null
2009-10-26 16:48:02,837 [main] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:D19A3745E4C2A334441256572123916] Checking post-conditions for phase "Addressing"
2009-10-26 16:48:02,837 [main] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:D19A3745E4C2A334441256572123916] Checking pre-condition for Phase "Security"
2009-10-26 16:48:02,837 [main] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:D19A3745E4C2A334441256572123916] Invoking phase "Security"
2009-10-26 16:48:02,837 [main] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:D19A3745E4C2A334441256572123916] Checking post-conditions for phase "Security"
2009-10-26 16:48:02,837 [main] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:D19A3745E4C2A334441256572123916] Checking pre-condition for Phase "PreDispatch"
2009-10-26 16:48:02,837 [main] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:D19A3745E4C2A334441256572123916] Invoking phase "PreDispatch"
2009-10-26 16:48:02,837 [main] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:D19A3745E4C2A334441256572123916] Checking post-conditions for phase "PreDispatch"
2009-10-26 16:48:02,837 [main] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:D19A3745E4C2A334441256572123916] Checking pre-condition for Phase "Dispatch"
2009-10-26 16:48:02,837 [main] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:D19A3745E4C2A334441256572123916] Invoking phase "Dispatch"
2009-10-26 16:48:02,837 [main] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:D19A3745E4C2A334441256572123916] Invoking Handler 'RequestURIBasedDispatcher' in Phase 'Dispatch'
2009-10-26 16:48:02,837 [main] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:D19A3745E4C2A334441256572123916] Invoking Handler 'SOAPActionBasedDispatcher' in Phase 'Dispatch'
2009-10-26 16:48:02,837 [main] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:D19A3745E4C2A334441256572123916] Invoking Handler 'RequestURIOperationDispatcher' in Phase 'Dispatch'
2009-10-26 16:48:02,837 [main] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:D19A3745E4C2A334441256572123916] Invoking Handler 'SOAPMessageBodyBasedDispatcher' in Phase 'Dispatch'
2009-10-26 16:48:02,837 [main] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:D19A3745E4C2A334441256572123916] Invoking Handler 'HTTPLocationBasedDispatcher' in Phase 'Dispatch'
2009-10-26 16:48:02,837 [main] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:D19A3745E4C2A334441256572123916] Checking post-conditions for phase "Dispatch"
2009-10-26 16:48:02,837 [main] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:D19A3745E4C2A334441256572123916] Checking pre-condition for Phase "RMPhase"
2009-10-26 16:48:02,837 [main] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:D19A3745E4C2A334441256572123916] Invoking phase "RMPhase"
2009-10-26 16:48:02,837 [main] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:D19A3745E4C2A334441256572123916] Checking post-conditions for phase "RMPhase"
2009-10-26 16:48:02,837 [main] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:D19A3745E4C2A334441256572123916] Checking pre-condition for Phase "OperationInPhase"
2009-10-26 16:48:02,837 [main] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:D19A3745E4C2A334441256572123916] Invoking phase "OperationInPhase"
2009-10-26 16:48:02,837 [main] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:D19A3745E4C2A334441256572123916] Checking post-conditions for phase "OperationInPhase"
2009-10-26 16:48:02,837 [main] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:D19A3745E4C2A334441256572123916] Invoking flowComplete() in Phase "OperationInPhase"
2009-10-26 16:48:02,837 [main] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:D19A3745E4C2A334441256572123916] Invoking flowComplete() in Phase "RMPhase"
2009-10-26 16:48:02,837 [main] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:D19A3745E4C2A334441256572123916] Invoking flowComplete() in Phase "Dispatch"
2009-10-26 16:48:02,853 [main] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:D19A3745E4C2A334441256572123916] Invoking flowComplete() for Handler 'HTTPLocationBasedDispatcher' in Phase 'Dispatch'
2009-10-26 16:48:02,853 [main] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:D19A3745E4C2A334441256572123916] Invoking flowComplete() for Handler 'SOAPMessageBodyBasedDispatcher' in Phase 'Dispatch'
2009-10-26 16:48:02,853 [main] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:D19A3745E4C2A334441256572123916] Invoking flowComplete() for Handler 'RequestURIOperationDispatcher' in Phase 'Dispatch'
2009-10-26 16:48:02,853 [main] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:D19A3745E4C2A334441256572123916] Invoking flowComplete() for Handler 'SOAPActionBasedDispatcher' in Phase 'Dispatch'
2009-10-26 16:48:02,853 [main] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:D19A3745E4C2A334441256572123916] Invoking flowComplete() for Handler 'RequestURIBasedDispatcher' in Phase 'Dispatch'
2009-10-26 16:48:02,853 [main] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:D19A3745E4C2A334441256572123916] Invoking flowComplete() in Phase "PreDispatch"
2009-10-26 16:48:02,853 [main] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:D19A3745E4C2A334441256572123916] Invoking flowComplete() in Phase "Security"
2009-10-26 16:48:02,853 [main] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:D19A3745E4C2A334441256572123916] Invoking flowComplete() in Phase "Addressing"
2009-10-26 16:48:02,853 [main] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:D19A3745E4C2A334441256572123916] Invoking flowComplete() for Handler 'AddressingBasedDispatcher' in Phase 'Addressing'
2009-10-26 16:48:02,853 [main] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:D19A3745E4C2A334441256572123916] Invoking flowComplete() in Phase "Transport"
2009-10-26 16:48:02,853 [main] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:D19A3745E4C2A334441256572123916] Invoking flowComplete() for Handler 'SOAPActionBasedDispatcher' in Phase 'Transport'
2009-10-26 16:48:02,853 [main] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:D19A3745E4C2A334441256572123916] Invoking flowComplete() for Handler 'RequestURIBasedDispatcher' in Phase 'Transport'
2009-10-26 16:48:02,853 [main] TRACE org.apache.axiom.om.impl.builder.StAXOMBuilder  - START_ELEMENT: 
2009-10-26 16:48:02,853 [main] TRACE org.apache.axiom.om.impl.builder.StAXOMBuilder  -   QName: {http://main.axis2.sil}getDrugByDrugIdResponse
2009-10-26 16:48:02,853 [main] DEBUG org.apache.axiom.soap.impl.builder.StAXSOAPModelBuilder  - Build the OMElement getDrugByDrugIdResponse by the StaxSOAPModelBuilder
2009-10-26 16:48:02,853 [main] TRACE org.apache.axiom.om.impl.builder.StAXOMBuilder  - START_ELEMENT: 
2009-10-26 16:48:02,853 [main] TRACE org.apache.axiom.om.impl.builder.StAXOMBuilder  -   QName: {http://main.axis2.sil}return
2009-10-26 16:48:02,853 [main] DEBUG org.apache.axiom.soap.impl.builder.StAXSOAPModelBuilder  - Build the OMElement return by the StaxSOAPModelBuilder
2009-10-26 16:48:02,853 [main] DEBUG httpclient.wire.content  - << "[\r]"
2009-10-26 16:48:02,853 [main] DEBUG httpclient.wire.content  - << "[\n]"
2009-10-26 16:48:02,853 [main] DEBUG httpclient.wire.content  - << "0"
2009-10-26 16:48:02,853 [main] DEBUG httpclient.wire.content  - << "[\r]"
2009-10-26 16:48:02,853 [main] DEBUG httpclient.wire.content  - << "[\n]"
2009-10-26 16:48:02,853 [main] TRACE org.apache.commons.httpclient.HttpParser  - enter HeaderParser.parseHeaders(InputStream, String)
2009-10-26 16:48:02,853 [main] TRACE org.apache.commons.httpclient.HttpParser  - enter HttpParser.readLine(InputStream, String)
2009-10-26 16:48:02,853 [main] TRACE org.apache.commons.httpclient.HttpParser  - enter HttpParser.readRawLine()
2009-10-26 16:48:02,853 [main] DEBUG httpclient.wire.content  - << "[\r]"
2009-10-26 16:48:02,853 [main] DEBUG httpclient.wire.content  - << "[\n]"
2009-10-26 16:48:02,853 [main] DEBUG httpclient.wire.header  - << "[\r][\n]"
2009-10-26 16:48:02,853 [main] DEBUG org.apache.commons.httpclient.HttpMethodBase  - Resorting to protocol version default close connection policy
2009-10-26 16:48:02,853 [main] DEBUG org.apache.commons.httpclient.HttpMethodBase  - Should NOT close connection, using HTTP/1.1
2009-10-26 16:48:02,853 [main] TRACE org.apache.commons.httpclient.HttpConnection  - enter HttpConnection.isResponseAvailable()
2009-10-26 16:48:02,853 [main] TRACE org.apache.commons.httpclient.HttpConnection  - enter HttpConnection.releaseConnection()
2009-10-26 16:48:02,853 [main] DEBUG org.apache.commons.httpclient.HttpConnection  - Releasing connection back to connection manager.
2009-10-26 16:48:02,853 [main] TRACE org.apache.commons.httpclient.MultiThreadedHttpConnectionManager  - enter HttpConnectionManager.releaseConnection(HttpConnection)
2009-10-26 16:48:02,853 [main] DEBUG org.apache.commons.httpclient.MultiThreadedHttpConnectionManager  - Freeing connection, hostConfig=HostConfiguration[host=http://192.168.18.18:8080]
2009-10-26 16:48:02,853 [main] TRACE org.apache.commons.httpclient.MultiThreadedHttpConnectionManager  - enter HttpConnectionManager.ConnectionPool.getHostPool(HostConfiguration)
2009-10-26 16:48:02,853 [main] DEBUG org.apache.commons.httpclient.util.IdleConnectionHandler  - Adding connection at: 1256572082853
2009-10-26 16:48:02,853 [main] DEBUG org.apache.commons.httpclient.MultiThreadedHttpConnectionManager  - Notifying no-one, there are no waiting threads


*********************************************************************************************************************

SERVER LOG:

.
.
.
2009-10-26 16:47:41,916 [http-8080-1] DEBUG org.apache.axis2.builder.BuilderUtil  - Input contentType (text/xml; charset=UTF-8)
2009-10-26 16:47:41,916 [http-8080-1] DEBUG org.apache.axis2.builder.BuilderUtil  - CharSetEncoding from content-type (UTF-8)
2009-10-26 16:47:41,916 [http-8080-1] DEBUG org.apache.axis2.transport.TransportUtils  - createSOAPEnvelope using Builder (class org.apache.axis2.builder.SOAPBuilder) selected from type (text/xml)
2009-10-26 16:47:41,916 [http-8080-1] DEBUG org.apache.axis2.builder.BuilderUtil  - char set encoding set from default =UTF-8
2009-10-26 16:47:41,916 [http-8080-1] DEBUG org.apache.axiom.om.util.StAXUtils  - XMLStreamReader is com.ctc.wstx.sr.ValidatingStreamReader
2009-10-26 16:47:41,916 [http-8080-1] TRACE org.apache.axiom.om.impl.builder.StAXOMBuilder  - START_ELEMENT: 
2009-10-26 16:47:41,916 [http-8080-1] TRACE org.apache.axiom.om.impl.builder.StAXOMBuilder  -   QName: {http://schemas.xmlsoap.org/soap/envelope/}Envelope
2009-10-26 16:47:41,916 [http-8080-1] DEBUG org.apache.axiom.soap.impl.builder.StAXSOAPModelBuilder  - Starting to process SOAP 1.1 message
2009-10-26 16:47:41,916 [http-8080-1] DEBUG org.apache.axiom.soap.impl.builder.StAXSOAPModelBuilder  - Build the OMElement Envelope by the StaxSOAPModelBuilder
2009-10-26 16:47:41,916 [http-8080-1] TRACE org.apache.axis2.engine.AxisEngine  - [MessageContext: logID=urn:uuid:64F72C5F5C41FBA2071256572089445] receive:null
2009-10-26 16:47:41,916 [http-8080-1] TRACE org.apache.axiom.om.impl.builder.StAXOMBuilder  - START_ELEMENT: 
2009-10-26 16:47:41,916 [http-8080-1] TRACE org.apache.axiom.om.impl.builder.StAXOMBuilder  -   QName: {http://schemas.xmlsoap.org/soap/envelope/}Body
2009-10-26 16:47:41,916 [http-8080-1] DEBUG org.apache.axiom.soap.impl.builder.StAXSOAPModelBuilder  - Build the OMElement Body by the StaxSOAPModelBuilder
2009-10-26 16:47:41,916 [http-8080-1] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:64F72C5F5C41FBA2071256572089445] Checking pre-condition for Phase "Transport"
2009-10-26 16:47:41,916 [http-8080-1] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:64F72C5F5C41FBA2071256572089445] Invoking phase "Transport"
2009-10-26 16:47:41,916 [http-8080-1] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:64F72C5F5C41FBA2071256572089445] Invoking Handler 'RequestURIBasedDispatcher' in Phase 'Transport'
2009-10-26 16:47:41,916 [http-8080-1] DEBUG org.apache.axis2.dispatchers.RequestURIBasedServiceDispatcher  - [MessageContext: logID=urn:uuid:64F72C5F5C41FBA2071256572089445] Checking for Service using target endpoint address : http://192.168.18.18:8080/axis2/services/SilDB2
2009-10-26 16:47:41,916 [http-8080-1] DEBUG org.apache.axis2.util.Utils  - parseRequestURLForServiceAndOperation : [http://192.168.18.18:8080/axis2/services/SilDB2][/axis2/services]
2009-10-26 16:47:41,916 [http-8080-1] DEBUG org.apache.axis2.i18n.ProjectResourceBundle  - org.apache.axis2.i18n.resource::handleGetObject(servicefound)
2009-10-26 16:47:41,916 [http-8080-1] DEBUG org.apache.axis2.engine.AbstractDispatcher  - [MessageContext: logID=urn:uuid:64F72C5F5C41FBA2071256572089445] Found AxisService : SilDB2
2009-10-26 16:47:41,916 [http-8080-1] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:64F72C5F5C41FBA2071256572089445] Invoking Handler 'SOAPActionBasedDispatcher' in Phase 'Transport'
2009-10-26 16:47:41,916 [http-8080-1] DEBUG org.apache.axis2.dispatchers.ActionBasedOperationDispatcher  - [MessageContext: logID=urn:uuid:64F72C5F5C41FBA2071256572089445] Checking for Operation using Action : http://main.axis2.sil/SilDB2/getDrugByDrugIdRequest
2009-10-26 16:47:41,916 [http-8080-1] DEBUG org.apache.axis2.description.AxisService  - getOperationBySOAPAction: Operation (org.apache.axis2.description.InOutAxisOperation@1469658,{http://main.axis2.sil}getDrugByDrugId) for soapAction: http://main.axis2.sil/SilDB2/getDrugByDrugIdRequest found in action map.
2009-10-26 16:47:41,916 [http-8080-1] DEBUG org.apache.axis2.i18n.ProjectResourceBundle  - org.apache.axis2.i18n.resource::handleGetObject(operationfound)
2009-10-26 16:47:41,916 [http-8080-1] DEBUG org.apache.axis2.engine.AbstractDispatcher  - [MessageContext: logID=urn:uuid:64F72C5F5C41FBA2071256572089445] Found AxisOperation : getDrugByDrugId
2009-10-26 16:47:41,916 [http-8080-1] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:64F72C5F5C41FBA2071256572089445] Checking post-conditions for phase "Transport"
2009-10-26 16:47:41,916 [http-8080-1] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:64F72C5F5C41FBA2071256572089445] Checking pre-condition for Phase "Addressing"
2009-10-26 16:47:41,916 [http-8080-1] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:64F72C5F5C41FBA2071256572089445] Invoking phase "Addressing"
2009-10-26 16:47:41,916 [http-8080-1] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:64F72C5F5C41FBA2071256572089445] Invoking Handler 'AddressingInHandler' in Phase 'Addressing'
2009-10-26 16:47:41,916 [http-8080-1] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:64F72C5F5C41FBA2071256572089445] Invoking Handler 'AddressingBasedDispatcher' in Phase 'Addressing'
2009-10-26 16:47:41,916 [http-8080-1] TRACE org.apache.axis2.dispatchers.AddressingBasedDispatcher  - invoke: IS_ADDR_INFO_ALREADY_PROCESSED=false
2009-10-26 16:47:41,916 [http-8080-1] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:64F72C5F5C41FBA2071256572089445] Checking post-conditions for phase "Addressing"
2009-10-26 16:47:41,916 [http-8080-1] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:64F72C5F5C41FBA2071256572089445] Checking pre-condition for Phase "Security"
2009-10-26 16:47:41,916 [http-8080-1] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:64F72C5F5C41FBA2071256572089445] Invoking phase "Security"
2009-10-26 16:47:41,916 [http-8080-1] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:64F72C5F5C41FBA2071256572089445] Checking post-conditions for phase "Security"
2009-10-26 16:47:41,916 [http-8080-1] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:64F72C5F5C41FBA2071256572089445] Checking pre-condition for Phase "PreDispatch"
2009-10-26 16:47:41,916 [http-8080-1] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:64F72C5F5C41FBA2071256572089445] Invoking phase "PreDispatch"
2009-10-26 16:47:41,916 [http-8080-1] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:64F72C5F5C41FBA2071256572089445] Checking post-conditions for phase "PreDispatch"
2009-10-26 16:47:41,916 [http-8080-1] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:64F72C5F5C41FBA2071256572089445] Checking pre-condition for Phase "Dispatch"
2009-10-26 16:47:41,916 [http-8080-1] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:64F72C5F5C41FBA2071256572089445] Invoking phase "Dispatch"
2009-10-26 16:47:41,916 [http-8080-1] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:64F72C5F5C41FBA2071256572089445] Invoking Handler 'RequestURIBasedDispatcher' in Phase 'Dispatch'
2009-10-26 16:47:41,916 [http-8080-1] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:64F72C5F5C41FBA2071256572089445] Invoking Handler 'SOAPActionBasedDispatcher' in Phase 'Dispatch'
2009-10-26 16:47:41,916 [http-8080-1] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:64F72C5F5C41FBA2071256572089445] Invoking Handler 'RequestURIOperationDispatcher' in Phase 'Dispatch'
2009-10-26 16:47:41,916 [http-8080-1] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:64F72C5F5C41FBA2071256572089445] Invoking Handler 'SOAPMessageBodyBasedDispatcher' in Phase 'Dispatch'
2009-10-26 16:47:41,916 [http-8080-1] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:64F72C5F5C41FBA2071256572089445] Invoking Handler 'AddressingValidationHandler' in Phase 'Dispatch'
2009-10-26 16:47:41,916 [http-8080-1] TRACE org.apache.axis2.handlers.addressing.AddressingValidationHandler  - invoke: IS_ADDR_INFO_ALREADY_PROCESSED=false
2009-10-26 16:47:41,916 [http-8080-1] DEBUG org.apache.axis2.addressing.AddressingHelper  - getAddressingRequirementParemeterValue: value: 'null'
2009-10-26 16:47:41,916 [http-8080-1] TRACE org.apache.axis2.handlers.addressing.AddressingValidationHandler  - checkUsingAddressing: WSAddressingFlag=unspecified
2009-10-26 16:47:41,916 [http-8080-1] DEBUG org.apache.axis2.addressing.AddressingHelper  - getInvocationPatternParameterValue: value: 'null'
2009-10-26 16:47:41,916 [http-8080-1] TRACE org.apache.axis2.handlers.addressing.AddressingValidationHandler  - checkWSAMInvocationPattern: value=both
2009-10-26 16:47:41,916 [http-8080-1] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:64F72C5F5C41FBA2071256572089445] Invoking Handler 'HTTPLocationBasedDispatcher' in Phase 'Dispatch'
2009-10-26 16:47:41,916 [http-8080-1] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:64F72C5F5C41FBA2071256572089445] Invoking Handler 'GenericProviderDispatcher' in Phase 'Dispatch'
2009-10-26 16:47:41,916 [http-8080-1] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:64F72C5F5C41FBA2071256572089445] Invoking Handler 'MustUnderstandValidationDispatcher' in Phase 'Dispatch'
2009-10-26 16:47:41,916 [http-8080-1] DEBUG org.apache.axis2.jaxws.dispatchers.MustUnderstandValidationDispatcher  - JAXWS MustUnderstandValidationDispatcher.invoke on AxisService SilDB2; AxisOperation org.apache.axis2.description.InOutAxisOperation@1469658
2009-10-26 16:47:41,916 [http-8080-1] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:64F72C5F5C41FBA2071256572089445] Checking post-conditions for phase "Dispatch"
2009-10-26 16:47:41,916 [http-8080-1] DEBUG org.apache.axis2.addressing.AddressingHelper  - [MessageContext: logID=urn:uuid:64F72C5F5C41FBA2071256572089445] isReplyRedirected: ReplyTo is null. Returning false
2009-10-26 16:47:41,916 [http-8080-1] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:64F72C5F5C41FBA2071256572089445] Checking pre-condition for Phase "RMPhase"
2009-10-26 16:47:41,916 [http-8080-1] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:64F72C5F5C41FBA2071256572089445] Invoking phase "RMPhase"
2009-10-26 16:47:41,916 [http-8080-1] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:64F72C5F5C41FBA2071256572089445] Checking post-conditions for phase "RMPhase"
2009-10-26 16:47:41,916 [http-8080-1] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:64F72C5F5C41FBA2071256572089445] Checking pre-condition for Phase "OperationInPhase"
2009-10-26 16:47:41,916 [http-8080-1] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:64F72C5F5C41FBA2071256572089445] Invoking phase "OperationInPhase"
2009-10-26 16:47:41,916 [http-8080-1] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:64F72C5F5C41FBA2071256572089445] Invoking Handler 'MustUnderstandChecker' in Phase 'OperationInPhase'
2009-10-26 16:47:41,916 [http-8080-1] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:64F72C5F5C41FBA2071256572089445] Checking post-conditions for phase "OperationInPhase"
2009-10-26 16:47:41,916 [http-8080-1] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:64F72C5F5C41FBA2071256572089445] Checking pre-condition for Phase "soapmonitorPhase"
2009-10-26 16:47:41,916 [http-8080-1] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:64F72C5F5C41FBA2071256572089445] Invoking phase "soapmonitorPhase"
2009-10-26 16:47:41,916 [http-8080-1] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:64F72C5F5C41FBA2071256572089445] Checking post-conditions for phase "soapmonitorPhase"
2009-10-26 16:47:41,916 [http-8080-1] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:64F72C5F5C41FBA2071256572089445] Checking pre-condition for Phase "loggingPhase"
2009-10-26 16:47:41,916 [http-8080-1] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:64F72C5F5C41FBA2071256572089445] Invoking phase "loggingPhase"
2009-10-26 16:47:41,916 [http-8080-1] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:64F72C5F5C41FBA2071256572089445] Invoking Handler 'null' in Phase 'loggingPhase'
2009-10-26 16:47:41,916 [http-8080-1] DEBUG org.apache.axiom.om.util.StAXUtils  - XMLStreamWriter is com.ctc.wstx.sw.SimpleNsStreamWriter
2009-10-26 16:47:41,916 [http-8080-1] TRACE org.apache.axiom.om.impl.MTOMXMLStreamWriter  - Call Stack =DEBUG_FRAME = org.apache.axiom.om.util.CommonUtils.callStackToString(CommonUtils.java:80)
    DEBUG_FRAME = org.apache.axiom.om.impl.MTOMXMLStreamWriter.<init>(MTOMXMLStreamWriter.java:74)
    DEBUG_FRAME = org.apache.axiom.om.impl.llom.OMNodeImpl.serialize(OMNodeImpl.java:384)
    DEBUG_FRAME = org.apache.axiom.om.impl.llom.OMElementImpl.toString(OMElementImpl.java:1106)
    DEBUG_FRAME = userguide.loggingmodule.LogHandler.invoke(Unknown Source)
    DEBUG_FRAME = org.apache.axis2.engine.Phase.invoke(Phase.java:318)
    DEBUG_FRAME = org.apache.axis2.engine.AxisEngine.invoke(AxisEngine.java:251)
    DEBUG_FRAME = org.apache.axis2.engine.AxisEngine.receive(AxisEngine.java:160)
    DEBUG_FRAME = org.apache.axis2.transport.http.HTTPTransportUtils.processHTTPPostRequest(HTTPTransportUtils.java:167)
    DEBUG_FRAME = org.apache.axis2.transport.http.AxisServlet.doPost(AxisServlet.java:142)
    DEBUG_FRAME = javax.servlet.http.HttpServlet.service(HttpServlet.java:637)
    DEBUG_FRAME = javax.servlet.http.HttpServlet.service(HttpServlet.java:717)
    DEBUG_FRAME = org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:290)
    DEBUG_FRAME = org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
    DEBUG_FRAME = org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:233)
    DEBUG_FRAME = org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:191)
    DEBUG_FRAME = org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:128)
    DEBUG_FRAME = org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102)
    DEBUG_FRAME = org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109)
    DEBUG_FRAME = org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:293)
    DEBUG_FRAME = org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:849)
    DEBUG_FRAME = org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:583)
    DEBUG_FRAME = org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:454)
    DEBUG_FRAME = java.lang.Thread.run(Thread.java:619)

2009-10-26 16:47:41,916 [http-8080-1] TRACE org.apache.axiom.om.impl.builder.StAXOMBuilder  - START_ELEMENT: 
2009-10-26 16:47:41,916 [http-8080-1] TRACE org.apache.axiom.om.impl.builder.StAXOMBuilder  -   QName: {http://main.axis2.sil}getDrugByDrugId
2009-10-26 16:47:41,916 [http-8080-1] DEBUG org.apache.axiom.soap.impl.builder.StAXSOAPModelBuilder  - Build the OMElement getDrugByDrugId by the StaxSOAPModelBuilder
2009-10-26 16:47:41,916 [http-8080-1] TRACE org.apache.axiom.om.impl.builder.StAXOMBuilder  - START_ELEMENT: 
2009-10-26 16:47:41,916 [http-8080-1] TRACE org.apache.axiom.om.impl.builder.StAXOMBuilder  -   QName: {http://main.axis2.sil}param0
2009-10-26 16:47:41,916 [http-8080-1] DEBUG org.apache.axiom.soap.impl.builder.StAXSOAPModelBuilder  - Build the OMElement param0 by the StaxSOAPModelBuilder
2009-10-26 16:47:41,916 [http-8080-1] TRACE org.apache.axiom.om.impl.builder.StAXOMBuilder  - CHARACTERS: 
2009-10-26 16:47:41,916 [http-8080-1] TRACE org.apache.axiom.om.impl.builder.StAXOMBuilder  - END_ELEMENT: 
2009-10-26 16:47:41,916 [http-8080-1] TRACE org.apache.axiom.om.impl.builder.StAXOMBuilder  -   QName: {http://main.axis2.sil}param0
2009-10-26 16:47:41,916 [http-8080-1] TRACE org.apache.axiom.om.impl.builder.StAXOMBuilder  - START_ELEMENT: 
2009-10-26 16:47:41,916 [http-8080-1] TRACE org.apache.axiom.om.impl.builder.StAXOMBuilder  -   QName: {http://main.axis2.sil}param1
2009-10-26 16:47:41,916 [http-8080-1] DEBUG org.apache.axiom.soap.impl.builder.StAXSOAPModelBuilder  - Build the OMElement param1 by the StaxSOAPModelBuilder
2009-10-26 16:47:41,916 [http-8080-1] TRACE org.apache.axiom.om.impl.builder.StAXOMBuilder  - CHARACTERS: 
2009-10-26 16:47:41,916 [http-8080-1] TRACE org.apache.axiom.om.impl.builder.StAXOMBuilder  - END_ELEMENT: 
2009-10-26 16:47:41,916 [http-8080-1] TRACE org.apache.axiom.om.impl.builder.StAXOMBuilder  -   QName: {http://main.axis2.sil}param1
2009-10-26 16:47:41,916 [http-8080-1] TRACE org.apache.axiom.om.impl.builder.StAXOMBuilder  - START_ELEMENT: 
2009-10-26 16:47:41,916 [http-8080-1] TRACE org.apache.axiom.om.impl.builder.StAXOMBuilder  -   QName: {http://main.axis2.sil}param2
2009-10-26 16:47:41,916 [http-8080-1] DEBUG org.apache.axiom.soap.impl.builder.StAXSOAPModelBuilder  - Build the OMElement param2 by the StaxSOAPModelBuilder
2009-10-26 16:47:41,916 [http-8080-1] TRACE org.apache.axiom.om.impl.builder.StAXOMBuilder  - CHARACTERS: 
2009-10-26 16:47:41,916 [http-8080-1] TRACE org.apache.axiom.om.impl.builder.StAXOMBuilder  - END_ELEMENT: 
2009-10-26 16:47:41,916 [http-8080-1] TRACE org.apache.axiom.om.impl.builder.StAXOMBuilder  -   QName: {http://main.axis2.sil}param2
2009-10-26 16:47:41,916 [http-8080-1] TRACE org.apache.axiom.om.impl.builder.StAXOMBuilder  - END_ELEMENT: 
2009-10-26 16:47:41,916 [http-8080-1] TRACE org.apache.axiom.om.impl.builder.StAXOMBuilder  -   QName: {http://main.axis2.sil}getDrugByDrugId
2009-10-26 16:47:41,916 [http-8080-1] TRACE org.apache.axiom.om.impl.builder.StAXOMBuilder  - END_ELEMENT: 
2009-10-26 16:47:41,916 [http-8080-1] TRACE org.apache.axiom.om.impl.builder.StAXOMBuilder  -   QName: {http://schemas.xmlsoap.org/soap/envelope/}Body
2009-10-26 16:47:41,916 [http-8080-1] DEBUG org.apache.axiom.om.impl.MTOMXMLStreamWriter  - Calling MTOMXMLStreamWriter.flush
2009-10-26 16:47:41,916 [http-8080-1] INFO  userguide.loggingmodule.LogHandler  - <?xml version='1.0' encoding='utf-8'?><soapenv:Envelope xmlns:soapenv="http://schemas.xmlsoap.org/soap/envelope/"><soapenv:Body><main:getDrugByDrugId xmlns:main="http://main.axis2.sil"><main:param0>20040607010594</main:param0><main:param1>false</main:param1><main:param2>-1</main:param2></main:getDrugByDrugId></soapenv:Body></soapenv:Envelope>
2009-10-26 16:47:41,916 [http-8080-1] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:64F72C5F5C41FBA2071256572089445] Checking post-conditions for phase "loggingPhase"
2009-10-26 16:47:41,916 [http-8080-1] TRACE org.apache.axis2.addressing.EndpointReference  - hasAnonymousAddress: http://www.w3.org/2005/08/addressing/anonymous is Anonymous: true
2009-10-26 16:47:41,932 [http-8080-1] TRACE org.apache.axis2.addressing.EndpointReference  - hasAnonymousAddress: http://www.w3.org/2005/08/addressing/anonymous is Anonymous: true
2009-10-26 16:47:41,932 [http-8080-1] DEBUG org.apache.axis2.context.ConfigurationContext  - messageID is null.
2009-10-26 16:47:41,932 [http-8080-1] DEBUG org.apache.axiom.om.util.OMXMLStreamReaderValidator  - An END_ELEMENT event for {http://main.axis2.sil}getDrugByDrugId was encountered.  But this does match the corresponding START_ELEMENT {http://main.axis2.sil}param2 event.
2009-10-26 16:47:41,995 [http-8080-1] TRACE org.apache.axis2.engine.AxisEngine  - [MessageContext: logID=urn:uuid:64F72C5F5C41FBA2071256572089525] send:null
2009-10-26 16:47:41,995 [http-8080-1] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:64F72C5F5C41FBA2071256572089525] Checking pre-condition for Phase "loggingPhase"
2009-10-26 16:47:41,995 [http-8080-1] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:64F72C5F5C41FBA2071256572089525] Invoking phase "loggingPhase"
2009-10-26 16:47:41,995 [http-8080-1] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:64F72C5F5C41FBA2071256572089525] Invoking Handler 'null' in Phase 'loggingPhase'
2009-10-26 16:47:41,995 [http-8080-1] DEBUG org.apache.axiom.om.util.StAXUtils  - XMLStreamWriter is com.ctc.wstx.sw.SimpleNsStreamWriter
2009-10-26 16:47:41,995 [http-8080-1] TRACE org.apache.axiom.om.impl.MTOMXMLStreamWriter  - Call Stack =DEBUG_FRAME = org.apache.axiom.om.util.CommonUtils.callStackToString(CommonUtils.java:80)
    DEBUG_FRAME = org.apache.axiom.om.impl.MTOMXMLStreamWriter.<init>(MTOMXMLStreamWriter.java:74)
    DEBUG_FRAME = org.apache.axiom.om.impl.llom.OMNodeImpl.serialize(OMNodeImpl.java:384)
    DEBUG_FRAME = org.apache.axiom.om.impl.llom.OMElementImpl.toString(OMElementImpl.java:1106)
    DEBUG_FRAME = userguide.loggingmodule.LogHandler.invoke(Unknown Source)
    DEBUG_FRAME = org.apache.axis2.engine.Phase.invoke(Phase.java:318)
    DEBUG_FRAME = org.apache.axis2.engine.AxisEngine.invoke(AxisEngine.java:251)
    DEBUG_FRAME = org.apache.axis2.engine.AxisEngine.send(AxisEngine.java:416)
    DEBUG_FRAME = org.apache.axis2.receivers.AbstractInOutMessageReceiver.invokeBusinessLogic(AbstractInOutMessageReceiver.java:43)
    DEBUG_FRAME = org.apache.axis2.receivers.AbstractMessageReceiver.receive(AbstractMessageReceiver.java:114)
    DEBUG_FRAME = org.apache.axis2.engine.AxisEngine.receive(AxisEngine.java:173)
    DEBUG_FRAME = org.apache.axis2.transport.http.HTTPTransportUtils.processHTTPPostRequest(HTTPTransportUtils.java:167)
    DEBUG_FRAME = org.apache.axis2.transport.http.AxisServlet.doPost(AxisServlet.java:142)
    DEBUG_FRAME = javax.servlet.http.HttpServlet.service(HttpServlet.java:637)
    DEBUG_FRAME = javax.servlet.http.HttpServlet.service(HttpServlet.java:717)
    DEBUG_FRAME = org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:290)
    DEBUG_FRAME = org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
    DEBUG_FRAME = org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:233)
    DEBUG_FRAME = org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:191)
    DEBUG_FRAME = org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:128)
    DEBUG_FRAME = org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102)
    DEBUG_FRAME = org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109)
    DEBUG_FRAME = org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:293)
    DEBUG_FRAME = org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:849)
    DEBUG_FRAME = org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:583)
    DEBUG_FRAME = org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:454)
    DEBUG_FRAME = java.lang.Thread.run(Thread.java:619)

2009-10-26 16:47:41,995 [http-8080-1] DEBUG org.apache.axiom.om.impl.MTOMXMLStreamWriter  - Calling MTOMXMLStreamWriter.flush
2009-10-26 16:47:41,995 [http-8080-1] DEBUG org.apache.axiom.om.impl.MTOMXMLStreamWriter  - Calling MTOMXMLStreamWriter.flush
2009-10-26 16:47:41,995 [http-8080-1] INFO  userguide.loggingmodule.LogHandler  - <?xml version='1.0' encoding='utf-8'?><soapenv:Envelope xmlns:soapenv="http://schemas.xmlsoap.org/soap/envelope/"><soapenv:Body><ns1:getDrugByDrugIdResponse xmlns:ns1="http://main.axis2.sil"><ns1:return><ns1:drugId>20040607010594</ns1:drugId><ns1:tradeName>Ramipril Durascan</ns1:tradeName><ns1:strengthNumeric>1.25</ns1:strengthNumeric><ns1:strengthNumericUnit>mg</ns1:strengthNumericUnit><ns1:strengthText>1,25 mg</ns1:strengthText><ns1:drugFormCode>CAPHAR</ns1:drugFormCode><ns1:drugFormTextSv>Kapsel, hård</ns1:drugFormTextSv><ns1:drugClassificationCode>-</ns1:drugClassificationCode><ns1:controlClassCode>0</ns1:controlClassCode><ns1:routeOfAdministrationCodes>-</ns1:routeOfAdministrationCodes><ns1:prescriberCodes>1</ns1:prescriberCodes><ns1:interchangeableFlag>N</ns1:interchangeableFlag><ns1:substanceGroupId>0</ns1:substanceGroupId><ns1:substanceGroupName></ns1:substanceGroupName><ns1:strengthGroupId>0</ns1:strengthGroupId><ns1:strengthGroupName></ns1:strengthGroupName><ns1:pharmaceuticalFormGroupId>0</ns1:pharmaceuticalFormGroupId><ns1:pharmaceuticalFormGroupName></ns1:pharmaceuticalFormGroupName><ns1:lactationGroup>?</ns1:lactationGroup><ns1:pregnancyCategory>?</ns1:pregnancyCategory><ns1:interactionStatus>1</ns1:interactionStatus><ns1:productTypeCode>MEP</ns1:productTypeCode><ns1:prescriptionCode>1</ns1:prescriptionCode><ns1:withdrawalDate>2005-02-28</ns1:withdrawalDate><ns1:hasRecommendedArticle>false</ns1:hasRecommendedArticle><ns1:silDeviationCode></ns1:silDeviationCode></ns1:return></ns1:getDrugByDrugIdResponse></soapenv:Body></soapenv:Envelope>
2009-10-26 16:47:41,995 [http-8080-1] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:64F72C5F5C41FBA2071256572089525] Checking post-conditions for phase "loggingPhase"
2009-10-26 16:47:41,995 [http-8080-1] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:64F72C5F5C41FBA2071256572089525] Checking pre-condition for Phase "soapmonitorPhase"
2009-10-26 16:47:41,995 [http-8080-1] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:64F72C5F5C41FBA2071256572089525] Invoking phase "soapmonitorPhase"
2009-10-26 16:47:41,995 [http-8080-1] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:64F72C5F5C41FBA2071256572089525] Checking post-conditions for phase "soapmonitorPhase"
2009-10-26 16:47:41,995 [http-8080-1] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:64F72C5F5C41FBA2071256572089525] Checking pre-condition for Phase "OperationOutPhase"
2009-10-26 16:47:41,995 [http-8080-1] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:64F72C5F5C41FBA2071256572089525] Invoking phase "OperationOutPhase"
2009-10-26 16:47:41,995 [http-8080-1] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:64F72C5F5C41FBA2071256572089525] Invoking Handler 'DispatchOperationHandler' in Phase 'OperationOutPhase'
2009-10-26 16:47:41,995 [http-8080-1] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:64F72C5F5C41FBA2071256572089525] Checking post-conditions for phase "OperationOutPhase"
2009-10-26 16:47:41,995 [http-8080-1] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:64F72C5F5C41FBA2071256572089525] Checking pre-condition for Phase "RMPhase"
2009-10-26 16:47:41,995 [http-8080-1] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:64F72C5F5C41FBA2071256572089525] Invoking phase "RMPhase"
2009-10-26 16:47:41,995 [http-8080-1] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:64F72C5F5C41FBA2071256572089525] Checking post-conditions for phase "RMPhase"
2009-10-26 16:47:41,995 [http-8080-1] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:64F72C5F5C41FBA2071256572089525] Checking pre-condition for Phase "PolicyDetermination"
2009-10-26 16:47:41,995 [http-8080-1] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:64F72C5F5C41FBA2071256572089525] Invoking phase "PolicyDetermination"
2009-10-26 16:47:41,995 [http-8080-1] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:64F72C5F5C41FBA2071256572089525] Checking post-conditions for phase "PolicyDetermination"
2009-10-26 16:47:41,995 [http-8080-1] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:64F72C5F5C41FBA2071256572089525] Checking pre-condition for Phase "MessageOut"
2009-10-26 16:47:41,995 [http-8080-1] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:64F72C5F5C41FBA2071256572089525] Invoking phase "MessageOut"
2009-10-26 16:47:41,995 [http-8080-1] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:64F72C5F5C41FBA2071256572089525] Invoking Handler 'AddressingOutHandler' in Phase 'MessageOut'
2009-10-26 16:47:41,995 [http-8080-1] TRACE org.apache.axis2.handlers.addressing.AddressingOutHandler  - [MessageContext: logID=urn:uuid:64F72C5F5C41FBA2071256572089525] Addressing is disabled. Not adding WS-Addressing headers.
2009-10-26 16:47:41,995 [http-8080-1] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:64F72C5F5C41FBA2071256572089525] Checking post-conditions for phase "MessageOut"
2009-10-26 16:47:41,995 [http-8080-1] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:64F72C5F5C41FBA2071256572089525] Checking pre-condition for Phase "Security"
2009-10-26 16:47:41,995 [http-8080-1] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:64F72C5F5C41FBA2071256572089525] Invoking phase "Security"
2009-10-26 16:47:41,995 [http-8080-1] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:64F72C5F5C41FBA2071256572089525] Checking post-conditions for phase "Security"
2009-10-26 16:47:41,995 [http-8080-1] TRACE org.apache.axis2.addressing.EndpointReference  - hasAnonymousAddress: http://www.w3.org/2005/08/addressing/anonymous is Anonymous: true
2009-10-26 16:47:41,995 [http-8080-1] DEBUG org.apache.axiom.om.OMOutputFormat  - Start getContentType: OMOutputFormat [ mimeBoundary =null rootContentId=null doOptimize=false doingSWA=false isSOAP11=true charSetEncoding=UTF-8 xmlVersion=null contentType=null ignoreXmlDeclaration=false autoCloseWriter=true actionProperty=null optimizedThreshold=0]
2009-10-26 16:47:42,010 [http-8080-1] DEBUG org.apache.axiom.om.OMOutputFormat  - getContentType= {text/xml}   OMOutputFormat [ mimeBoundary =null rootContentId=null doOptimize=false doingSWA=false isSOAP11=true charSetEncoding=UTF-8 xmlVersion=null contentType=text/xml ignoreXmlDeclaration=false autoCloseWriter=true actionProperty=null optimizedThreshold=0]
2009-10-26 16:47:42,010 [http-8080-1] DEBUG org.apache.axis2.transport.http.SOAPMessageFormatter  - contentType from the OMOutputFormat =text/xml
2009-10-26 16:47:42,010 [http-8080-1] DEBUG org.apache.axis2.transport.http.SOAPMessageFormatter  - contentType returned =text/xml; charset=UTF-8
2009-10-26 16:47:42,010 [http-8080-1] DEBUG org.apache.axis2.transport.http.SOAPMessageFormatter  - start writeTo()
2009-10-26 16:47:42,010 [http-8080-1] DEBUG org.apache.axis2.transport.http.SOAPMessageFormatter  -   preserve=false
2009-10-26 16:47:42,010 [http-8080-1] DEBUG org.apache.axis2.transport.http.SOAPMessageFormatter  -   isOptimized=false
2009-10-26 16:47:42,010 [http-8080-1] DEBUG org.apache.axis2.transport.http.SOAPMessageFormatter  -   isDoingSWA=false
2009-10-26 16:47:42,010 [http-8080-1] DEBUG org.apache.axis2.util.Utils  - MTOM optimized Threshold value =0
2009-10-26 16:47:42,010 [http-8080-1] DEBUG org.apache.axiom.om.impl.MTOMXMLStreamWriter  - OutputStream =class java.io.BufferedOutputStream
2009-10-26 16:47:42,010 [http-8080-1] DEBUG org.apache.axiom.om.impl.MTOMXMLStreamWriter  - OMFormat = OMOutputFormat [ mimeBoundary =null rootContentId=null doOptimize=false doingSWA=false isSOAP11=true charSetEncoding=UTF-8 xmlVersion=null contentType=text/xml ignoreXmlDeclaration=false autoCloseWriter=true actionProperty=null optimizedThreshold=0]
2009-10-26 16:47:42,010 [http-8080-1] TRACE org.apache.axiom.om.impl.MTOMXMLStreamWriter  - Call Stack =DEBUG_FRAME = org.apache.axiom.om.util.CommonUtils.callStackToString(CommonUtils.java:80)
    DEBUG_FRAME = org.apache.axiom.om.impl.MTOMXMLStreamWriter.<init>(MTOMXMLStreamWriter.java:94)
    DEBUG_FRAME = org.apache.axiom.om.impl.llom.OMNodeImpl.serializeAndConsume(OMNodeImpl.java:485)
    DEBUG_FRAME = org.apache.axis2.transport.http.SOAPMessageFormatter.writeTo(SOAPMessageFormatter.java:79)
    DEBUG_FRAME = org.apache.axis2.transport.http.CommonsHTTPTransportSender.sendUsingOutputStream(CommonsHTTPTransportSender.java:358)
    DEBUG_FRAME = org.apache.axis2.transport.http.CommonsHTTPTransportSender.invoke(CommonsHTTPTransportSender.java:235)
    DEBUG_FRAME = org.apache.axis2.engine.AxisEngine.send(AxisEngine.java:435)
    DEBUG_FRAME = org.apache.axis2.receivers.AbstractInOutMessageReceiver.invokeBusinessLogic(AbstractInOutMessageReceiver.java:43)
    DEBUG_FRAME = org.apache.axis2.receivers.AbstractMessageReceiver.receive(AbstractMessageReceiver.java:114)
    DEBUG_FRAME = org.apache.axis2.engine.AxisEngine.receive(AxisEngine.java:173)
    DEBUG_FRAME = org.apache.axis2.transport.http.HTTPTransportUtils.processHTTPPostRequest(HTTPTransportUtils.java:167)
    DEBUG_FRAME = org.apache.axis2.transport.http.AxisServlet.doPost(AxisServlet.java:142)
    DEBUG_FRAME = javax.servlet.http.HttpServlet.service(HttpServlet.java:637)
    DEBUG_FRAME = javax.servlet.http.HttpServlet.service(HttpServlet.java:717)
    DEBUG_FRAME = org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:290)
    DEBUG_FRAME = org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
    DEBUG_FRAME = org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:233)
    DEBUG_FRAME = org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:191)
    DEBUG_FRAME = org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:128)
    DEBUG_FRAME = org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102)
    DEBUG_FRAME = org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109)
    DEBUG_FRAME = org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:293)
    DEBUG_FRAME = org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:849)
    DEBUG_FRAME = org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:583)
    DEBUG_FRAME = org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:454)
    DEBUG_FRAME = java.lang.Thread.run(Thread.java:619)

2009-10-26 16:47:42,010 [http-8080-1] DEBUG org.apache.axiom.om.util.StAXUtils  - XMLStreamWriter is com.ctc.wstx.sw.SimpleNsStreamWriter
2009-10-26 16:47:42,010 [http-8080-1] DEBUG org.apache.axiom.om.impl.llom.OMSourcedElementImpl  - serialize {http://main.axis2.sil}getDrugByDrugIdResponse to XMLStreamWriter
2009-10-26 16:47:42,010 [http-8080-1] DEBUG org.apache.axiom.om.impl.MTOMXMLStreamWriter  - Calling MTOMXMLStreamWriter.flush
2009-10-26 16:47:42,010 [http-8080-1] DEBUG org.apache.axiom.om.impl.MTOMXMLStreamWriter  - Calling MTOMXMLStreamWriter.flush
2009-10-26 16:47:42,010 [http-8080-1] DEBUG org.apache.axiom.om.impl.MTOMXMLStreamWriter  - close
2009-10-26 16:47:42,010 [http-8080-1] DEBUG org.apache.axis2.transport.http.SOAPMessageFormatter  - end writeTo()
2009-10-26 16:47:42,010 [http-8080-1] DEBUG org.apache.axis2.transport.TransportUtils  - Found RequestResponseTransport setting response written
2009-10-26 16:47:42,010 [http-8080-1] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:64F72C5F5C41FBA2071256572089525] Invoking flowComplete() in Phase "Security"
2009-10-26 16:47:42,010 [http-8080-1] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:64F72C5F5C41FBA2071256572089525] Invoking flowComplete() in Phase "MessageOut"
2009-10-26 16:47:42,010 [http-8080-1] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:64F72C5F5C41FBA2071256572089525] Invoking flowComplete() for Handler 'AddressingOutHandler' in Phase 'MessageOut'
2009-10-26 16:47:42,010 [http-8080-1] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:64F72C5F5C41FBA2071256572089525] Invoking flowComplete() in Phase "PolicyDetermination"
2009-10-26 16:47:42,010 [http-8080-1] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:64F72C5F5C41FBA2071256572089525] Invoking flowComplete() in Phase "RMPhase"
2009-10-26 16:47:42,010 [http-8080-1] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:64F72C5F5C41FBA2071256572089525] Invoking flowComplete() in Phase "OperationOutPhase"
2009-10-26 16:47:42,010 [http-8080-1] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:64F72C5F5C41FBA2071256572089525] Invoking flowComplete() for Handler 'DispatchOperationHandler' in Phase 'OperationOutPhase'
2009-10-26 16:47:42,010 [http-8080-1] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:64F72C5F5C41FBA2071256572089525] Invoking flowComplete() in Phase "soapmonitorPhase"
2009-10-26 16:47:42,010 [http-8080-1] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:64F72C5F5C41FBA2071256572089525] Invoking flowComplete() in Phase "loggingPhase"
2009-10-26 16:47:42,010 [http-8080-1] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:64F72C5F5C41FBA2071256572089525] Invoking flowComplete() for Handler 'null' in Phase 'loggingPhase'
2009-10-26 16:47:42,010 [http-8080-1] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:64F72C5F5C41FBA2071256572089445] Invoking flowComplete() in Phase "loggingPhase"
2009-10-26 16:47:42,010 [http-8080-1] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:64F72C5F5C41FBA2071256572089445] Invoking flowComplete() for Handler 'null' in Phase 'loggingPhase'
2009-10-26 16:47:42,010 [http-8080-1] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:64F72C5F5C41FBA2071256572089445] Invoking flowComplete() in Phase "soapmonitorPhase"
2009-10-26 16:47:42,010 [http-8080-1] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:64F72C5F5C41FBA2071256572089445] Invoking flowComplete() in Phase "OperationInPhase"
2009-10-26 16:47:42,010 [http-8080-1] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:64F72C5F5C41FBA2071256572089445] Invoking flowComplete() for Handler 'MustUnderstandChecker' in Phase 'OperationInPhase'
2009-10-26 16:47:42,010 [http-8080-1] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:64F72C5F5C41FBA2071256572089445] Invoking flowComplete() in Phase "RMPhase"
2009-10-26 16:47:42,010 [http-8080-1] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:64F72C5F5C41FBA2071256572089445] Invoking flowComplete() in Phase "Dispatch"
2009-10-26 16:47:42,010 [http-8080-1] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:64F72C5F5C41FBA2071256572089445] Invoking flowComplete() for Handler 'MustUnderstandValidationDispatcher' in Phase 'Dispatch'
2009-10-26 16:47:42,010 [http-8080-1] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:64F72C5F5C41FBA2071256572089445] Invoking flowComplete() for Handler 'GenericProviderDispatcher' in Phase 'Dispatch'
2009-10-26 16:47:42,010 [http-8080-1] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:64F72C5F5C41FBA2071256572089445] Invoking flowComplete() for Handler 'HTTPLocationBasedDispatcher' in Phase 'Dispatch'
2009-10-26 16:47:42,010 [http-8080-1] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:64F72C5F5C41FBA2071256572089445] Invoking flowComplete() for Handler 'AddressingValidationHandler' in Phase 'Dispatch'
2009-10-26 16:47:42,010 [http-8080-1] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:64F72C5F5C41FBA2071256572089445] Invoking flowComplete() for Handler 'SOAPMessageBodyBasedDispatcher' in Phase 'Dispatch'
2009-10-26 16:47:42,010 [http-8080-1] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:64F72C5F5C41FBA2071256572089445] Invoking flowComplete() for Handler 'RequestURIOperationDispatcher' in Phase 'Dispatch'
2009-10-26 16:47:42,010 [http-8080-1] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:64F72C5F5C41FBA2071256572089445] Invoking flowComplete() for Handler 'SOAPActionBasedDispatcher' in Phase 'Dispatch'
2009-10-26 16:47:42,010 [http-8080-1] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:64F72C5F5C41FBA2071256572089445] Invoking flowComplete() for Handler 'RequestURIBasedDispatcher' in Phase 'Dispatch'
2009-10-26 16:47:42,010 [http-8080-1] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:64F72C5F5C41FBA2071256572089445] Invoking flowComplete() in Phase "PreDispatch"
2009-10-26 16:47:42,010 [http-8080-1] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:64F72C5F5C41FBA2071256572089445] Invoking flowComplete() in Phase "Security"
2009-10-26 16:47:42,010 [http-8080-1] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:64F72C5F5C41FBA2071256572089445] Invoking flowComplete() in Phase "Addressing"
2009-10-26 16:47:42,010 [http-8080-1] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:64F72C5F5C41FBA2071256572089445] Invoking flowComplete() for Handler 'AddressingBasedDispatcher' in Phase 'Addressing'
2009-10-26 16:47:42,010 [http-8080-1] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:64F72C5F5C41FBA2071256572089445] Invoking flowComplete() for Handler 'AddressingInHandler' in Phase 'Addressing'
2009-10-26 16:47:42,010 [http-8080-1] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:64F72C5F5C41FBA2071256572089445] Invoking flowComplete() in Phase "Transport"
2009-10-26 16:47:42,010 [http-8080-1] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:64F72C5F5C41FBA2071256572089445] Invoking flowComplete() for Handler 'SOAPActionBasedDispatcher' in Phase 'Transport'
2009-10-26 16:47:42,010 [http-8080-1] DEBUG org.apache.axis2.engine.Phase  - [MessageContext: logID=urn:uuid:64F72C5F5C41FBA2071256572089445] Invoking flowComplete() for Handler 'RequestURIBasedDispatcher' in Phase 'Transport'
2009-10-26 16:47:42,010 [http-8080-1] DEBUG org.apache.axis2.transport.TransportUtils  - Found RequestResponseTransport returning isResponseWritten()
2009-10-26 16:47:42,010 [http-8080-1] DEBUG org.apache.axis2.transport.TransportUtils  - Entering deleteAttachments()
2009-10-26 16:47:42,010 [http-8080-1] DEBUG org.apache.axis2.transport.TransportUtils  - Exiting deleteAttachments()









 		 	   		  
_________________________________________________________________
Windows Live: Keep your friends up to date with what you do online.
http://www.microsoft.com/middleeast/windows/windowslive/see-it-in-action/social-network-basics.aspx?ocid=PID23461::T:WLMTAGL:ON:WL:en-xm:SI_SB_1:092010
Mime
View raw message