mod_h2: wrong values logged for "Bytes sent" on apache 2.4 with http/2

I have noticed wrong values logged for %O (Bytes sent) on interrupted connections on apache-2.4.43 when connection is over http/2. SSL makes no difference. But on plain-text connections “%s”, “%D” and “%A” are wrong too. (all variables are from apache mod_log_config)

Here are the requests:

user@userpc:~/homedir$ timeout -s KILL 5 curl --http2 https://s801.sureserver.com/testXXX.bin --output /dev/null
  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
 29  100M   29 29.7M    0     0  6771k      0  0:00:15  0:00:04  0:00:11 6770kKilled

user@userpc:~/homedir$ timeout -s KILL 5 curl --http1.1 https://s801.sureserver.com/testXXX.bin --output /dev/null
  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
 29  100M   29 29.0M    0     0  6371k      0  0:00:16  0:00:04  0:00:12 6370kKilled

user@userpc:~/homedir$ timeout -s KILL 5 curl --http1.0 https://s801.sureserver.com/testXXX.bin --output /dev/null
  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
 33  100M   33 33.4M    0     0  7087k      0  0:00:14  0:00:04  0:00:10 7085kKilled

user@userpc:~/homedir$ timeout -s KILL 5 curl --http2 http://s801.sureserver.com/testXXX.bin --output /dev/null
  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
 31  100M   31 31.0M    0     0  7348k      0  0:00:13  0:00:04  0:00:09 7346kKilled

user@userpc:~/homedir$ timeout -s KILL 5 curl --http1.1 http://s801.sureserver.com/testXXX.bin --output /dev/null
  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
 35  100M   35 35.7M    0     0  8123k      0  0:00:12  0:00:04  0:00:08 8121kKilled

user@userpc:~/homedir$ timeout -s KILL 5 curl --http1.0 http://s801.sureserver.com/testXXX.bin --output /dev/null
  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
 36  100M   36 36.3M    0     0  8152k      0  0:00:12  0:00:04  0:00:08 8150kKilled

user@userpc:~/homedir$ timeout -s KILL 5 curl --http2 -H "Range: bytes=0-52428800" https://s801.sureserver.com/testXXX.bin --output /dev/null
  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
 69 50.0M   69 34.8M    0     0  7951k      0  0:00:06  0:00:04  0:00:02 7950kKilled

user@userpc:~/homedir$ timeout -s KILL 5 curl --http1.1 -H "Range: bytes=0-52428800" https://s801.sureserver.com/testXXX.bin --output /dev/null
  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
 71 50.0M   71 35.6M    0     0  8060k      0  0:00:06  0:00:04  0:00:02 8058kKilled

Here is the LogFormat definition:

LogFormat "%V %a %l %u %t \"%r\" %>s %O \"%{Referer}i\" \"%{User-Agent}i\" 0 0 \"%{HTTPS}x:%{SSL_PROTOCOL}x:%{SSL_CIPHER}x\" %I %D %A" combined

And that’s what I get logged:

