[nginx] HTTP/2: added debug logging of response headers.

[Valentin Bartenev]

details:   http://hg.nginx.org/nginx/rev/6812ca9a8002
branches:  
changeset: 6401:6812ca9a8002
user:      Valentin Bartenev <vbart at nginx.com>
date:      Tue Feb 16 17:49:14 2016 +0300
description:
HTTP/2: added debug logging of response headers.

Because of HPACK compression it's hard to see what headers are actually
sent by the server.

diffstat:

 src/http/v2/ngx_http_v2_filter_module.c |  41 +++++++++++++++++++++++++++++++++
 1 files changed, 41 insertions(+), 0 deletions(-)

diffs (107 lines):

diff -r b4c28876d2c3 -r 6812ca9a8002 src/http/v2/ngx_http_v2_filter_module.c
--- a/src/http/v2/ngx_http_v2_filter_module.c	Tue Feb 16 17:49:14 2016 +0300
+++ b/src/http/v2/ngx_http_v2_filter_module.c	Tue Feb 16 17:49:14 2016 +0300
@@ -421,6 +421,10 @@ ngx_http_v2_header_filter(ngx_http_reque
 
     start = pos;
 
+    ngx_log_debug1(NGX_LOG_DEBUG_HTTP, fc->log, 0,
+                   "http2 output header: \":status: %03ui\"",
+                   r->headers_out.status);
+
     if (status) {
         *pos++ = status;
 
@@ -431,6 +435,10 @@ ngx_http_v2_header_filter(ngx_http_reque
     }
 
     if (r->headers_out.server == NULL) {
+        ngx_log_debug1(NGX_LOG_DEBUG_HTTP, fc->log, 0,
+                       "http2 output header: \"server: %s\"",
+                       clcf->server_tokens ? NGINX_VER : "nginx");
+
         *pos++ = ngx_http_v2_inc_indexed(NGX_HTTP_V2_SERVER_INDEX);
 
         if (clcf->server_tokens) {
@@ -448,6 +456,10 @@ ngx_http_v2_header_filter(ngx_http_reque
     }
 
     if (r->headers_out.date == NULL) {
+        ngx_log_debug1(NGX_LOG_DEBUG_HTTP, fc->log, 0,
+                       "http2 output header: \"date: %V\"",
+                       &ngx_cached_http_time);
+
         *pos++ = ngx_http_v2_inc_indexed(NGX_HTTP_V2_DATE_INDEX);
         pos = ngx_http_v2_write_value(pos, ngx_cached_http_time.data,
                                       ngx_cached_http_time.len, tmp);
@@ -481,6 +493,10 @@ ngx_http_v2_header_filter(ngx_http_reque
             r->headers_out.content_type.data = p - len;
         }
 
+        ngx_log_debug1(NGX_LOG_DEBUG_HTTP, fc->log, 0,
+                       "http2 output header: \"content-type: %V\"",
+                       &r->headers_out.content_type);
+
         pos = ngx_http_v2_write_value(pos, r->headers_out.content_type.data,
                                       r->headers_out.content_type.len, tmp);
     }
@@ -488,6 +504,10 @@ ngx_http_v2_header_filter(ngx_http_reque
     if (r->headers_out.content_length == NULL
         && r->headers_out.content_length_n >= 0)
     {
+        ngx_log_debug1(NGX_LOG_DEBUG_HTTP, fc->log, 0,
+                       "http2 output header: \"content-length: %O\"",
+                       r->headers_out.content_length_n);
+
         *pos++ = ngx_http_v2_inc_indexed(NGX_HTTP_V2_CONTENT_LENGTH_INDEX);
 
         p = pos;
@@ -503,6 +523,10 @@ ngx_http_v2_header_filter(ngx_http_reque
         ngx_http_time(pos, r->headers_out.last_modified_time);
         len = sizeof("Wed, 31 Dec 1986 18:00:00 GMT") - 1;
 
+        ngx_log_debug2(NGX_LOG_DEBUG_HTTP, fc->log, 0,
+                       "http2 output header: \"last-modified: %*s\"",
+                       len, pos);
+
         /*
          * Date will always be encoded using huffman in the temporary buffer,
          * so it's safe here to use src and dst pointing to the same address.
@@ -511,6 +535,10 @@ ngx_http_v2_header_filter(ngx_http_reque
     }
 
     if (r->headers_out.location && r->headers_out.location->value.len) {
+        ngx_log_debug1(NGX_LOG_DEBUG_HTTP, fc->log, 0,
+                       "http2 output header: \"location: %V\"",
+                       &r->headers_out.location->value);
+
         *pos++ = ngx_http_v2_inc_indexed(NGX_HTTP_V2_LOCATION_INDEX);
         pos = ngx_http_v2_write_value(pos, r->headers_out.location->value.data,
                                       r->headers_out.location->value.len, tmp);
@@ -518,6 +546,9 @@ ngx_http_v2_header_filter(ngx_http_reque
 
 #if (NGX_HTTP_GZIP)
     if (r->gzip_vary) {
+        ngx_log_debug0(NGX_LOG_DEBUG_HTTP, fc->log, 0,
+                       "http2 output header: \"vary: Accept-Encoding\"");
+
         *pos++ = ngx_http_v2_inc_indexed(NGX_HTTP_V2_VARY_INDEX);
         pos = ngx_cpymem(pos, accept_encoding, sizeof(accept_encoding));
     }
@@ -542,6 +573,16 @@ ngx_http_v2_header_filter(ngx_http_reque
             continue;
         }
 
+#if (NGX_DEBUG)
+        if (fc->log->log_level & NGX_LOG_DEBUG_HTTP) {
+            ngx_strlow(tmp, header[i].key.data, header[i].key.len);
+
+            ngx_log_debug3(NGX_LOG_DEBUG_HTTP, fc->log, 0,
+                           "http2 output header: \"%*s: %V\"",
+                           header[i].key.len, tmp, &header[i].value);
+        }
+#endif
+
         *pos++ = 0;
 
         pos = ngx_http_v2_write_name(pos, header[i].key.data,