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@[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]
>
>
