* Fixed reporting of transferred bytes for mod_logio for modifiers %…

…O (and %S) to

   report the number of transferred header and body lengths. This is still only
   an approximation of the bytes on the connection. The data is subject to header
   compression and h2 framing afterwards. Grain of salt. Fixes #203.

ChangeLog

@@ -1,5 +1,7 @@
- * Changed logio reporting of bytes sent for a stream. Should now reflect the actual
- payload bytes sent to the client.
+ * Fixed reporting of transferred bytes for mod_logio for modifiers %O (and %S) to
+ report the number of transferred header and body lengths. This is still only
+ an approximation of the bytes on the connection. The data is subject to header
+ compression and h2 framing afterwards. Grain of salt. Fixes #203.
 
 v1.15.14
 --------------------------------------------------------------------------------

http2_test.sh

@@ -0,0 +1,53 @@
+#!/bin/bash
+set -u
+
+function curl() {
+ command curl "$@" --limit-rate 5M \
+ -o /dev/null -w "HTTP/%{http_version}" -m 5 \
+ 2>&1 | grep -v 'Operation timed out after'
+ echo; echo
+}
+
+[ "$#" -eq 1 ] || {
+ echo "Usage: $0 URL" >&2
+ exit 1
+}
+
+SRV="$1"; shift
+
+###
+
+UNIQ_ID="test_id=$(date +%s)"
+URI="$SRV?$UNIQ_ID"
+
+echo "### Performing test with ID $UNIQ_ID"
+echo "### grep $UNIQ_ID /var/log/access.mod_h2_issue_203"
+echo
+
+echo "# http2_whole_ssl"
+curl --http2 "https://$URI&_http2_whole_ssl___"
+
+echo "# http11_whole_ssl"
+curl --http1.1 "https://$URI&http11_whole_ssl___"
+
+echo "# http10_whole_ssl"
+curl --http1.0 "https://$URI&http10_whole_ssl___"
+
+###
+
+echo "# http2_whole_nonssl"
+curl --http2 "http:https://$URI&_http2_whole_nonssl"
+
+echo "# http11_whole_nonssl"
+curl --http1.1 "http:https://$URI&http11_whole_nonssl"
+
+echo "# http10_whole_nonssl"
+curl --http1.0 "http:https://$URI&http10_whole_nonssl"
+
+###
+
+echo "# http2_half_ssl"
+curl --http2 -H "Range: bytes=0-52428800" "https://$URI&_http2_half_ssl____"
+
+echo "# http11_half_ssl"
+curl --http1.1 -H "Range: bytes=0-52428800" "https://$URI&http11_half_ssl____"

mod_http2/h2_bucket_beam.c

@@ -1042,6 +1042,7 @@ apr_status_t h2_beam_receive(h2_bucket_beam *beam,
  H2_BLIST_INSERT_TAIL(&beam->hold_list, bsender);
 
  remain -= bsender->length;
+ beam->received_bytes += bsender->length;
  ++transferred;
  ++transferred_buckets;
  continue;

mod_http2/h2_headers.c

@@ -64,6 +64,7 @@ apr_bucket * h2_bucket_headers_make(apr_bucket *b, h2_headers *r)
 
  b = apr_bucket_shared_make(b, br, 0, 0);
  b->type = &h2_bucket_type_headers;
+ b->length = h2_headers_length(r);
 
  return b;
 } 
@@ -125,6 +126,20 @@ h2_headers *h2_headers_create(int status, apr_table_t *headers_in,
  return headers;
 }
 
