tomcat-users mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Mark Thomas <ma...@apache.org>
Subject Re: Async servlet and request recycling
Date Wed, 02 Nov 2016 09:22:28 GMT
On 02/11/2016 08:51, Thomas Boniface wrote:
> I'm glad this was useful in the end.
> 
> Could you send the link to the corresponding issue ? I'd be interesting to
> read the commit for the fix and known the tomcat versions this will be
> pushed to.

There is no issue.

In terms of the commits, look at commits from me yesterday.

It was fixed in for branches that support async so 7.0.x to 9.0.x. For
exact versions, see the changelog entries that are part of those commits.

Mark

> 
> Thanks
> 
> 2016-11-01 11:08 GMT+01:00 Mark Thomas <markt@apache.org>:
> 
>> 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 <thomas@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.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@.@.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 <markt@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 <thomas@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 <violetagg@apache.org>:
>>>>>>>>
>>>>>>>>> Hi,
>>>>>>>>>
>>>>>>>>> 2016-09-29 10:14 GMT+03:00 Thomas Boniface <thomas@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 <
>>>>>>>>> chris@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-unsubscribe@tomcat.apache.org
>>>>>>>>>>> For additional commands, e-mail: users-help@tomcat.apache.org
>>>>>>>>>>>
>>>>>>>>>>>
>>>>>>>>>
>>>>>>>>
>>>>>>>>
>>>>>>>
>>>>>>
>>>>>>
>>>>>> ---------------------------------------------------------------------
>>>>>> To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
>>>>>> For additional commands, e-mail: users-help@tomcat.apache.org
>>>>>>
>>>>>
>>>>
>>>
>>>
>>> ---------------------------------------------------------------------
>>> To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
>>> For additional commands, e-mail: users-help@tomcat.apache.org
>>>
>>
>>
>> ---------------------------------------------------------------------
>> To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
>> For additional commands, e-mail: users-help@tomcat.apache.org
>>
>>
> 


---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org


Mime
View raw message