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.
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.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
>>>
>>
>
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org
For additional commands, e-mail: users-h...@tomcat.apache.org
