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.
This commit is contained in:
Willy Tarreau
parent
271c440392
commit
11e8a8c2ac
127
src/mux_h2.c
127
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 @@ static int h2c_decode_headers(struct h2c *h2c, struct buffer *rxbuf, uint32_t *f
|
|||
/* 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;
|
||||
|
|
|
|||
Loading…
Reference in New Issue