MEDIUM: mux-h2/trace: add tracing support for headers

Now we can make use of TRACE_PRINTF() to iterate over headers as they
are received or dumped. It's worth noting that the dumps may occasionally
be interrupted due to a buffer full or a realign, but in this case it
will be visible because the trace will restart from the first one. All
these headers (and trailers) may be interleaved with other connections'
so they're all preceeded by the pointer to the connection and optionally
the stream (or alternately the stream ID) to help discriminating them.

Since it's not easy to read the header directions, sent headers are
prefixed with "sndh" and received headers are prefixed with "rcvh", both
of which are rare enough in the traces to conveniently support a quick
grep.

In order to avoid code duplication, h2_encode_headers() was implemented
as a wrapper on top of hpack_encode_header(), which optionally emits the
header to the trace if the trace is active. In addition, for headers that
are encoded using a different method, h2_trace_header() was added as well.

Header names are truncated to 256 bytes and values to 1024 bytes. If
the lengths are larger, they will be truncated and suffixed with
"(... +xxx)" where "xxx" is the number of extra bytes.

Example of what an end-to-end H2 request gives:

  [00|h2|5|mux_h2.c:4818] h2c_decode_headers(): h2c=0x1c13120(F,FRP) dsi=1 rcvh :method: GET
  [00|h2|5|mux_h2.c:4818] h2c_decode_headers(): h2c=0x1c13120(F,FRP) dsi=1 rcvh :path: /
  [00|h2|5|mux_h2.c:4818] h2c_decode_headers(): h2c=0x1c13120(F,FRP) dsi=1 rcvh :scheme: http
  [00|h2|5|mux_h2.c:4818] h2c_decode_headers(): h2c=0x1c13120(F,FRP) dsi=1 rcvh :authority: localhost:14446
  [00|h2|5|mux_h2.c:4818] h2c_decode_headers(): h2c=0x1c13120(F,FRP) dsi=1 rcvh user-agent: curl/7.54.1
  [00|h2|5|mux_h2.c:4818] h2c_decode_headers(): h2c=0x1c13120(F,FRP) dsi=1 rcvh accept: */*
  [00|h2|5|mux_h2.c:4818] h2c_decode_headers(): h2c=0x1c13120(F,FRP) dsi=1 rcvh cookie: blah
  [00|h2|5|mux_h2.c:5491] h2s_bck_make_req_headers(): h2c=0x1c1cd90(B,FRH) h2s=0x1c1e3d0(1,IDL) sndh :method: GET
  [00|h2|5|mux_h2.c:5572] h2s_bck_make_req_headers(): h2c=0x1c1cd90(B,FRH) h2s=0x1c1e3d0(1,IDL) sndh :authority: localhost:14446
  [00|h2|5|mux_h2.c:5596] h2s_bck_make_req_headers(): h2c=0x1c1cd90(B,FRH) h2s=0x1c1e3d0(1,IDL) sndh :path: /
  [00|h2|5|mux_h2.c:5647] h2s_bck_make_req_headers(): h2c=0x1c1cd90(B,FRH) h2s=0x1c1e3d0(1,IDL) sndh user-agent: curl/7.54.1
  [00|h2|5|mux_h2.c:5647] h2s_bck_make_req_headers(): h2c=0x1c1cd90(B,FRH) h2s=0x1c1e3d0(1,IDL) sndh accept: */*
  [00|h2|5|mux_h2.c:5647] h2s_bck_make_req_headers(): h2c=0x1c1cd90(B,FRH) h2s=0x1c1e3d0(1,IDL) sndh cookie: blah
  [00|h2|5|mux_h2.c:4818] h2c_decode_headers(): h2c=0x1c1cd90(B,FRP) dsi=1 rcvh :status: 200
  [00|h2|5|mux_h2.c:4818] h2c_decode_headers(): h2c=0x1c1cd90(B,FRP) dsi=1 rcvh content-length: 0
  [00|h2|5|mux_h2.c:4818] h2c_decode_headers(): h2c=0x1c1cd90(B,FRP) dsi=1 rcvh x-req: size=102, time=0 ms
  [00|h2|5|mux_h2.c:4818] h2c_decode_headers(): h2c=0x1c1cd90(B,FRP) dsi=1 rcvh x-rsp: id=dummy, code=200, cache=1, size=0, time=0 ms (0 real)
  [00|h2|5|mux_h2.c:5210] h2s_frt_make_resp_headers(): h2c=0x1c13120(F,FRH) h2s=0x1c1c780(1,HCR) sndh :status: 200
  [00|h2|5|mux_h2.c:5231] h2s_frt_make_resp_headers(): h2c=0x1c13120(F,FRH) h2s=0x1c1c780(1,HCR) sndh content-length: 0
  [00|h2|5|mux_h2.c:5231] h2s_frt_make_resp_headers(): h2c=0x1c13120(F,FRH) h2s=0x1c1c780(1,HCR) sndh x-req: size=102, time=0 ms
  [00|h2|5|mux_h2.c:5231] h2s_frt_make_resp_headers(): h2c=0x1c13120(F,FRH) h2s=0x1c1c780(1,HCR) sndh x-rsp: id=dummy, code=200, cache=1, size=0, time=0 ms (0 real)

