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