+static int add_header_lengths(void *ctx, const char *name, const char *value) 
+{
+ apr_size_t *plen = ctx;
+ *plen += strlen(name) + strlen(value); 
+ return 1;
+}
+
+apr_size_t h2_headers_length(h2_headers *headers)
+{
+ apr_size_t len = 0;
+ apr_table_do(add_header_lengths, &len, headers->headers, NULL);
+ return len;
+}
+
 h2_headers *h2_headers_rcreate(request_rec *r, int status,
  apr_table_t *header, apr_pool_t *pool)
 {

mod_http2/h2_headers.h

@@ -81,4 +81,9 @@ h2_headers *h2_headers_die(apr_status_t type,
 
 int h2_headers_are_response(h2_headers *headers);
 
+/**
+ * Give the number of bytes of all contained header strings.
+ */
+apr_size_t h2_headers_length(h2_headers *headers);
+
 #endif /* defined(__mod_h2__h2_headers__) */

test/e2e/TestEnv.py

@@ -54,6 +54,7 @@ def init( cls ) :
 
  cls.HTTPD_CONF_DIR = os.path.join(cls.WEBROOT, "conf")
  cls.HTTPD_DOCS_DIR = os.path.join(cls.WEBROOT, "htdocs")
+ cls.HTTPD_LOGS_DIR = os.path.join(cls.WEBROOT, "logs")
  cls.HTTPD_TEST_CONF = os.path.join(cls.HTTPD_CONF_DIR, "test.conf")
  cls.E2E_DIR = os.path.join(cls.TEST_DIR, "e2e")
 

test/e2e/test_004_post.py

@@ -4,6 +4,7 @@
 #
 
 import copy
+import json
 import os
 import re
 import sys
@@ -175,3 +176,41 @@ def test_004_25(self):
  self.nghttp_upload_and_verify( "data-100k", [ "--no-content-length" ] )
  self.nghttp_upload_and_verify( "data-1m", [ "--no-content-length" ] )
 
+ def test_004_30(self):
+ # issue: #203
+ resource = "data-1k"
+ full_length = 1000
+ chunk = 200
+ self.curl_upload_and_verify( resource, [ "-v", "--http2"] )
+ logfile = os.path.join(TestEnv.HTTPD_LOGS_DIR, "test_004_30")
+ if os.path.isfile(logfile):
+ os.remove(logfile)
+ HttpdConf().add_line("""
+LogFormat "{ \\"request\\": \\"%r\\", \\"status\\": %>s, \\"bytes_resp_B\\": %B, \\"bytes_tx_O\\": %O, \\"bytes_rx_I\\": %I, \\"bytes_rx_tx_S\\": %S }" issue_203
+CustomLog logs/test_004_30 issue_203
+ """).add_vhost_cgi().install()
+ assert TestEnv.apache_restart() == 0
+ url = TestEnv.mkurl("https", "cgi", "/files/{0}".format(resource))
+ r = TestEnv.curl_get(url, 5, ["--http2"])
+ assert 200 == r["response"]["status"]
+ r = TestEnv.curl_get(url, 5, ["--http1.1", "-H", "Range: bytes=0-{0}".format(chunk-1)])
+ assert 206 == r["response"]["status"]
+ assert chunk == len(r["response"]["body"].decode('utf-8'))
+ r = TestEnv.curl_get(url, 5, ["--http2", "-H", "Range: bytes=0-{0}".format(chunk-1)])
+ assert 206 == r["response"]["status"]
+ assert chunk == len(r["response"]["body"].decode('utf-8'))
+ # now check what response lengths have actually been reported
+ lines = open(logfile).readlines()
+ log_h2_full = json.loads(lines[-3])
+ log_h1 = json.loads(lines[-2])
+ log_h2 = json.loads(lines[-1])
+ assert log_h2_full['bytes_rx_I'] > 0
+ assert log_h2_full['bytes_resp_B'] == full_length
+ assert log_h2_full['bytes_tx_O'] > full_length
+ assert log_h1['bytes_rx_I'] > 0 # input bytes recieved
+ assert log_h1['bytes_resp_B'] == chunk # response bytes sent (payload)
+ assert log_h1['bytes_tx_O'] > chunk # output bytes sent
+ assert log_h2['bytes_rx_I'] > 0
+ assert log_h2['bytes_resp_B'] == chunk
+ assert log_h2['bytes_tx_O'] > chunk
+