Mailing-List: contact dev-help@cxf.apache.org; run by ezmlm
Precedence: bulk
Reply-To: dev@cxf.apache.org
Received-SPF: pass (nike.apache.org: domain of elakito@googlemail.com
 designates 209.85.213.169 as permitted sender)
DomainKey-Signature: a=rsa-sha1; c=nofws;
        d=googlemail.com; s=gamma;
        h=mime-version:date:message-id:subject:from:to:content-type;
        b=ee8Mx/lEXgM3ZWYDmWiKLOGr2RWxXkT4eXunjLnMwaMDPEA169oPmqdEHwE5nYcH+2
         x8p4TxqsLkYztWXccJZoCrn8L7Ki1jAq1G++p9euLI3Ek27lIKrLIQD+Z7FIiGBm9O9Q
         /OeVYS/CQPhebZrZO5F7WJBXaautFEi1YVGMM=
MIME-Version: 1.0
Date: Sat, 18 Jun 2011 00:46:52 +0200
Message-ID: <BANLkTin_RvU8vs2+2owSaMgSQ6AhEuCY1Q@mail.gmail.com>
Subject: Oneway CXF service having problem with Gemini-Web/Tomcat-catalina
From: Aki Yoshida <elakito@googlemail.com>
To: dev@cxf.apache.org
Content-Type: text/plain; charset=ISO-8859-1

Hi,
There seems to be some IO handling problem in oneway CXF services on
equinox with the latest gemini-web.
It think I have identified the cause of the problem and that we could
fix it in CXF. But I would like to get your comments.

The problem happens sporadically for oneway services when the
StaxInInterceptor tries to instantiate the XMLStreamReader from the
InputStream object. In this test scenario, a series of oneway calls
are sequentially sent to a CXF oneway service. And sporadically, some
calls result in the following exception, that is indicating the input
stream is already closed, even though the data should be available in
the stream.

Caused by: java.lang.RuntimeException: Couldn't parse stream.
	at org.apache.cxf.staxutils.StaxUtils.createXMLStreamReader(StaxUtils.java:1143)
~[na:na]
	at org.apache.cxf.interceptor.StaxInInterceptor.handleMessage(StaxInInterceptor.java:105)
~[na:na]
	... 27 common frames omitted
Caused by: com.ctc.wstx.exc.WstxIOException: Stream closed
	at com.ctc.wstx.stax.WstxInputFactory.doCreateSR(WstxInputFactory.java:536)
~[na:na]
	at com.ctc.wstx.stax.WstxInputFactory.createSR(WstxInputFactory.java:585)
~[na:na]
	at com.ctc.wstx.stax.WstxInputFactory.createSR(WstxInputFactory.java:610)
~[na:na]
	at com.ctc.wstx.stax.WstxInputFactory.createXMLStreamReader(WstxInputFactory.java:316)
~[na:na]
	at org.apache.cxf.staxutils.StaxUtils.createXMLStreamReader(StaxUtils.java:1141)
~[na:na]
	... 28 common frames omitted
Caused by: java.io.IOException: Stream closed
	at org.apache.catalina.connector.InputBuffer.read(InputBuffer.java:308)
~[na:na]
	at org.apache.catalina.connector.CoyoteInputStream.read(CoyoteInputStream.java:202)
~[na:na]
	at org.apache.cxf.transport.servlet.LogServletInputStream.read(LogServletInputStream.java:80)
~[na:na]
	at com.ctc.wstx.io.BaseReader.readBytes(BaseReader.java:155) ~[na:na]
	at com.ctc.wstx.io.UTF8Reader.loadMore(UTF8Reader.java:368) ~[na:na]
	at com.ctc.wstx.io.UTF8Reader.read(UTF8Reader.java:111) ~[na:na]
	at com.ctc.wstx.io.ReaderBootstrapper.initialLoad(ReaderBootstrapper.java:250)
~[na:na]
	at com.ctc.wstx.io.ReaderBootstrapper.bootstrapInput(ReaderBootstrapper.java:133)
~[na:na]
	at com.ctc.wstx.stax.WstxInputFactory.doCreateSR(WstxInputFactory.java:531)
~[na:na]

I didn't see this problem with jetty before and started to see this
problem sporadically right after switching to gemini-web.

It seems that the error has something to do with the way in which its
previous call is handled and how the servlet container manages the
stream resources. To investigate this situation, I logged CXF's each
method call into the HttpServletRequest, HttpServetResponse,
ServletInputStream, and ServerOutputStream objects and noticed that
the input stream was always closed by a web container's cleanup thread
instead of the CXF's servlet thread. In contrast, the output stream
was always closed by the CXF servlet thread at
AbstractHTTPDestination's close(). In this method, there is an
interesting code fragment that explains this particular handling for
the oneway case:

        public void close(Message msg) throws IOException {
            super.close(msg);
            if (msg.getExchange() == null) {
                return;
            }
            Message m = msg.getExchange().getInMessage();
            if (m == null || msg.getExchange().isOneWay()) {
                return;
            }
            InputStream is = m.getContent(InputStream.class);
            if (is != null) {
                try {
                    is.close();
                    ...

The intention of the above code was probably to asynchronously read
the input stream later than this point. But if the output stream is
closed and the servlet is returned, there is no guarantee that the
input stream remains available. So, I think we can close the input
stream there. Besides, OneWayProcessorInterceptor is supposed to be
pulling in the entire stream data.

            if (Boolean.FALSE.equals(o)) {
                //need to suck in all the data from the input stream as
                //the transport might discard any data on the stream when this
                //thread unwinds or when the empty response is sent back
                DelegatingInputStream in =
message.get(DelegatingInputStream.class);
                if (in != null) {
                    in.cacheInput();
                }
            }

So, I modified the AbstractHTTPDestination's close method to also
close the input stream upon closing the output stream. And it seems
that the problem is gone. But I am not 100% sure that this might not
be introducing another problem.

My hypothesis is that Gemini-web (tomcat-catalina) closes the input
stream with some non-deterministic behavior that sporadically causes
the input stream of the subsequent call to become closed. I think if
tomcat-cataline always closes the input stream right away after the
call comes back, it will probably also solve this problem.

Should I go ahead to put this change in 2.5 and 2.4.x? Or do you think
we should discuss this issue with the tomcat-cataline people?

Thanks.

Regards, aki