[PATCH] HTTP/2: add debug logging of control frames

[Piotr Sikora via nginx-devel]

# HG changeset patch
# User Piotr Sikora 
# Date 1490516711 25200
#  Sun Mar 26 01:25:11 2017 -0700
# Node ID 7414a1467d0684a73d091c508834973b944890cd
# Parent  22be63bf21edaa1b8ea916c7d8cd4e5fe4892061
HTTP/2: add debug logging of control frames.

Signed-off-by: Piotr Sikora 

diff -r 22be63bf21ed -r 7414a1467d06 src/http/v2/ngx_http_v2.c
--- a/src/http/v2/ngx_http_v2.c
+++ b/src/http/v2/ngx_http_v2.c
@@ -40,9 +40,11 @@
 
 /* settings fields */
 #define NGX_HTTP_V2_HEADER_TABLE_SIZE_SETTING0x1
+#define NGX_HTTP_V2_ENABLE_PUSH_SETTING  0x2
 #define NGX_HTTP_V2_MAX_STREAMS_SETTING  0x3
 #define NGX_HTTP_V2_INIT_WINDOW_SIZE_SETTING 0x4
 #define NGX_HTTP_V2_MAX_FRAME_SIZE_SETTING   0x5
+#define NGX_HTTP_V2_HEADER_LIST_SIZE_SETTING 0x6
 
 #define NGX_HTTP_V2_FRAME_BUFFER_SIZE24
 
@@ -1955,6 +1957,9 @@ ngx_http_v2_state_settings(ngx_http_v2_c
 return ngx_http_v2_connection_error(h2c, NGX_HTTP_V2_SIZE_ERROR);
 }
 
+ngx_log_debug0(NGX_LOG_DEBUG_HTTP, h2c->connection->log, 0,
+   "http2 SETTINGS frame ack:1");
+
 h2c->settings_ack = 1;
 
 return ngx_http_v2_state_complete(h2c, pos, end);
@@ -1968,6 +1973,10 @@ ngx_http_v2_state_settings(ngx_http_v2_c
 return ngx_http_v2_connection_error(h2c, NGX_HTTP_V2_SIZE_ERROR);
 }
 
+ngx_log_debug1(NGX_LOG_DEBUG_HTTP, h2c->connection->log, 0,
+   "http2 SETTINGS frame params:%uz",
+   h2c->state.length / NGX_HTTP_V2_SETTINGS_PARAM_SIZE);
+
 ngx_http_v2_send_settings(h2c, 1);
 
 return ngx_http_v2_state_settings_params(h2c, pos, end);
@@ -1993,6 +2002,27 @@ ngx_http_v2_state_settings_params(ngx_ht
 
 switch (id) {
 
+case NGX_HTTP_V2_HEADER_TABLE_SIZE_SETTING:
+
+ngx_log_debug1(NGX_LOG_DEBUG_HTTP, h2c->connection->log, 0,
+   "http2 SETTINGS frame HEADER_TABLE_SIZE:%ui "
+   "(ignored)", value);
+break;
+
+case NGX_HTTP_V2_ENABLE_PUSH_SETTING:
+
+ngx_log_debug1(NGX_LOG_DEBUG_HTTP, h2c->connection->log, 0,
+   "http2 SETTINGS frame ENABLE_PUSH:%ui "
+   "(ignored)", value);
+break;
+
+case NGX_HTTP_V2_MAX_STREAMS_SETTING:
+
+ngx_log_debug1(NGX_LOG_DEBUG_HTTP, h2c->connection->log, 0,
+   "http2 SETTINGS frame MAX_CONCURRENT_STREAMS:%ui "
+   "(ignored)", value);
+break;
+
 case NGX_HTTP_V2_INIT_WINDOW_SIZE_SETTING:
 
 if (value > NGX_HTTP_V2_MAX_WINDOW) {
@@ -2004,6 +2034,10 @@ ngx_http_v2_state_settings_params(ngx_ht
   NGX_HTTP_V2_FLOW_CTRL_ERROR);
 }
 
+ngx_log_debug1(NGX_LOG_DEBUG_HTTP, h2c->connection->log, 0,
+   "http2 SETTINGS frame INITIAL_WINDOW_SIZE:%ui",
+   value);
+
 if (ngx_http_v2_adjust_windows(h2c, value - h2c->init_window)
 != NGX_OK)
 {
@@ -2026,10 +2060,25 @@ ngx_http_v2_state_settings_params(ngx_ht
 
NGX_HTTP_V2_PROTOCOL_ERROR);
 }
 
+ngx_log_debug1(NGX_LOG_DEBUG_HTTP, h2c->connection->log, 0,
+   "http2 SETTINGS frame MAX_FRAME_SIZE:%ui",
+   value);
+
 h2c->frame_size = value;
 break;
 
+case NGX_HTTP_V2_HEADER_LIST_SIZE_SETTING:
+
+ngx_log_debug1(NGX_LOG_DEBUG_HTTP, h2c->connection->log, 0,
+   "http2 SETTINGS frame MAX_HEADER_LIST_SIZE:%ui "
+   "(ignored)", value);
+break;
+
 default:
+
+ngx_log_debug2(NGX_LOG_DEBUG_HTTP, h2c->connection->log, 0,
+   "http2 SETTINGS frame 0x%Xi:%ui "
+   "(ignored)", id, value);
 break;
 }
 
@@ -2070,12 +2119,16 @@ ngx_http_v2_state_ping(ngx_http_v2_conne
 }
 
 ngx_log_debug1(NGX_LOG_DEBUG_HTTP, h2c->connection->log, 0,
-   "http2 PING frame, flags: %ud", h2c->state.flags);
+   "http2 PING frame ack:%ud",
+   h2c->state.flags & NGX_HTTP_V2_ACK_FLAG ? 1 : 0);
 
 if (h2c->state.flags & NGX_HTTP_V2_ACK_FLAG) {
 return ngx_http_v2_state_skip(h2c, pos, end);
 }
 
