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 <[email protected]>:
>
> 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@[email protected].........
> .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@[email protected]*..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@[email protected]*..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@[email protected].*..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..(..@[email protected];..............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 <[email protected]>:
>>
>> 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 <[email protected]>:
>> >
>> >> 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 <[email protected]>:
>> >>
>> >>> Hi,
>> >>>
>> >>> 2016-09-29 10:14 GMT+03:00 Thomas Boniface <[email protected]>:
>> >>>>
>> >>>> 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 <
>> >>> [email protected]
>> >>>>> :
>> >>>>
>> > 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: [email protected]
>> >>>>> For additional commands, e-mail: [email protected]
>> >>>>>
>> >>>>>
>> >>>
>> >>
>> >>
>> >
>>
>>
>> ---------------------------------------------------------------------
>> To unsubscribe, e-mail: [email protected]
>> For additional commands, e-mail: [email protected]
>>
>
