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.DefaultClientExchangeHandlerImpl.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 >> >