At some point the frontend/backend names would be useful but that's a more
general comment than just the H2 traces.

diff --git a/src/mux_h2.c b/src/mux_h2.c
index 16ed74305b765a531fe53afb32afefdbce85e944..5684940882ed1452fca50d74e00ef0d3473218c9 100644 (file)
--- a/src/mux_h2.c
+++ b/src/mux_h2.c
@@ -840,6 +840,80 @@ static int h2_avail_streams(struct connection *conn)
        return ret1;
 }
 
+/* inconditionally produce a trace of the header. Please do not call this one
+ * and use h2_trace_header() instead which first checks if traces are enabled.
+ */
+void _h2_trace_header(const struct ist hn, const struct ist hv,
+                     uint64_t mask, const struct ist trc_loc, const char *func,
+                     const struct h2c *h2c, const struct h2s *h2s)
+{
+       struct ist n_ist, v_ist;
+       const char *c_str, *s_str;
+
+       chunk_reset(&trash);
+       c_str = chunk_newstr(&trash);
+       if (h2c) {
+               chunk_appendf(&trash, "h2c=%p(%c,%s) ",
+                             h2c, (h2c->flags & H2_CF_IS_BACK) ? 'B' : 'F', h2c_st_to_str(h2c->st0));
+       }
+
+       s_str = chunk_newstr(&trash);
+       if (h2s) {
+               if (h2s->id <= 0)
+                       chunk_appendf(&trash, "dsi=%d ", h2s->h2c->dsi);
+               chunk_appendf(&trash, "h2s=%p(%d,%s) ", h2s, h2s->id, h2s_st_to_str(h2s->st));
+       }
+       else if (h2c)
+               chunk_appendf(&trash, "dsi=%d ", h2c->dsi);
+
+       n_ist = ist2(chunk_newstr(&trash), 0);
+       istscpy(&n_ist, hn, 256);
+       trash.data += n_ist.len;
+       if (n_ist.len != hn.len)
+               chunk_appendf(&trash, " (... +%ld)", (long)(hn.len - n_ist.len));
+
+       v_ist = ist2(chunk_newstr(&trash), 0);
+       istscpy(&v_ist, hv, 1024);
+       trash.data += v_ist.len;
+       if (v_ist.len != hv.len)
+               chunk_appendf(&trash, " (... +%ld)", (long)(hv.len - v_ist.len));
+
+       TRACE_PRINTF_LOC(TRACE_LEVEL_USER, mask, trc_loc, func,
+                        h2c->conn, 0, 0, 0,
+                        "%s%s%s %s: %s", c_str, s_str,
+                        (mask & H2_EV_TX_HDR) ? "sndh" : "rcvh",
+                        n_ist.ptr, v_ist.ptr);
+}
+
+/* produce a trace of the header after checking that tracing is enabled */
+static inline void h2_trace_header(const struct ist hn, const struct ist hv,
+                                  uint64_t mask, const struct ist trc_loc, const char *func,
+                                  const struct h2c *h2c, const struct h2s *h2s)
+{
+       if ((TRACE_SOURCE)->verbosity >= H2_VERB_ADVANCED &&
+           TRACE_ENABLED(TRACE_LEVEL_USER, mask, h2c ? h2c->conn : 0, h2s, 0, 0))
+               _h2_trace_header(hn, hv, mask, trc_loc, func, h2c, h2s);
+}
+
+/* hpack-encode header name <hn> and value <hv>, possibly emitting a trace if
+ * currently enabled. This is done on behalf of function <func> at <trc_loc>
+ * passed as ist(TRC_LOC), h2c <h2c>, and h2s <h2s>, all of which may be NULL.
+ * The trace is only emitted if the header is emitted (in which case non-zero
+ * is returned). The trash is modified. In the traces, the header's name will
+ * be truncated to 256 chars and the header's value to 1024 chars.
+ */
+static inline int h2_encode_header(struct buffer *buf, const struct ist hn, const struct ist hv,
+                                  uint64_t mask, const struct ist trc_loc, const char *func,
+                                  const struct h2c *h2c, const struct h2s *h2s)
+{
+       int ret;
+
+       ret = hpack_encode_header(buf, hn, hv);
+       if (ret)
+               h2_trace_header(hn, hv, mask, trc_loc, func, h2c, h2s);
+
+       return ret;
+}
 
 /*****************************************************************/
 /* functions below are dedicated to the mux setup and management */
