Bug 52316 - AccessLog does not log size for files sent with sendfile
Summary: AccessLog does not log size for files sent with sendfile
Alias: None
Product: Tomcat 7
Classification: Unclassified
Component: Catalina (show other bugs)
Version: 7.0.23
Hardware: PC Windows XP
: P2 normal (vote)
Target Milestone: ---
Assignee: Tomcat Developers Mailing List
Depends on:
Reported: 2011-12-09 22:23 UTC by Konstantin Kolinko
Modified: 2011-12-28 21:29 UTC (History)
0 users


Note You need to log in before you can comment on or make changes to this bug.
Description Konstantin Kolinko 2011-12-09 22:23:47 UTC
Confirming a problem reported on the users@ list.

This affects both NIO and APR protocols when file is delivered with sendfile. Note, that the file have to be >48kb to trigger use of sendfile.

Steps to reproduce:
1) Configure three connectors:
    <Connector port="8081" protocol="org.apache.coyote.http11.Http11Protocol"
               redirectPort="8443" />
    <Connector port="8082" protocol="org.apache.coyote.http11.Http11NioProtocol"
               redirectPort="8443" />
    <Connector port="8083" protocol="org.apache.coyote.http11.Http11AprProtocol"
               redirectPort="8443" />

and configure AccessLogValve in a <Host>:

        <Valve className="org.apache.catalina.valves.AccessLogValve"
               prefix="localhost_access_log." suffix=".txt"
               pattern="%h %l %u %t &quot;%r&quot; %s %b (%D ms)" />

The difference from common pattern is that I added "(%D ms)" at the end.
2) Put some big file (>48k) as webapps/ROOT/file
3) Download it 3 times:
4) Access Log: - - [10/Dec/2011:01:05:08 +0300] "GET /file?8081 HTTP/1.1" 200 15027784 (4766 ms) - - [10/Dec/2011:01:05:23 +0300] "GET /file?8082 HTTP/1.1" 200 - (31 ms) - - [10/Dec/2011:01:05:48 +0300] "GET /file?8083 HTTP/1.1" 200 - (16 ms)

Note that '-' is printed instead of file size for Nio and Apr connectors.

A). Disable sendfile with useSendfile="false" on a connector

B). Add the following pattern to AccessLogValve:

"%{org.apache.tomcat.sendfile.start}r %{org.apache.tomcat.sendfile.end}r"

That will log the range of bytes sent by sendfile.
E.g.: - - [10/Dec/2011:01:05:08 +0300] "GET /file?8081 HTTP/1.1" 200 15027784 (4766 ms) - - - - [10/Dec/2011:01:05:23 +0300] "GET /file?8082 HTTP/1.1" 200 - (31 ms) 0 15027784 - - [10/Dec/2011:01:05:48 +0300] "GET /file?8083 HTTP/1.1" 200 - (16 ms) 0 15027784 

Overall, looking at the timing value printed by %D I would say that logging occurs before data are sent. So the value of 0 bytes is correct.

It could be possible to log file size from request attributes set by sendfile, but that cannot account for aborted downloads. Though I think that would be better than the current logging of '0'.

At least this limitation can be mentioned in documentation for %b and %B patterns in AccessLogValve section in valve.html and in Javadoc.
Comment 1 Mark Thomas 2011-12-27 20:29:08 UTC
Since sendfile sends the data asynchronously on a separate thread, the access log can never know exactly how many bytes are sent without destroying the benefits of sendfile.

I lean towards logging the bytes intended to be sent (calculated from the request attributes).
Comment 2 Mark Thomas 2011-12-28 21:29:13 UTC
Fixed in trunk and 7.0.x and will be included in 7.0.24 onwards.