You are viewing a plain text version of this content. The canonical link for it is here.
Posted to java-user@axis.apache.org by "Menzner, Rainer" <RM...@l1id.com> on 2011/06/24 09:43:31 UTC
Howto get extended log information in case of ClientAbortException
Hi everyone,
occasionally, when processing a client request takes too long time, the client runs into a timeout condition and closes the connection. When the Axis2 web service later tries to send the request response, the following kind of exception occurs on the server:
09:03:50,932 ERROR [AxisEngine]
org.apache.axis2.AxisFault
at org.apache.axis2.AxisFault.makeFault(AxisFault.java:430)
at org.apache.axis2.transport.http.SOAPMessageFormatter.writeTo(SOAPMessageFormatter.java:83)
at org.apache.axis2.transport.http.CommonsHTTPTransportSender.sendUsingOutputStream(CommonsHTTPTransportSender.java:358)
[snip]
at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:598)
at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:447)
at java.lang.Thread.run(Thread.java:619)
Caused by: com.ctc.wstx.exc.WstxIOException: null
at com.ctc.wstx.sw.BaseStreamWriter.flush(BaseStreamWriter.java:313)
at org.apache.axiom.om.impl.MTOMXMLStreamWriter.flush(MTOMXMLStreamWriter.java:168)
at org.apache.axiom.om.impl.llom.OMNodeImpl.serializeAndConsume(OMNodeImpl.java:487)
at org.apache.axis2.transport.http.SOAPMessageFormatter.writeTo(SOAPMessageFormatter.java:79)
... 30 more
Caused by: ClientAbortException: java.net.SocketException: Software caused connection abort: socket write error
at org.apache.catalina.connector.OutputBuffer.doFlush(OutputBuffer.java:348)
at org.apache.catalina.connector.OutputBuffer.flush(OutputBuffer.java:314)
at org.apache.catalina.connector.CoyoteOutputStream.flush(CoyoteOutputStream.java:98)
at java.io.BufferedOutputStream.flush(BufferedOutputStream.java:124)
at com.ctc.wstx.io.UTF8Writer.flush(UTF8Writer.java:99)
at com.ctc.wstx.sw.BufferingXmlWriter.flush(BufferingXmlWriter.java:214)
at com.ctc.wstx.sw.BaseStreamWriter.flush(BaseStreamWriter.java:311)
... 33 more
Caused by: java.net.SocketException: Software caused connection abort: socket write error
at java.net.SocketOutputStream.socketWrite0(Native Method)
at java.net.SocketOutputStream.socketWrite(SocketOutputStream.java:92)
at java.net.SocketOutputStream.write(SocketOutputStream.java:136)
at org.apache.coyote.http11.InternalOutputBuffer.realWriteBytes(InternalOutputBuffer.java:724)
at org.apache.tomcat.util.buf.ByteChunk.flushBuffer(ByteChunk.java:449)
at org.apache.coyote.http11.InternalOutputBuffer.flush(InternalOutputBuffer.java:299)
at org.apache.coyote.http11.Http11Processor.action(Http11Processor.java:950)
at org.apache.coyote.Response.action(Response.java:186)
at org.apache.catalina.connector.OutputBuffer.doFlush(OutputBuffer.java:343)
... 39 more
Unfortunately, this kind of exception does not provide any information about which request was unable to complete in time.
In our web service we have some further information like a Request Context which has info about request type, user, a context-Id, ip-address, etc., and we would like to have that info printed somewhere in the logs so that we can identify the requests or circumstances under which the service is prone to run out of time. Now, that exception occurs about at the end of processing, at least, beyond our web service implementation code, and also outside the compiled Axis2-generated stub classes.
Is there an option of registering a particular handler that could print some more log information at that very late point in processing? I have looked through axis2.xml and into the phase definitions but I don't have an idea where to add a handler or if this is possible at all.
I would appreciate any feedback and thoughts on this.
We are currently using Axis2 1.5.1 (Java) deployed in a JBoss 5.1.0 under Windows 7 (but I don't think this matters).
Thanks,
-Rainer
RE: Howto get extended log information in case of
ClientAbortException
Posted by "Menzner, Rainer" <RM...@l1id.com>.
Guys,
in the meantime I found the following solution for us to be acceptable:
1. By exploiting the named properties in the In-Message-Context, the WS method implementations put everything required to do application-specific logging into the Axis2 In-Message-Context
2. The default Axis2 HTTP transport sender is wrapped by an application specific class inheriting from the original Axis2 transport sender. The new class' invoke()-method is a wrapper around the base class' invoke method which catches transport level exceptions and does appropriate logging.
3. The inherited application specific class is activated by editing axis2.xml and adjusting the <transportSender>-nodes for HTTP and HTTPS correspondingly.
That seems to work so far thanks to Axis2 flexible handler concepts. And it also works properly for the case of occurring SOAP faults.
Thanks,
-Rainer
From: Stadelmann Josef [mailto:josef.stadelmann@axa-winterthur.ch]
Sent: Monday, June 27, 2011 9:20 AM
To: java-user@axis.apache.org
Subject: AW: Howto get extended log information in case of ClientAbortException
Gentlemen's
I cannot give you just out of pocket a precise answer, but maybe some idea about how to approach.
The issue is most then same: where are the boundaries?
In this case I can see about 3 boundaries:
a) Your web service method - must be able to log the time of entrance into a method and the completion or exit from that method
b) Your axis2/J is a servlet - is a message process in engine, has phases, etc. - it should be able to log the time of entrance at phase-1-incomming and completion of a phase XYZ-incoming (message-receiver) and it should log phase-1-outgoing and phase-XYZ-outgoing
c) Your web application server running on top of a JVM, it physically receives the message, takes it from the wire, and calls the proper servlet - axis2 - hence calling and completing of the servlet axis2 should be logged, taking the message from the wire and completing putting the message to the wire should be logged as well.
I have configured Tomcat AS to use log4j, and using Chainsaw (log4j) and a sockethubappender I can see all the loggers Tomcat uses.
Axis2 has some defined loggers as well, i.e. the deployment engine logs when a axis2 web service is deployed, and there are more i.e. addressing
And finally we are logging each time when a request hits one of our long lasting session service objects (instance of the service class, state-full-web-service-object in scope="soapsession"), and we log the time at which the method completes.
Putting this 6 message into a sequence of an interaction-frame gives you about the information what happens, what should happen.
The message
1. has received at AS-incoming
2. has received at Axi2 Phase XYZ-incoming
3. has received at Method M1
4. has completed Method M1
5. has completed at Axis2 Phase XYZ-outgoing
6. has completed at AS outgoing
And now I think the questions have to go to 3 forums
1. The AS Forum how to log incoming request
2. The Axis2 Forum how to log start and completion of phases
3. Your own forum :) how to log start and completion of method
And you need to be able to have a consistent message-Id from client to service-method and back.
So far my thoughts at the moment, and I agree, it could be more consistent and more easy to handle, and less varying concepts.
Also be aware that unhandled exceptions are logged in the AS main log file, so out from experience it is always good to know where your various log files are and what they are able to log.
Josef
Von: Menzner, Rainer [mailto:RMenzner@l1id.com]
Gesendet: Freitag, 24. Juni 2011 09:44
An: axis-user@ws.apache.org
Betreff: Howto get extended log information in case of ClientAbortException
Hi everyone,
occasionally, when processing a client request takes too long time, the client runs into a timeout condition and closes the connection. When the Axis2 web service later tries to send the request response, the following kind of exception occurs on the server:
09:03:50,932 ERROR [AxisEngine]
org.apache.axis2.AxisFault
at org.apache.axis2.AxisFault.makeFault(AxisFault.java:430)
at org.apache.axis2.transport.http.SOAPMessageFormatter.writeTo(SOAPMessageFormatter.java:83)
at org.apache.axis2.transport.http.CommonsHTTPTransportSender.sendUsingOutputStream(CommonsHTTPTransportSender.java:358)
[snip]
at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:598)
at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:447)
at java.lang.Thread.run(Thread.java:619)
Caused by: com.ctc.wstx.exc.WstxIOException: null
at com.ctc.wstx.sw.BaseStreamWriter.flush(BaseStreamWriter.java:313)
at org.apache.axiom.om.impl.MTOMXMLStreamWriter.flush(MTOMXMLStreamWriter.java:168)
at org.apache.axiom.om.impl.llom.OMNodeImpl.serializeAndConsume(OMNodeImpl.java:487)
at org.apache.axis2.transport.http.SOAPMessageFormatter.writeTo(SOAPMessageFormatter.java:79)
... 30 more
Caused by: ClientAbortException: java.net.SocketException: Software caused connection abort: socket write error
at org.apache.catalina.connector.OutputBuffer.doFlush(OutputBuffer.java:348)
at org.apache.catalina.connector.OutputBuffer.flush(OutputBuffer.java:314)
at org.apache.catalina.connector.CoyoteOutputStream.flush(CoyoteOutputStream.java:98)
at java.io.BufferedOutputStream.flush(BufferedOutputStream.java:124)
at com.ctc.wstx.io.UTF8Writer.flush(UTF8Writer.java:99)
at com.ctc.wstx.sw.BufferingXmlWriter.flush(BufferingXmlWriter.java:214)
at com.ctc.wstx.sw.BaseStreamWriter.flush(BaseStreamWriter.java:311)
... 33 more
Caused by: java.net.SocketException: Software caused connection abort: socket write error
at java.net.SocketOutputStream.socketWrite0(Native Method)
at java.net.SocketOutputStream.socketWrite(SocketOutputStream.java:92)
at java.net.SocketOutputStream.write(SocketOutputStream.java:136)
at org.apache.coyote.http11.InternalOutputBuffer.realWriteBytes(InternalOutputBuffer.java:724)
at org.apache.tomcat.util.buf.ByteChunk.flushBuffer(ByteChunk.java:449)
at org.apache.coyote.http11.InternalOutputBuffer.flush(InternalOutputBuffer.java:299)
at org.apache.coyote.http11.Http11Processor.action(Http11Processor.java:950)
at org.apache.coyote.Response.action(Response.java:186)
at org.apache.catalina.connector.OutputBuffer.doFlush(OutputBuffer.java:343)
... 39 more
Unfortunately, this kind of exception does not provide any information about which request was unable to complete in time.
In our web service we have some further information like a Request Context which has info about request type, user, a context-Id, ip-address, etc., and we would like to have that info printed somewhere in the logs so that we can identify the requests or circumstances under which the service is prone to run out of time. Now, that exception occurs about at the end of processing, at least, beyond our web service implementation code, and also outside the compiled Axis2-generated stub classes.
Is there an option of registering a particular handler that could print some more log information at that very late point in processing? I have looked through axis2.xml and into the phase definitions but I don't have an idea where to add a handler or if this is possible at all.
I would appreciate any feedback and thoughts on this.
We are currently using Axis2 1.5.1 (Java) deployed in a JBoss 5.1.0 under Windows 7 (but I don't think this matters).
Thanks,
-Rainer
AW: Howto get extended log information in case of ClientAbortException
Posted by Stadelmann Josef <jo...@axa-winterthur.ch>.
Gentlemen's
I cannot give you just out of pocket a precise answer, but maybe some
idea about how to approach.
The issue is most then same: where are the boundaries?
In this case I can see about 3 boundaries:
a) Your web service method - must be able to log the time of
entrance into a method and the completion or exit from that method
b) Your axis2/J is a servlet - is a message process in engine, has
phases, etc. - it should be able to log the time of entrance at
phase-1-incomming and completion of a phase XYZ-incoming
(message-receiver) and it should log phase-1-outgoing and
phase-XYZ-outgoing
c) Your web application server running on top of a JVM, it
physically receives the message, takes it from the wire, and calls the
proper servlet - axis2 - hence calling and completing of the servlet
axis2 should be logged, taking the message from the wire and completing
putting the message to the wire should be logged as well.
I have configured Tomcat AS to use log4j, and using Chainsaw (log4j)
and a sockethubappender I can see all the loggers Tomcat uses.
Axis2 has some defined loggers as well, i.e. the deployment engine logs
when a axis2 web service is deployed, and there are more i.e. addressing
And finally we are logging each time when a request hits one of our long
lasting session service objects (instance of the service class,
state-full-web-service-object in scope="soapsession"), and we log the
time at which the method completes.
Putting this 6 message into a sequence of an interaction-frame gives you
about the information what happens, what should happen.
The message
1. has received at AS-incoming
2. has received at Axi2 Phase XYZ-incoming
3. has received at Method M1
4. has completed Method M1
5. has completed at Axis2 Phase XYZ-outgoing
6. has completed at AS outgoing
And now I think the questions have to go to 3 forums
1. The AS Forum how to log incoming request
2. The Axis2 Forum how to log start and completion of phases
3. Your own forum J how to log start and completion of method
And you need to be able to have a consistent message-Id from client to
service-method and back.
So far my thoughts at the moment, and I agree, it could be more
consistent and more easy to handle, and less varying concepts.
Also be aware that unhandled exceptions are logged in the AS main log
file, so out from experience it is always good to know where your
various log files are and what they are able to log.
Josef
Von: Menzner, Rainer [mailto:RMenzner@l1id.com]
Gesendet: Freitag, 24. Juni 2011 09:44
An: axis-user@ws.apache.org
Betreff: Howto get extended log information in case of
ClientAbortException
Hi everyone,
occasionally, when processing a client request takes too long time, the
client runs into a timeout condition and closes the connection. When the
Axis2 web service later tries to send the request response, the
following kind of exception occurs on the server:
09:03:50,932 ERROR [AxisEngine]
org.apache.axis2.AxisFault
at org.apache.axis2.AxisFault.makeFault(AxisFault.java:430)
at
org.apache.axis2.transport.http.SOAPMessageFormatter.writeTo(SOAPMessage
Formatter.java:83)
at
org.apache.axis2.transport.http.CommonsHTTPTransportSender.sendUsingOutp
utStream(CommonsHTTPTransportSender.java:358)
[snip]
at
org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(
Http11Protocol.java:598)
at
org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:447)
at java.lang.Thread.run(Thread.java:619)
Caused by: com.ctc.wstx.exc.WstxIOException: null
at
com.ctc.wstx.sw.BaseStreamWriter.flush(BaseStreamWriter.java:313)
at
org.apache.axiom.om.impl.MTOMXMLStreamWriter.flush(MTOMXMLStreamWriter.j
ava:168)
at
org.apache.axiom.om.impl.llom.OMNodeImpl.serializeAndConsume(OMNodeImpl.
java:487)
at
org.apache.axis2.transport.http.SOAPMessageFormatter.writeTo(SOAPMessage
Formatter.java:79)
... 30 more
Caused by: ClientAbortException: java.net.SocketException: Software
caused connection abort: socket write error
at
org.apache.catalina.connector.OutputBuffer.doFlush(OutputBuffer.java:348
)
at
org.apache.catalina.connector.OutputBuffer.flush(OutputBuffer.java:314)
at
org.apache.catalina.connector.CoyoteOutputStream.flush(CoyoteOutputStrea
m.java:98)
at
java.io.BufferedOutputStream.flush(BufferedOutputStream.java:124)
at com.ctc.wstx.io.UTF8Writer.flush(UTF8Writer.java:99)
at
com.ctc.wstx.sw.BufferingXmlWriter.flush(BufferingXmlWriter.java:214)
at
com.ctc.wstx.sw.BaseStreamWriter.flush(BaseStreamWriter.java:311)
... 33 more
Caused by: java.net.SocketException: Software caused connection abort:
socket write error
at java.net.SocketOutputStream.socketWrite0(Native Method)
at
java.net.SocketOutputStream.socketWrite(SocketOutputStream.java:92)
at java.net.SocketOutputStream.write(SocketOutputStream.java:136)
at
org.apache.coyote.http11.InternalOutputBuffer.realWriteBytes(InternalOut
putBuffer.java:724)
at
org.apache.tomcat.util.buf.ByteChunk.flushBuffer(ByteChunk.java:449)
at
org.apache.coyote.http11.InternalOutputBuffer.flush(InternalOutputBuffer
.java:299)
at
org.apache.coyote.http11.Http11Processor.action(Http11Processor.java:950
)
at org.apache.coyote.Response.action(Response.java:186)
at
org.apache.catalina.connector.OutputBuffer.doFlush(OutputBuffer.java:343
)
... 39 more
Unfortunately, this kind of exception does not provide any information
about which request was unable to complete in time.
In our web service we have some further information like a Request
Context which has info about request type, user, a context-Id,
ip-address, etc., and we would like to have that info printed somewhere
in the logs so that we can identify the requests or circumstances under
which the service is prone to run out of time. Now, that exception
occurs about at the end of processing, at least, beyond our web service
implementation code, and also outside the compiled Axis2-generated stub
classes.
Is there an option of registering a particular handler that could print
some more log information at that very late point in processing? I have
looked through axis2.xml and into the phase definitions but I don't have
an idea where to add a handler or if this is possible at all.
I would appreciate any feedback and thoughts on this.
We are currently using Axis2 1.5.1 (Java) deployed in a JBoss 5.1.0
under Windows 7 (but I don't think this matters).
Thanks,
-Rainer
Re: Howto get extended log information in case of ClientAbortException
Posted by Charles Galpin <cg...@lhsw.com>.
I'd just like to throw in a "me too". We get this same error occasionally and it would be nice to be able to log some details about it.
But I'll take it one step further - it would be nice to enable logging of the source and url/method of all requests kind of like apache tomcat logs too if possible. I'm guessing this is similar to logging details about the request when it gets the socket write error.
Thanks,
charles
On Jun 24, 2011, at 3:43 AM, Menzner, Rainer wrote:
> Hi everyone,
>
> occasionally, when processing a client request takes too long time, the client runs into a timeout condition and closes the connection. When the Axis2 web service later tries to send the request response, the following kind of exception occurs on the server:
>
> 09:03:50,932 ERROR [AxisEngine]
> org.apache.axis2.AxisFault
> at org.apache.axis2.AxisFault.makeFault(AxisFault.java:430)
> at org.apache.axis2.transport.http.SOAPMessageFormatter.writeTo(SOAPMessageFormatter.java:83)
> at org.apache.axis2.transport.http.CommonsHTTPTransportSender.sendUsingOutputStream(CommonsHTTPTransportSender.java:358)
>
> [snip]
>
> at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:598)
> at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:447)
> at java.lang.Thread.run(Thread.java:619)
> Caused by: com.ctc.wstx.exc.WstxIOException: null
> at com.ctc.wstx.sw.BaseStreamWriter.flush(BaseStreamWriter.java:313)
> at org.apache.axiom.om.impl.MTOMXMLStreamWriter.flush(MTOMXMLStreamWriter.java:168)
> at org.apache.axiom.om.impl.llom.OMNodeImpl.serializeAndConsume(OMNodeImpl.java:487)
> at org.apache.axis2.transport.http.SOAPMessageFormatter.writeTo(SOAPMessageFormatter.java:79)
> ... 30 more
> Caused by: ClientAbortException: java.net.SocketException: Software caused connection abort: socket write error
> at org.apache.catalina.connector.OutputBuffer.doFlush(OutputBuffer.java:348)
> at org.apache.catalina.connector.OutputBuffer.flush(OutputBuffer.java:314)
> at org.apache.catalina.connector.CoyoteOutputStream.flush(CoyoteOutputStream.java:98)
> at java.io.BufferedOutputStream.flush(BufferedOutputStream.java:124)
> at com.ctc.wstx.io.UTF8Writer.flush(UTF8Writer.java:99)
> at com.ctc.wstx.sw.BufferingXmlWriter.flush(BufferingXmlWriter.java:214)
> at com.ctc.wstx.sw.BaseStreamWriter.flush(BaseStreamWriter.java:311)
> ... 33 more
> Caused by: java.net.SocketException: Software caused connection abort: socket write error
> at java.net.SocketOutputStream.socketWrite0(Native Method)
> at java.net.SocketOutputStream.socketWrite(SocketOutputStream.java:92)
> at java.net.SocketOutputStream.write(SocketOutputStream.java:136)
> at org.apache.coyote.http11.InternalOutputBuffer.realWriteBytes(InternalOutputBuffer.java:724)
> at org.apache.tomcat.util.buf.ByteChunk.flushBuffer(ByteChunk.java:449)
> at org.apache.coyote.http11.InternalOutputBuffer.flush(InternalOutputBuffer.java:299)
> at org.apache.coyote.http11.Http11Processor.action(Http11Processor.java:950)
> at org.apache.coyote.Response.action(Response.java:186)
> at org.apache.catalina.connector.OutputBuffer.doFlush(OutputBuffer.java:343)
> ... 39 more
>
>
> Unfortunately, this kind of exception does not provide any information about which request was unable to complete in time.
>
> In our web service we have some further information like a Request Context which has info about request type, user, a context-Id, ip-address, etc., and we would like to have that info printed somewhere in the logs so that we can identify the requests or circumstances under which the service is prone to run out of time. Now, that exception occurs about at the end of processing, at least, beyond our web service implementation code, and also outside the compiled Axis2-generated stub classes.
>
> Is there an option of registering a particular handler that could print some more log information at that very late point in processing? I have looked through axis2.xml and into the phase definitions but I don’t have an idea where to add a handler or if this is possible at all.
>
> I would appreciate any feedback and thoughts on this.
>
> We are currently using Axis2 1.5.1 (Java) deployed in a JBoss 5.1.0 under Windows 7 (but I don’t think this matters).
>
> Thanks,
> -Rainer
>
>
>