mod_http2 with mod_logio logs cumulative connection "bytes received" instead of per-request

[cPanelChrisD]

When using %I (mod_logio "Bytes received" field) or %S in LogFormat, the logged value is cumulative for the bytes received for the entire HTTP/2 connection and not per-request. This problem does not occur for %O (mod_logio "Bytes sent").

The simplest way that I have found to replicate this is with HTTP/2-enabled curl. It is not necessary for the upload to actually be "successful", as long as the request can be made to Apache. I get a 405 result in the example below because PUT is not implemented for the default configuration, but it is enough to show the issue with log output using the following:

    LogFormat "%h %l %u %t \"%r\" %>s %b %S %I %O" common

# dd if=/dev/urandom of=100M.file bs=1M count=100
# curl --http2 --http2-prior-knowledge -v -o /dev/null -T 100M.file http://localhost/up1 -T 100M.file http://localhost/up2 -T 100M.file http://localhost/up3
# tail -3 /usr/local/apache2/logs/access_log
--
::1 - - [03/Apr/2018:10:31:23 -0500] "PUT /up1 HTTP/2.0" 405 224 104857824 104857600 224
::1 - - [03/Apr/2018:10:31:23 -0500] "PUT /up2 HTTP/2.0" 405 224 209715424 209715200 224
::1 - - [03/Apr/2018:10:31:23 -0500] "PUT /up3 HTTP/2.0" 405 224 314573024 314572800 224

Note that %S and %I are logging the cumulative received bytes, not just the received bytes for each request. The expected log output would be like when using HTTP/1.1:

# curl --http1.1 -v -o /dev/null -T 100M.file http://localhost/up1 -T 100M.file http://localhost/up2 -T 100M.file http://localhost/up3
# tail -3 /usr/local/apache2/logs/access_log
::1 - - [03/Apr/2018:11:25:19 -0500] "PUT /up1 HTTP/1.1" 405 224 104858202 104857749 453
::1 - - [03/Apr/2018:11:25:19 -0500] "PUT /up2 HTTP/1.1" 405 224 104858179 104857726 453
::1 - - [03/Apr/2018:11:25:19 -0500] "PUT /up3 HTTP/1.1" 405 224 104858179 104857726 453

[cPanelChrisD]

The example above was demonstrated on a vanilla CentOS 7.4 system with Apache 2.4.33 compiled from source, using the default configuration except to enable mod_http2 and mod_logio:

--- httpd.conf.orig     2018-04-03 10:19:12.608412490 -0500
+++ httpd.conf  2018-04-03 10:31:10.885353580 -0500
@@ -148,6 +148,12 @@
 #LoadModule userdir_module modules/mod_userdir.so
 LoadModule alias_module modules/mod_alias.so
 #LoadModule rewrite_module modules/mod_rewrite.so
+LoadModule logio_module modules/mod_logio.so
+LoadModule http2_module modules/mod_http2.so
+
+<IfModule http2_module>
+    Protocols h2 h2c http/1.1
+</IfModule>

 <IfModule unixd_module>
 #
@@ -280,7 +286,7 @@
     # a CustomLog directive (see below).
     #
     LogFormat "%h %l %u %t \"%r\" %>s %b \"%{Referer}i\" \"%{User-Agent}i\"" combined
-    LogFormat "%h %l %u %t \"%r\" %>s %b" common
+    LogFormat "%h %l %u %t \"%r\" %>s %b %S %I %O" common

     <IfModule logio_module>
       # You need to enable mod_logio.c to use %I and %O

# /usr/local/apache2/bin/httpd -V
Server version: Apache/2.4.33 (Unix)
Server built:   Apr  3 2018 11:05:13
Server's Module Magic Number: 20120211:76
Server loaded:  APR 1.6.3, APR-UTIL 1.6.1
Compiled using: APR 1.6.3, APR-UTIL 1.6.1
Architecture:   64-bit
Server MPM:     event
  threaded:     yes (fixed thread count)
    forked:     yes (variable process count)
