Bug 58871

Summary: HTTP/2 when in use, response size is recorded in the zero byte If you set the %O in LogFormat
Product: Apache httpd-2 Reporter: Soukaku <soukaku+httpd>
Component: mod_http2Assignee: Apache HTTPD Bugs Mailing List <bugs>
Status: RESOLVED FIXED    
Severity: normal    
Priority: P2    
Version: 2.4.18   
Target Milestone: ---   
Hardware: PC   
OS: Linux   

Description Soukaku 2016-01-15 12:23:41 UTC
I went a set of Apache2 to test the HTTP/2.
As a result of checking the access.log, when it is accessed by the HTTP/2, it was noticed that the response data size is recorded in the zero byte.

HTTP/1.1 :
192.0.2.20 - - [22/Dec/2015:00:46:51 +0900] "GET /~soukaku/images/eyecatch0002.jpg HTTP/1.1" 200 44068 "http://www.downtown.jp/~soukaku/archives/2010/0225_225635.html" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_10_4) AppleWebKit/600.7.12 (KHTML, like Gecko) Version/8.0.7 Safari/600.7.12"

HTTP/2 :
203.0.113.60 - - [22/Dec/2015:03:35:58 +0900] "GET /~soukaku/images/eyecatch0002.jpg HTTP/2" 200 0 "http://www.downtown.jp/~soukaku/archives/2013/0117_010718.html" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_11_2) AppleWebKit/601.3.9 (KHTML, like Gecko) Version/9.0.2 Safari/601.3.9"

Is this a bug?


- Log setting

CustomLog	/var/log/apache2/access.log 	combined
LogFormat "%h %l %u %t \"%r\" %>s %O \"%{Referer}i\" \"%{User-Agent}i\"" combined


− Server info

# apache2ctl -v
Server version: Apache/2.4.18 (Debian)
Server built:   2015-12-19T08:26:14

# apache2ctl -M
Loaded Modules:
 core_module (static)
 so_module (static)
 watchdog_module (static)
 http_module (static)
 log_config_module (static)
 logio_module (static)
 version_module (static)
 unixd_module (static)
 access_compat_module (shared)
 actions_module (shared)
 alias_module (shared)
 apreq_module (shared)
 auth_basic_module (shared)
 auth_digest_module (shared)
 authn_core_module (shared)
 authn_file_module (shared)
 authz_core_module (shared)
 authz_groupfile_module (shared)
 authz_host_module (shared)
 authz_user_module (shared)
 autoindex_module (shared)
 cache_module (shared)
 cgi_module (shared)
 cgid_module (shared)
 dav_module (shared)
 dav_fs_module (shared)
 dav_lock_module (shared)
 dbd_module (shared)
 deflate_module (shared)
 dir_module (shared)
 encoding_module (shared)
 env_module (shared)
 expires_module (shared)
 filter_module (shared)
 geoip_module (shared)
 headers_module (shared)
 http2_module (shared)
 include_module (shared)
 info_module (shared)
 mime_module (shared)
 mpm_prefork_module (shared)
 negotiation_module (shared)
 perl_module (shared)
 php5_module (shared)
 reqtimeout_module (shared)
 rewrite_module (shared)
 security2_module (shared)
 setenvif_module (shared)
 socache_shmcb_module (shared)
 spamhaus_module (shared)
 ssl_module (shared)
 status_module (shared)
 suexec_module (shared)
 unique_id_module (shared)
 userdir_module (shared)
 usertrack_module (shared)
 xsendfile_module (shared)

# curl -vIL --http2 http://www.downtown.jp/
*   Trying 2401:2500:102:2120:153:120:6:47...
* Connected to www.downtown.jp (2401:2500:102:2120:153:120:6:47) port 80 (#0)
> HEAD / HTTP/1.1
> Host: www.downtown.jp
> User-Agent: curl/7.46.0
> Accept: */*
> Connection: Upgrade, HTTP2-Settings
> Upgrade: h2c
> HTTP2-Settings: AAMAAABkAAQAAP__
>
< HTTP/1.1 101 Switching Protocols
HTTP/1.1 101 Switching Protocols
< Upgrade: h2c
Upgrade: h2c
< Connection: Upgrade
Connection: Upgrade
* Received 101
* Using HTTP2, server supports multi-use
* Connection state changed (HTTP/2 confirmed)
* TCP_NODELAY set
* Copying HTTP/2 data in stream buffer to connection buffer after upgrade: len=0

< HTTP/2.0 200
HTTP/2.0 200
< date:Fri, 15 Jan 2016 12:21:53 GMT
date:Fri, 15 Jan 2016 12:21:53 GMT
< server:Apache/2.4.18 (Debian)
server:Apache/2.4.18 (Debian)
< accept-ranges:bytes
accept-ranges:bytes
< vary:Accept-Encoding
vary:Accept-Encoding
< cache-control:max-age=0
cache-control:max-age=0
< expires:Fri, 15 Jan 2016 12:21:53 GMT
expires:Fri, 15 Jan 2016 12:21:53 GMT
< content-length:13692
content-length:13692
< content-type:text/html
content-type:text/html

<
* Connection #0 to host www.downtown.jp left intact
Comment 1 Stefan Eissing 2016-01-19 12:45:34 UTC
Thanks, that did indeed slip my attention. This is fixed in revision 1725496 in trunk. It will be back ported to the next 2.4.x release.

Additionally, I will make it available in the next release on https://github.com/icing/mod_h2 if you want to test drive it earlier.

Thanks!