+ngx_log_debug0(NGX_LOG_DEBUG_HTTP, h2c->connection->log, 0,
+   "http2 send PING frame ack:1");
+
 frame = ngx_http_v2_get_frame(h2c, NGX_HTTP_V2_PING_SIZE,
   NGX_HTTP_V2_PING_FRAME,
   NGX_HTTP_V2_ACK_FLAG, 0);
@@ -2449,8 +2502,18 @@ ngx_http_v2_send_settings(ngx_http_v2_co
 ngx_http_v2_srv_conf_t   *h2scf;
 ngx_http_v2_out_frame_t  *frame;
 
-

Re: [PATCH] HTTP/2: add debug logging of pseudo-headers

[Piotr Sikora via nginx-devel]

Hey Valentin,

> Maybe "http2 pseudo-header: \":%V: %V\""?
> Because it doesn't look like a valid "http header".

I was going back and forth between different versions, but I ended up
using "http header", which matches rest of the headers and has the
same alignment, because then pseudo-headers look like part of the same
logical block, i.e.

[debug] 1#1: *1 http2 http header: ":method: GET"
[debug] 1#1: *1 http2 http header: ":path: /h2x"
[debug] 1#1: *1 http2 http header: ":scheme: http"
[debug] 1#1: *1 http2 http header: ":authority: 127.0.0.1"
[debug] 1#1: *1 http2 http header: "accept: */*"
[debug] 1#1: *1 http2 http header: "accept-encoding: gzip, deflate"
[debug] 1#1: *1 http2 http header: "user-agent: nghttp2/1.21.0-DEV"

vs

[debug] 1#1: *1 http2 pseudo-header: ":method: GET"
[debug] 1#1: *1 http2 pseudo-header: ":path: /h2x"
[debug] 1#1: *1 http2 pseudo-header: ":scheme: http"
[debug] 1#1: *1 http2 pseudo-header: ":authority: 127.0.0.1"
[debug] 1#1: *1 http2 http header: "accept: */*"
[debug] 1#1: *1 http2 http header: "accept-encoding: gzip, deflate"
[debug] 1#1: *1 http2 http header: "user-agent: nghttp2/1.21.0-DEV"

vs

[debug] 1#1: *1 http2 http pseudo-header: ":method: GET"
[debug] 1#1: *1 http2 http pseudo-header: ":path: /h2x"
[debug] 1#1: *1 http2 http pseudo-header: ":scheme: http"
[debug] 1#1: *1 http2 http pseudo-header: ":authority: 127.0.0.1"
[debug] 1#1: *1 http2 http header: "accept: */*"
[debug] 1#1: *1 http2 http header: "accept-encoding: gzip, deflate"
[debug] 1#1: *1 http2 http header: "user-agent: nghttp2/1.21.0-DEV"

The ":" prefix already indicates those are pseudo-headers, and because
of different alignment, all the alternatives make them look like
unrelated things.

This might be just a matter of taste, though, so if you feel strongly
about one of the alternatives, then I can change it, just please be
explicit about it.

Best regards,
Piotr Sikora
___
nginx-devel mailing list
nginx-devel@nginx.org
http://mailman.nginx.org/mailman/listinfo/nginx-devel