I'm glad this was useful in the end.
Could you send the link to the corresponding issue ? I'd be interesting to
read the commit for the fix and known the tomcat versions this will be
pushed to.
Thanks
2016-11-01 11:08 GMT+01:00 Mark Thomas <ma...@apache.org>:
> On 25/10/2016 09:59, Mark Thomas wrote:
> > Thanks for this.
> >
> > While I haven't had a chance to look into this, there is enough
> > information here to justify opening a bug report. That has the added
> > advantage that it won't get forogtten.
>
> I've found the time to look at this.
>
> There was a bug. While Tomcat did clean up its internal resources
> correctly, it didn't call onError() so the app was never given a chance
> to clean up unless it did so as a result of the original IOException.
>
> The app should call onComplete() from onError() (as required by the
> spec). It it doesn't, that will trigger another error and Tomcat will
> call on onComplete()
>
> This should be fixed in the next set of releases.
>
> Mark
>
>
> >
> > Mark
> >
> >
> > On 18/10/2016 09:55, Thomas Boniface wrote:
> >> Just a small correction, the callback was a bit weird. The correct one
> is
> >> below (but that doesn't impact the behavior of the scenario)
> >>
> >> @Override
> >> public void completed(HttpResponse result) {
> >> try {
> >> try {
> >> Thread.sleep(200);
> >> } catch (InterruptedException e) {
> >> e.printStackTrace();
> >> }
> >>
> >> ServletOutputStream out = res.getOutputStream();
> >> out.print("Hello world");
> >> out.flush();
> >> out.close();
> >> } catch (IOException e) {
> >> } finally {
> >> req.getAsyncContext().complete();
> >> }
> >> }
> >>
> >>
> >> 2016-10-18 10:38 GMT+02:00 Thomas Boniface <tho...@stickyads.tv>:
> >>>
> >>> I think I managed to narrow things down a bit.
> >>>
> >>>
> >>> I managed to reproduced locally the issue (it's not occuring 100% of
> the
> >> time but it appears after a very few attempt for me). I created a really
> >> basic webapps :
> >>>
> >>> package stickyads.tv;
> >>>
> >>> import org.apache.http.HttpResponse;
> >>> import org.apache.http.client.methods.HttpGet;
> >>> import org.apache.http.concurrent.FutureCallback;
> >>> import org.apache.http.impl.nio.client.CloseableHttpAsyncClient;
> >>> import org.apache.http.impl.nio.client.HttpAsyncClients;
> >>>
> >>> import javax.servlet.*;
> >>> import javax.servlet.annotation.WebServlet;
> >>> import java.io.IOException;
> >>>
> >>> @WebServlet(value="/hello", name="helloServlet", asyncSupported = true)
> >>> public class HelloServlet extends GenericServlet {
> >>>
> >>> private static final CloseableHttpAsyncClient httpclient =
> >> HttpAsyncClients.createDefault();
> >>> static {
> >>> httpclient.start();
> >>> }
> >>>
> >>> @Override
> >>> public void service(final ServletRequest req, final ServletResponse
> >> res) throws ServletException, IOException {
> >>> req.startAsync();
> >>>
> >>> HttpGet request = new HttpGet("http://www.apache.org/";);
> >>> httpclient.execute(request, new FutureCallback<HttpResponse>()
> {
> >>> @Override
> >>> public void completed(HttpResponse result) {
> >>> try {
> >>> try {
> >>> Thread.sleep(200);
> >>> } catch (InterruptedException e) {
> >>> e.printStackTrace();
> >>> }
> >>>
> >>> ServletOutputStream out = res.getOutputStream();
> >>> out.print("Hello world");
> >>> out.flush();
> >>> out.close();
> >>> } catch (IOException e) {
> >>> // this will generate an NPE
> >>> req.getAsyncContext().complete();
> >>> }
> >>> }
> >>>
> >>> @Override
> >>> public void failed(Exception ex) {
> >>>
> >>> }
> >>>
> >>> @Override
> >>> public void cancelled() {
> >>>
> >>> }
> >>> });
> >>> }
> >>> }
> >>>
> >>> I deploy the war on tomcat 7.0.72 and then call it using a simple
> python
> >> program that sends a request and closes the requests without waiting
> for a
> >> response:
> >>>
> >>> import socket
> >>>
> >>> # create an INET, STREAMing socket
> >>> s = socket.socket(socket.AF_INET, socket.SOCK_STREAM)
> >>> # now connect to the web server on port 80 - the normal http port
> >>> s.connect(("127.0.0.1", 8080))
> >>> s.send("GET /broken-pipe-1.0-SNAPSHOT/hello
> >> HTTP/1.1\nHost:127.0.0.1\nX-Forwarded-For: 127.0.0.1\nX-Forwarded-
> Protocol:
> >> http\n\n")
> >>>
> >>> This result in a broken pipe exception, a recycling of the async
> context
> >> but no complete:
> >>>
> >>> INFO: An error occurred in processing while on a non-container thread.
> >> The connection will be closed immediately
> >>> java.net.SocketException: Broken pipe
> >>> at java.net.SocketOutputStream.$$YJP$$socketWrite0(Native Method)
> >>> at java.net.SocketOutputStream.socketWrite0(
> SocketOutputStream.java)
> >>> at
> >> java.net.SocketOutputStream.socketWrite(SocketOutputStream.java:109)
> >>> at java.net.SocketOutputStream.write(SocketOutputStream.java:153)
> >>> at
> >> org.apache.coyote.http11.InternalOutputBuffer.realWriteBytes(
> InternalOutputBuffer.java:215)
> >>> at
> >> org.apache.tomcat.util.buf.ByteChunk.flushBuffer(ByteChunk.java:480)
> >>> at
> >> org.apache.coyote.http11.InternalOutputBuffer.endRequest(
> InternalOutputBuffer.java:159)
> >>> at
> >> org.apache.coyote.http11.AbstractHttp11Processor.action(
> AbstractHttp11Processor.java:761)
> >>> at org.apache.coyote.Response.action(Response.java:174)
> >>> at org.apache.coyote.Response.finish(Response.java:274)
> >>> at
> >> org.apache.catalina.connector.OutputBuffer.close(OutputBuffer.java:322)
> >>> at
> >> org.apache.catalina.connector.CoyoteOutputStream.close(
> CoyoteOutputStream.java:108)
> >>> at stickyads.tv.HelloServlet$1.completed(HelloServlet.java:33)
> >>> at stickyads.tv.HelloServlet$1.completed(HelloServlet.java:26)
> >>> at
> >> org.apache.http.concurrent.BasicFuture.completed(BasicFuture.java:119)
> >>> at
> >> org.apache.http.impl.nio.client.DefaultClientExchangeHandlerIm
> pl.responseCompleted(DefaultClientExchangeHandlerImpl.java:177)
> >>> at
> >> org.apache.http.nio.protocol.HttpAsyncRequestExecutor.processResponse(
> HttpAsyncRequestExecutor.java:412)
> >>> at
> >> org.apache.http.nio.protocol.HttpAsyncRequestExecutor.inputReady(
> HttpAsyncRequestExecutor.java:305)
> >>> at
> >> org.apache.http.impl.nio.DefaultNHttpClientConnection.consumeInput(
> DefaultNHttpClientConnection.java:267)
> >>> at
> >> org.apache.http.impl.nio.client.InternalIODispatch.onInputReady(
> InternalIODispatch.java:81)
> >>> at
> >> org.apache.http.impl.nio.client.InternalIODispatch.onInputReady(
> InternalIODispatch.java:39)
> >>> at
> >> org.apache.http.impl.nio.reactor.AbstractIODispatch.
> inputReady(AbstractIODispatch.java:116)
> >>> at
> >> org.apache.http.impl.nio.reactor.BaseIOReactor.
> readable(BaseIOReactor.java:164)
> >>> at
> >> org.apache.http.impl.nio.reactor.AbstractIOReactor.processEvent(
> AbstractIOReactor.java:339)
> >>> at
> >> org.apache.http.impl.nio.reactor.AbstractIOReactor.processEvents(
> AbstractIOReactor.java:317)
> >>> at
> >> org.apache.http.impl.nio.reactor.AbstractIOReactor.
> execute(AbstractIOReactor.java:278)
> >>> at
> >> org.apache.http.impl.nio.reactor.BaseIOReactor.execute(
> BaseIOReactor.java:106)
> >>> at
> >> org.apache.http.impl.nio.reactor.AbstractMultiworkerIOReactor$
> Worker.run(AbstractMultiworkerIOReactor.java:590)
> >>> at java.lang.Thread.run(Thread.java:745)
> >>>
> >>> Oct 18, 2016 9:47:24 AM org.apache.catalina.core.AsyncContextImpl
> logDebug
> >>> FINE: Req: 1f68c4e1 CReq: 3a716fa9 RP: 4c7aa6ad Stage: 7 Thread:
> >> http-bio-8080-exec-5 State: N/A Method: recycle
> >> URI: /broken-pipe-1.0-SNAPSHOT/hello
> >>>
> >>> Here is also a tcpdump corresponding to this scenario:
> >>>
> >>> 09:47:43.916628 IP (tos 0x0, ttl 64, id 63341, offset 0, flags [DF],
> >> proto TCP (6), length 60)
> >>> 127.0.0.1.44078 > 127.0.0.1.8080: Flags [S], cksum 0xfe30
> (incorrect
> >> -> 0x0bcc), seq 3052296773, win 43690, options [mss 65495,sackOK,TS val
> >> 273198376 ecr 0,nop,wscale 7], length 0
> >>> E..<.m@.@.EL..............ZE.........0.........
> >>> .H.(........
> >>> 09:47:43.916642 IP (tos 0x0, ttl 64, id 0, offset 0, flags [DF], proto
> >> TCP (6), length 60)
> >>> 127.0.0.1.8080 > 127.0.0.1.44078: Flags [S.], cksum 0xfe30
> (incorrect
> >> -> 0x44d5), seq 705486696, ack 3052296774, win 43690, options [mss
> >> 65495,sackOK,TS val 273198376 ecr 273198376,nop,wscale 7], length 0
> >>> E..<..@.@.<.............*..h..ZF.....0.........
> >>> .H.(.H.(....
> >>> 09:47:43.916653 IP (tos 0x0, ttl 64, id 63342, offset 0, flags [DF],
> >> proto TCP (6), length 52)
> >>> 127.0.0.1.44078 > 127.0.0.1.8080: Flags [.], cksum 0xfe28
> (incorrect
> >> -> 0x171a), seq 1, ack 1, win 342, options [nop,nop,TS val 273198376 ecr
> >> 273198376], length 0
> >>> E..4.n@.@.ES..............ZF*..i...V.(.....
> >>> .H.(.H.(
> >>> 09:47:43.916917 IP (tos 0x0, ttl 64, id 63343, offset 0, flags [DF],
> >> proto TCP (6), length 172)
> >>> 127.0.0.1.44078 > 127.0.0.1.8080: Flags [P.], cksum 0xfea0
> (incorrect
> >> -> 0xbf79), seq 1:121, ack 1, win 342, options [nop,nop,TS val 273198376
> >> ecr 273198376], length 120
> >>> E....o@.@.D...............ZF*..i...V.......
> >>> .H.(.H.(GET /broken-pipe-1.0-SNAPSHOT/hello HTTP/1.1
> >>> Host:127.0.0.1
> >>> X-Forwarded-For: 127.0.0.1
> >>> X-Forwarded-Protocol: http
> >>>
> >>>
> >>> 09:47:43.916923 IP (tos 0x0, ttl 64, id 29249, offset 0, flags [DF],
> >> proto TCP (6), length 52)
> >>> 127.0.0.1.8080 > 127.0.0.1.44078: Flags [.], cksum 0xfe28
> (incorrect
> >> -> 0x16a2), seq 1, ack 121, win 342, options [nop,nop,TS val 273198376
> ecr
> >> 273198376], length 0
> >>> E..4rA@.@...............*..i..Z....V.(.....
> >>> .H.(.H.(
> >>> 09:47:43.923131 IP (tos 0x0, ttl 64, id 63344, offset 0, flags [DF],
> >> proto TCP (6), length 52)
> >>> 127.0.0.1.44078 > 127.0.0.1.8080: Flags [F.], cksum 0xfe28
> (incorrect
> >> -> 0x16a0), seq 121, ack 1, win 342, options [nop,nop,TS val 273198377
> ecr
> >> 273198376], length 0
> >>> E..4.p@.@.EQ..............Z.*..i...V.(.....
> >>> .H.).H.(
> >>> 09:47:43.960144 IP (tos 0x0, ttl 64, id 29250, offset 0, flags [DF],
> >> proto TCP (6), length 52)
> >>> 127.0.0.1.8080 > 127.0.0.1.44078: Flags [.], cksum 0xfe28
> (incorrect
> >> -> 0x1695), seq 1, ack 122, win 342, options [nop,nop,TS val 273198387
> ecr
> >> 273198377], length 0
> >>> E..4rB@.@...............*..i..Z....V.(.....
> >>> .H.3.H.)
> >>> 09:47:44.380384 IP (tos 0x0, ttl 64, id 29251, offset 0, flags [DF],
> >> proto TCP (6), length 179)
> >>> 127.0.0.1.8080 > 127.0.0.1.44078: Flags [P.], cksum 0xfea7
> (incorrect
> >> -> 0xe005), seq 1:128, ack 122, win 342, options [nop,nop,TS val
> 273198492
> >> ecr 273198377], length 127
> >>> E...rC@.@...............*..i..Z....V.......
> >>> .H...H.)HTTP/1.1 200 OK
> >>> Server: Apache-Coyote/1.1
> >>> Transfer-Encoding: chunked
> >>> Date: Tue, 18 Oct 2016 07:47:44 GMT
> >>>
> >>> b
> >>> Hello world
> >>>
> >>> 09:47:44.380398 IP (tos 0x0, ttl 64, id 52626, offset 0, flags [DF],
> >> proto TCP (6), length 40)
> >>> 127.0.0.1.44078 > 127.0.0.1.8080: Flags [R], cksum 0xd571
> (correct),
> >> seq 3052296895, win 0, length 0
> >>> E..(..@.@.o;..............Z.....P....q..
> >>>
> >>> This shows the python "client", sends a FIN to tomcat, tomcat PUSH
> anyway
> >> and then the "client" RESETs.
> >>>
> >>> Thomas
> >>>
> >>> 2016-10-10 19:10 GMT+02:00 Mark Thomas <ma...@apache.org>:
> >>>>
> >>>> On 10/10/2016 15:47, Thomas Boniface wrote:
> >>>>> Hello,
> >>>>>
> >>>>> I have managed to test this use case on the server revealing the
> issue
> >> with
> >>>>> the latest tomcat release (7.0.72). I still can observe the issue on
> >>>>> catalina.out side: a broken pipe exception pops up and a recycle is
> >> shown
> >>>>> for the async context but no complete.
> >>>>
> >>>> Steps to reproduce?
> >>>>
> >>>> Better still, a test case that demonstrates the issue?
> >>>>
> >>>> Mark
> >>>>
> >>>>
> >>>>>
> >>>>> Oct 10, 2016 4:41:07 PM org.apache.coyote.AbstractProcessor
> >> setErrorState
> >>>>> INFO: An error occurred in processing while on a non-container
> thread.
> >> The
> >>>>> connection will be closed immediately
> >>>>> java.net.SocketException: Broken pipe
> >>>>> at java.net.SocketOutputStream.$$YJP$$socketWrite0(Native
> Method)
> >>>>> at
> >> java.net.SocketOutputStream.socketWrite0(SocketOutputStream.java)
> >>>>> at
> >> java.net.SocketOutputStream.socketWrite(SocketOutputStream.java:109)
> >>>>> at java.net.SocketOutputStream.write(SocketOutputStream.java:
> 153)
> >>>>> at
> >>>>>
> >> org.apache.coyote.http11.InternalOutputBuffer.realWriteBytes(
> InternalOutputBuffer.java:215)
> >>>>> at
> >> org.apache.tomcat.util.buf.ByteChunk.flushBuffer(ByteChunk.java:480)
> >>>>> at
> >>>>>
> >> org.apache.coyote.http11.InternalOutputBuffer.endRequest(
> InternalOutputBuffer.java:159)
> >>>>> at
> >>>>>
> >> org.apache.coyote.http11.AbstractHttp11Processor.action(
> AbstractHttp11Processor.java:761)
> >>>>> at org.apache.coyote.Response.action(Response.java:174)
> >>>>> at org.apache.coyote.Response.finish(Response.java:274)
> >>>>> at
> >>>>> org.apache.catalina.connector.OutputBuffer.close(
> OutputBuffer.java:322)
> >>>>> at
> >>>>>
> >> org.apache.catalina.connector.CoyoteOutputStream.close(
> CoyoteOutputStream.java:108)
> >>>>> ...
> >>>>> Oct 10, 2016 4:41:07 PM org.apache.catalina.core.AsyncContextImpl
> >> logDebug
> >>>>> FINE: Req: 2de85b25 CReq: 70e2c044 RP: 1dff11c5 Stage: 7 Thread:
> >>>>> http-bio-8080-exec-8 State: N/A Method: recycle
> >>>>> URI:
> >>>>>
> >> /www/delivery/swfIndex.php?reqType=AdsSetup&protocolVersion=2.0&zoneId=
> 5335
> >>>>>
> >>>>> On application logs side the behavior changed a bit as I now have a
> >>>>> IllegalStateException:
> >>>>>
> >>>>> java.lang.IllegalStateException: It is illegal to call this method
> if
> >> the
> >>>>> current request is not in asynchronous mode (i.e. isAsyncStarted()
> >> returns
> >>>>> false)
> >>>>> at
> >>>>>
> >> org.apache.catalina.connector.Request.getAsyncContext(
> Request.java:1740)
> >>>>> ~[catalina.jar:7.0.72]
> >>>>>
> >>>>> In the end, the situation seems pretty similar. The container appears
> >> to
> >>>>> recycle the request without completing the async context and I can't
> >>>>> complete on application side as the request I have is now recycled.
> >>>>>
> >>>>> Thanks,
> >>>>> Thomas
> >>>>>
> >>>>>
> >>>>> 2016-10-03 17:06 GMT+02:00 Thomas Boniface <tho...@stickyads.tv>:
> >>>>>
> >>>>>> Hi,
> >>>>>>
> >>>>>> Thanks for your feedbacks. I noticed the issue I described do not
> >> occur on
> >>>>>> my local or integration environment. I still try to figure out how
> to
> >>>>>> reproduce this in an environment I can easely update to the latest
> >> tomcat
> >>>>>> version.
> >>>>>>
> >>>>>> Although it may not occur in latest release. Could you give me an
> >> input on
> >>>>>> what are the consequences of the behaviour I described ?
> >>>>>>
> >>>>>> Thanks,
> >>>>>> Thomas
> >>>>>>
> >>>>>> 2016-09-29 9:41 GMT+02:00 Violeta Georgieva <violet...@apache.org>:
> >>>>>>
> >>>>>>> Hi,
> >>>>>>>
> >>>>>>> 2016-09-29 10:14 GMT+03:00 Thomas Boniface <tho...@stickyads.tv>:
> >>>>>>>>
> >>>>>>>> The tomcat version is 7.0.64.
> >>>>>>>
> >>>>>>> I would recommend you to verify the behaviour against the latest
> >> Tomcat 7
> >>>>>>> (7.0.72).
> >>>>>>> We have changes in the async processing since 7.0.64.
> >>>>>>> http://tomcat.apache.org/tomcat-7.0-doc/changelog.html
> >>>>>>>
> >>>>>>> Regards,
> >>>>>>> Violeta
> >>>>>>>
> >>>>>>>> Thomas
> >>>>>>>>
> >>>>>>>> 2016-09-28 22:43 GMT+02:00 Christopher Schultz <
> >>>>>>> ch...@christopherschultz.net
> >>>>>>>>> :
> >>>>>>>>
> >>>>> Thomas,
> >>>>>
> >>>>> On 9/28/16 11:55 AM, Thomas Boniface wrote:
> >>>>>>>>>>> Hi,
> >>>>>>>>>>>
> >>>>>>>>>>> When a client calls an asynchronous servlet and closes the
> >>>>>>>>>>> connection a java.io.IOException: Broken pipe is catched by
> >> Tomcat
> >>>>>>>>>>> level when the webapp tries to write to the socket.
> >>>>>>>>>>>
> >>>>>>>>>>> This exception is not transmited to the webapp level but it
> seems
> >>>>>>>>>>> the request has been recycled (all content is reinitialised),
> in
> >>>>>>>>>>> such a case it impossible for the webapp to retrieve the
> >>>>>>>>>>> AsyncContext from the HttpServletRequest making the
> AsyncContext
> >>>>>>>>>>> complete call impossible.
> >>>>>>>>>>>
> >>>>>>>>>>> Activating the tomcat logging for AsyncContext
> >>>>>>>>>>> (org.apache.catalina.core.AsyncContextImpl.level = FINE) shows
> >> the
> >>>>>>>>>>> recycle method is called but not the complete method, what
> seems
> >> to
> >>>>>>>>>>> confirm my assumption. In a use case were the client waits for
> >> the
> >>>>>>>>>>> response, I can see both complete and recycle are called.
> >>>>>>>>>>>
> >>>>>>>>>>> My question is, what is the impact of the complete not being
> >> called
> >>>>>>>>>>> on the AsyncContext, is the socket cleaned up properly ?
> >>>>>
> >>>>> Tomcat version?
> >>>>>
> >>>>> -chris
> >>>>>>>>>
> >>>>>>>>>
> >> ---------------------------------------------------------------------
> >>>>>>>>> To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org
> >>>>>>>>> For additional commands, e-mail: users-h...@tomcat.apache.org
> >>>>>>>>>
> >>>>>>>>>
> >>>>>>>
> >>>>>>
> >>>>>>
> >>>>>
> >>>>
> >>>>
> >>>> ---------------------------------------------------------------------
> >>>> To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org
> >>>> For additional commands, e-mail: users-h...@tomcat.apache.org
> >>>>
> >>>
> >>
> >
> >
> > ---------------------------------------------------------------------
> > To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org
> > For additional commands, e-mail: users-h...@tomcat.apache.org
> >
>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org
> For additional commands, e-mail: users-h...@tomcat.apache.org
>
>
