You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@tomcat.apache.org by Jeremy Boynes <jb...@apache.org> on 2010/10/21 08:09:04 UTC
Request logging with async examples
When I run the async1 example in trunk, the request gets logged twice in the access log:
0:0:0:0:0:0:0:1%0 - - [20/Oct/2010:21:32:39 -0700] "GET /examples/async/async1 HTTP/1.1" 200 -
0:0:0:0:0:0:0:1%0 - - [20/Oct/2010:21:32:42 -0700] "GET /examples/async/async1 HTTP/1.1" 200 863
Is this the expected behaviour or should the post-invoke part of AccessLogValve be returning early for the first dispatch (when async has been started)?
However, with async2 which calls complete() from a background thread to finish the request, only the first dispatch is logged:
0:0:0:0:0:0:0:1%0 - - [20/Oct/2010:22:25:02 -0700] "GET /examples/async/async2 HTTP/1.1" 200 -
It doesn't look like the Valve is being invoked at all when the request is completed.
It also logs the 200 response if I change Async2 to send an error response:
- actx.getResponse().getWriter().write("Output from background thread. Time:"+System.currentTimeMillis()+"\n");
+ ((HttpServletResponse)actx.getResponse()).sendError(404);
which seems problematic as it looks form the log that the request was OK. This does not send any data back to the client:
$ curl -v http://localhost:8080/examples/async/async2
* About to connect() to localhost port 8080 (#0)
* Trying ::1... connected
* Connected to localhost (::1) port 8080 (#0)
> GET /examples/async/async2 HTTP/1.1
> User-Agent: curl/7.19.7 (universal-apple-darwin10.0) libcurl/7.19.7 OpenSSL/0.9.8l zlib/1.2.3
> Host: localhost:8080
> Accept: */*
>
[[ delays for a few seconds ... ]]
* Empty reply from server
* Connection #0 to host localhost left intact
curl: (52) Empty reply from server
* Closing connection #0
Thanks
Jeremy
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org
Re: Request logging with async examples
Posted by Mark Thomas <ma...@apache.org>.
On 21/10/2010 01:09, Jeremy Boynes wrote:
> When I run the async1 example in trunk, the request gets logged twice in the access log:
> 0:0:0:0:0:0:0:1%0 - - [20/Oct/2010:21:32:39 -0700] "GET /examples/async/async1 HTTP/1.1" 200 -
> 0:0:0:0:0:0:0:1%0 - - [20/Oct/2010:21:32:42 -0700] "GET /examples/async/async1 HTTP/1.1" 200 863
>
> Is this the expected behaviour or should the post-invoke part of AccessLogValve be returning early for the first dispatch (when async has been started)?
Looks like a bug to me. It might be a side-effect of the async
refactoring I did but I must confess I didn't test access logging before
or after the refactoring so it might always have been like this. Either
way, please raise a bugzilla issue for this. As always, patches are very
much appreciated.
> However, with async2 which calls complete() from a background thread to finish the request, only the first dispatch is logged:
> 0:0:0:0:0:0:0:1%0 - - [20/Oct/2010:22:25:02 -0700] "GET /examples/async/async2 HTTP/1.1" 200 -
> It doesn't look like the Valve is being invoked at all when the request is completed.
Same as above.
> It also logs the 200 response if I change Async2 to send an error response:
> - actx.getResponse().getWriter().write("Output from background thread. Time:"+System.currentTimeMillis()+"\n");
> + ((HttpServletResponse)actx.getResponse()).sendError(404);
> which seems problematic as it looks form the log that the request was OK. This does not send any data back to the client:
And another one.
While there are probably three separate changes required to fix this,
the issues are so similar lets keep them in a single bug report - at
least to start with. We can always break then out if we need to.
Mark
> $ curl -v http://localhost:8080/examples/async/async2
> * About to connect() to localhost port 8080 (#0)
> * Trying ::1... connected
> * Connected to localhost (::1) port 8080 (#0)
>> GET /examples/async/async2 HTTP/1.1
>> User-Agent: curl/7.19.7 (universal-apple-darwin10.0) libcurl/7.19.7 OpenSSL/0.9.8l zlib/1.2.3
>> Host: localhost:8080
>> Accept: */*
>>
> [[ delays for a few seconds ... ]]
> * Empty reply from server
> * Connection #0 to host localhost left intact
> curl: (52) Empty reply from server
> * Closing connection #0
>
> Thanks
> Jeremy
>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
> For additional commands, e-mail: dev-help@tomcat.apache.org
>
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org