Server compiled with....
 -D APR_HAS_SENDFILE
 -D APR_HAS_MMAP
 -D APR_HAVE_IPV6 (IPv4-mapped addresses enabled)
 -D APR_USE_SYSVSEM_SERIALIZE
 -D APR_USE_PTHREAD_SERIALIZE
 -D SINGLE_LISTEN_UNSERIALIZED_ACCEPT
 -D APR_HAS_OTHER_CHILD
 -D AP_HAVE_RELIABLE_PIPED_LOGS
 -D DYNAMIC_MODULE_LIMIT=256
 -D HTTPD_ROOT="/usr/local/apache2"
 -D SUEXEC_BIN="/usr/local/apache2/bin/suexec"
 -D DEFAULT_PIDLOG="logs/httpd.pid"
 -D DEFAULT_SCOREBOARD="logs/apache_runtime_status"
 -D DEFAULT_ERRORLOG="logs/error_log"
 -D AP_TYPES_CONFIG_FILE="conf/mime.types"
 -D SERVER_CONFIG_FILE="conf/httpd.conf"

[icing]

The confusion stems from different connection re-use, I assume.

mod_logio really counts in/out bytes per connection (and not per request). It seems that with curl, you have a new connection every time (I think connection close is default behaviour of Apache for requests that give error response, like yours). With HTTP/2, the connection is reused for all 3 requests, so you see the numbers adding up.

[cPanelChrisD]

You are correct that it is related to connection re-use. There is at least an inconsistency in logging behavior of persistent connections. I have not been able to reproduce this behavior for the "Bytes out" counter when reusing HTTP/2 connections, only "Bytes in" appears to be affected. It also does not occur with HTTP/1.1 when using persistent connections. In all of these other cases, the per-request bytes are being logged.

A per-connection "bytes in" counter is also not useful for log entries that are, in all other ways, per-request. A log analysis will not be able to determine the actual number of uploaded bytes for a range of requests if each %I field in the log is cumulative for a connection, because there is no connection identification available (like a unique "connection ID" field, for example).

For example, how should the total number of bytes uploaded here be determined:

::1 - - [03/Apr/2018:10:31:23 -0500] "PUT /up1 HTTP/2.0" 405 224 104857824 104857600 224
::1 - - [03/Apr/2018:10:31:23 -0500] "PUT /up2 HTTP/2.0" 405 224 209715424 209715200 224
::1 - - [03/Apr/2018:10:31:23 -0500] "PUT /up3 HTTP/2.0" 405 224 314573024 314572800 224

Is the total number of "bytes in" 629145600 or 314572800 for these three requests? The correct answer is 314572800 but it is impossible to know this without assuming information that is not available in the logs, which is the knowledge that these requests were made using the same connection. As far as I know, Apache has no method available to log the necessary information. Given only the information available, a log analysis must determine that the total number of "bytes in" is 629145600, which is not correct.

[icing]

You are correct. There is definitely something going very wrong here. The cumulative numbers are plain wrong. Working on it...

[icing]

Please check v1.10.17 for a fix. That one should report accurately the bytes in/out per request.

[cPanelChrisD]

I can confirm that this is resolved in v1.10.17.

[Tue Apr 10 10:13:29.184726 2018] [http2:info] [pid 13303:tid 139963302672192] AH03090: mod_http2 (v1.10.17-git, feats=CHPRIO+SHA256+INVHD+DWINS, nghttp2 1.21.1), initializing...

# curl --http2 --http2-prior-knowledge -v -o /dev/null -T 100M.file http://localhost/up1 -T 100M.file http://localhost/up2 -T 100M.file http://localhost/up3
# tail -3 /usr/local/apache2/logs/access_log
::1 - - [10/Apr/2018:10:14:14 -0500] "PUT /up1 HTTP/2.0" 405 224 104861792 104857653 4139
::1 - - [10/Apr/2018:10:14:14 -0500] "PUT /up2 HTTP/2.0" 405 224 104862509 104857629 4880
::1 - - [10/Apr/2018:10:14:15 -0500] "PUT /up3 HTTP/2.0" 405 224 104860751 104857629 3122

Thank you!

[icing]

Fixed in v1.10.17.