Bug 58702 - Access log lines are not written if client aborts
Access log lines are not written if client aborts
Status: RESOLVED FIXED
Product: Tomcat 8
Classification: Unclassified
Component: Catalina
8.0.30
PC All
: P2 normal (vote)
: ----
Assigned To: Tomcat Developers Mailing List
:
Depends on:
Blocks:
  Show dependency tree
 
Reported: 2015-12-08 03:13 UTC by zikfat
Modified: 2015-12-18 11:36 UTC (History)
0 users



Attachments
war file to demo the issue (570.50 KB, application/zip)
2015-12-08 03:13 UTC, zikfat
Details

Note You need to log in before you can comment on or make changes to this bug.
Description zikfat 2015-12-08 03:13:08 UTC
Created attachment 33333 [details]
war file to demo the issue

When a client aborts a request to a web application before the response is written no line is written to the Tomcat access log.

I most recently tested this on an out-of-the-box 8.0.30 distribution but I have seen the problem occur on Tomcat 8.0.28 and 7.0.39 as well.

I believe that the general repro steps are as simple as this:

1) In a browser, hit any endpoint in a web application that has an AccessLogValve configured
2) Close the browser tab that made the request before the request finishes
3) Check the access log and note that no access log line was written for the request

Demo app:
I've attached a WAR file with a simple web application to demonstrate the problem. The source code for the application is included in the WAR.

The demo application has two servlets, one "fast" and one "slow". They both log a unique ID for the request to a logback-configured application log, then return a 200 response with a simple string. The only difference between them is that the fast servlet returns immediately while the slow servlet sleeps for 30 seconds before returning.

The unique request ID generated by these servlets is also added as a request attribute so that it can be shown in the access log.

Repro steps with the demo app:
1) Put the WAR file into a Tomcat container and load it.
2) Open a web browser and go to localhost:<port>/missing-access-log-demo/fast
3) Check the application and access logs at <catalina-base>/logs/missing-access-log-demo. Note that both logs generated a line for the request, and that the unique identifier for the request is the same in both files.
4) In a web browser, go to localhost:<port>/missing-access-log-demo/slow. Watch the application log as you make the request and you should see a line quickly added with the request's unique ID.
5) Before the request completes, close the browser tab that made the request.
6) Wait 30 seconds and watch the access log. Note that no line for this request is ever added.

Expected result:

Even if the client never gets the response, a request was processed by the server so I would expect to see it appear in the access logs.

Details:
I've stepped into the Tomcat code and it seems pretty clear this is happening in the CoyoteAdapter class:

http://svn.apache.org/viewvc/tomcat/tc8.0.x/tags/TOMCAT_8_0_30/java/org/apache/catalina/connector/CoyoteAdapter.java?view=markup

On line 558 the CoyoteAdapter calls response.finishResponse, right before the code that will call the access log. If the client is gone the finishResponse method throws an IOException when trying to flush its OutputBuffer. This exception causes the code to skip the call to context.logAccess and is then swallowed and ignored by the subsequent catch block.
Comment 1 Mark Thomas 2015-12-18 11:36:58 UTC
Fixed in 9.0.x for 9.0.0.M2, 8.0.x for 8.0.31 and 7.0.x for 7.0.68.

It was not fixed in 6.0.x since 6.0.x does not have the additional access log infrastructure required.