@@ -4729,6 +4803,26 @@ next_frame:
        /* past this point we cannot roll back in case of error */
        outlen = hpack_decode_frame(h2c->ddht, hdrs, flen, list,
                                    sizeof(list)/sizeof(list[0]), tmp);
+
+       if (outlen > 0 &&
+           (TRACE_SOURCE)->verbosity >= H2_VERB_ADVANCED &&
+           TRACE_ENABLED(TRACE_LEVEL_USER, H2_EV_RX_FRAME|H2_EV_RX_HDR, h2c->conn, 0, 0, 0)) {
+               struct ist n;
+               int i;
+
+               for (i = 0; list[i].n.len; i++) {
+                       n = list[i].n;
+
+                       if (!isttest(n)) {
+                               /* this is in fact a pseudo header whose number is in n.len */
+                               n = h2_phdr_to_ist(n.len);
+                       }
+
+                       h2_trace_header(n, list[i].v, H2_EV_RX_FRAME|H2_EV_RX_HDR,
+                                       ist(TRC_LOC), __FUNCTION__, h2c, NULL);
+               }
+       }
+
        if (outlen < 0) {
                TRACE_STATE("failed to decompress HPACK", H2_EV_RX_FRAME|H2_EV_RX_HDR|H2_EV_H2C_ERR|H2_EV_PROTO_ERR, h2c->conn);
                h2c_error(h2c, H2_ERR_COMPRESSION_ERROR);
@@ -5113,6 +5207,14 @@ static size_t h2s_frt_make_resp_headers(struct h2s *h2s, struct htx *htx)
                goto full;
        }
 