s801.sureserver.com XXX.XXX.XXX.XXX - - [22/Jul/2020:11:25:32 +0300] "GET /testXXX.bin HTTP/2.0" 200 104857600 "-" "curl/7.62.0" 0 0 "on:TLSv1.2:ECDHE-RSA-AES256-GCM-SHA384" 52 4977555
s801.sureserver.com XXX.XXX.XXX.XXX - - [22/Jul/2020:11:25:41 +0300] "GET /testXXX.bin HTTP/1.1" 200 33319484 "-" "curl/7.62.0" 0 0 "on:TLSv1.2:ECDHE-RSA-AES256-GCM-SHA384" 764 4747961
s801.sureserver.com XXX.XXX.XXX.XXX - - [22/Jul/2020:11:26:20 +0300] "GET /testXXX.bin HTTP/1.0" 200 37307283 "-" "curl/7.62.0" 0 0 "on:TLSv1.2:ECDHE-RSA-AES256-GCM-SHA384" 764 4762581
s801.sureserver.com XXX.XXX.XXX.XXX - - [01/Jan/1970:02:00:00 +0200] "GET /testXXX.bin HTTP/2.0" 200 104857600 "-" "curl/7.62.0" 0 0 "off:-:-" 0 1595406571434452
s801.sureserver.com XXX.XXX.XXX.XXX - - [22/Jul/2020:11:54:30 +0300] "GET /testXXX.bin HTTP/1.1" 200 43146056 "-" "curl/7.62.0" 0 0 "off:-:-" 92 4969537
s801.sureserver.com XXX.XXX.XXX.XXX - - [22/Jul/2020:11:54:48 +0300] "GET /testXXX.bin HTTP/1.0" 200 43091032 "-" "curl/7.62.0" 0 0 "off:-:-" 92 4993841
s801.sureserver.com XXX.XXX.XXX.XXX - - [22/Jul/2020:12:21:41 +0300] "GET /testXXX.bin HTTP/2.0" 206 52428801 "-" "curl/7.62.0" 0 0 "on:TLSv1.2:ECDHE-RSA-AES256-GCM-SHA384" 66 4977392
s801.sureserver.com XXX.XXX.XXX.XXX - - [22/Jul/2020:12:27:26 +0300] "GET /testXXX.bin HTTP/1.1" 206 42318859 "-" "curl/7.62.0" 0 0 "on:TLSv1.2:ECDHE-RSA-AES256-GCM-SHA384" 789 4973665

As you can see, the logged Bytes sent value match the requested size (last 2 attempts are partial download and on http/2 request logged value is the chunk size in the request).

About this issue

Original URL
State: closed
Created 4 years ago
Reactions: 1
Comments: 27 (12 by maintainers)

Commits related to this issue

* accurately report the bytes sent for a request in the '%O' Log format. This addresses #203, a long outstanding issue where mod_h2 has reported numbers over-eagerly from internal buffering and... — committed to icing/mod_h2 by icing a year ago

Most upvoted comments

@AxisNL, if you set H2CopyFiles on then traffic is logged correctly. This is how we use HTTP2 in production and have no complaints by customers.

famzah on Apr 15, 2023

On behalf of @vl-grigorov, I confirm that the bug is fixed. Thank you.

famzah on Jun 12, 2023

Merged the PR into master.

icing on May 10, 2023

@AxisNL, if you set H2CopyFiles on then traffic is logged correctly. This is how we use HTTP2 in production and have no complaints by customers.

Thanks! I have just enabled H2CopyFiles on on all our production webservers (Apache 2.4.56 on Debian Bullseye) and it seems to work fine. We’re using mod_logio to log Input/Output bytes with %I %O. Initial testing resulted in 8MB %O (Bytes sent) on a 250MB mp4 file, and the full file size was then logged (actually just 249MB) only after the movie was preloaded 100% in browser player.

This deployment affects over 1000 customer sites running on HTTP/2. I will report here if we encounter any issues.

onlime on Apr 15, 2023

Since this requires extensive testing, I suggest that we work with the same configuration and scripts.

Here is what I’ve configured in Apache (a separate “access_log”, so that we don’t disturb any production data):

Protocols h2 h2c http/1.1
#H2CopyFiles on

LogFormat "\"%r\" http_status=%>s(%s) bytes_resp_B=%B(%b) bytes_tx_O=%O bytes_rx_I=%I bytes_rx_tx_S=%S time_req_us=%D \"%{HTTPS}x:%{SSL_PROTOCOL}x\"" mod_h2_issue_203
CustomLog /var/log/access.mod_h2_issue_203 mod_h2_issue_203

Here is the script that I use to do the tests: http2_test.txt

Sample usage:

http2_test example.com/100M.bin

The script downloads about 20 MBytes for each request. I run it locally on the testing server to avoid network jitter. The script is designed not to leak any sensitive data like machine hostname, etc.

famzah on Sep 7, 2020