+       if ((TRACE_SOURCE)->verbosity >= H2_VERB_ADVANCED) {
+               char sts[4];
+
+               h2_trace_header(ist(":status"), ist(ultoa_r(h2s->status, sts, sizeof(sts))),
+                                   H2_EV_TX_FRAME|H2_EV_TX_HDR, ist(TRC_LOC), __FUNCTION__,
+                                   h2c, h2s);
+       }
+
        /* encode all headers, stop at empty name */
        for (hdr = 0; hdr < sizeof(list)/sizeof(list[0]); hdr++) {
                /* these ones do not exist in H2 and must be dropped. */
@@ -5130,7 +5232,8 @@ static size_t h2s_frt_make_resp_headers(struct h2s *h2s, struct htx *htx)
                if (isteq(list[hdr].n, ist("")))
                        break; // end
 
-               if (!hpack_encode_header(&outbuf, list[hdr].n, list[hdr].v)) {
+               if (!h2_encode_header(&outbuf, list[hdr].n, list[hdr].v, H2_EV_TX_FRAME|H2_EV_TX_HDR,
+                                     ist(TRC_LOC), __FUNCTION__, h2c, h2s)) {
                        /* output full */
                        if (b_space_wraps(mbuf))
                                goto realign_again;
@@ -5390,6 +5493,8 @@ static size_t h2s_bck_make_req_headers(struct h2s *h2s, struct htx *htx)
                goto full;
        }
 
+       h2_trace_header(ist(":method"), meth, H2_EV_TX_FRAME|H2_EV_TX_HDR, ist(TRC_LOC), __FUNCTION__, h2c, h2s);
+
        auth = ist(NULL);
 
        /* RFC7540 #8.3: the CONNECT method must have :
@@ -5403,12 +5508,14 @@ static size_t h2s_bck_make_req_headers(struct h2s *h2s, struct htx *htx)
        if (unlikely(sl->info.req.meth == HTTP_METH_CONNECT) && !extended_connect) {
                auth = uri;
 
-               if (!hpack_encode_header(&outbuf, ist(":authority"), auth)) {
+               if (!h2_encode_header(&outbuf, ist(":authority"), auth, H2_EV_TX_FRAME|H2_EV_TX_HDR,
+                                     ist(TRC_LOC), __FUNCTION__, h2c, h2s)) {
                        /* output full */
                        if (b_space_wraps(mbuf))
                                goto realign_again;
                        goto full;
                }
+
                h2s->flags |= H2_SF_BODY_TUNNEL;
        } else {
                /* other methods need a :scheme. If an authority is known from
@@ -5468,7 +5575,9 @@ static size_t h2s_bck_make_req_headers(struct h2s *h2s, struct htx *htx)
                        goto full;
                }
 
-               if (auth.len && !hpack_encode_header(&outbuf, ist(":authority"), auth)) {
+               if (auth.len &&
+                   !h2_encode_header(&outbuf, ist(":authority"), auth, H2_EV_TX_FRAME|H2_EV_TX_HDR,
+                                     ist(TRC_LOC), __FUNCTION__, h2c, h2s)) {
                        /* output full */
                        if (b_space_wraps(mbuf))
                                goto realign_again;
@@ -5492,15 +5601,16 @@ static size_t h2s_bck_make_req_headers(struct h2s *h2s, struct htx *htx)
                        goto full;
                }
 
+               h2_trace_header(ist(":path"), uri, H2_EV_TX_FRAME|H2_EV_TX_HDR, ist(TRC_LOC), __FUNCTION__, h2c, h2s);
+
                /* encode the pseudo-header protocol from rfc8441 if using
                 * Extended CONNECT method.
                 */
                if (unlikely(extended_connect)) {
                        const struct ist protocol = ist(h2s->upgrade_protocol);
                        if (isttest(protocol)) {
-                               if (!hpack_encode_header(&outbuf,
-                                                        ist(":protocol"),
-                                                        protocol)) {
+                               if (!h2_encode_header(&outbuf, ist(":protocol"), protocol, H2_EV_TX_FRAME|H2_EV_TX_HDR,
+                                                     ist(TRC_LOC), __FUNCTION__, h2c, h2s)) {
                                        /* output full */
                                        if (b_space_wraps(mbuf))
                                                goto realign_again;
@@ -5543,7 +5653,7 @@ static size_t h2s_bck_make_req_headers(struct h2s *h2s, struct htx *htx)
                if (isteq(n, ist("")))
                        break; // end
 
-               if (!hpack_encode_header(&outbuf, n, v)) {
+               if (!h2_encode_header(&outbuf, n, v, H2_EV_TX_FRAME|H2_EV_TX_HDR, ist(TRC_LOC), __FUNCTION__, h2c, h2s)) {
                        /* output full */
                        if (b_space_wraps(mbuf))
                                goto realign_again;
@@ -6091,7 +6201,8 @@ static size_t h2s_make_trailers(struct h2s *h2s, struct htx *htx)
                if (*(list[idx].n.ptr) == ':')
                        continue;
 
-               if (!hpack_encode_header(&outbuf, list[idx].n, list[idx].v)) {
+               if (!h2_encode_header(&outbuf, list[idx].n, list[idx].v, H2_EV_TX_FRAME|H2_EV_TX_HDR,
+                                     ist(TRC_LOC), __FUNCTION__, h2c, h2s)) {
                        /* output full */
                        if (b_space_wraps(mbuf))
                                goto realign_again;