MINOR: mux-h2/traces: clarify the "rejected H2 request" event

In h2_frt_handle_headers() all failures lead to a generic message saying
"rejected H2 request". It's quite inexpressive while there are a few
distinct tests that are made before jumping there:

  - trailers on closed stream
  - unparsable request
  - refused stream

Let's emit the traces from these call points instead so that we get more
info about what happened. Since these are user-level messages, we take
care of keeping them aligned as much as possible.

For example before it would say:

  [04|h2|1|mux_h2.c:2859] rejected H2 request : h2c=0x7f5d58036fd0(F,FRE)
  [04|h2|5|mux_h2.c:2860] h2c_frt_handle_headers(): leaving on error : h2c=0x7f5d58036fd0(F,FRE) dsi=1 h2s=0x9fdb60(0,CLO)

And now it says:

  [04|h2|1|mux_h2.c:2817] rcvd unparsable H2 request : h2c=0x7f55f8037160(F,FRH) dsi=1 h2s=CLO
  [04|h2|5|mux_h2.c:2875] h2c_frt_handle_headers(): leaving on error : h2c=0x7f55f8037160(F,FRE) dsi=1 h2s=CLO

diff --git a/src/mux_h2.c b/src/mux_h2.c
index 8544dcc52ac90a23aa0b4e9d83f54c5e0780e3c6..ee5d0deda9afb40c0ee2ef2cd84f36cc3d71be70 100644 (file)
--- a/src/mux_h2.c
+++ b/src/mux_h2.c
@@ -2764,12 +2764,13 @@ static struct h2s *h2c_frt_handle_headers(struct h2c *h2c, struct h2s *h2s)
                        }
                        goto done;
                }
-               /* the connection was already killed by an RST, let's consume
+               /* the stream was already killed by an RST, let's consume
                 * the data and send another RST.
                 */
                error = h2c_dec_hdrs(h2c, &rxbuf, &flags, &body_len, NULL);
                sess_log(h2c->conn->owner);
                h2s = (struct h2s*)h2_error_stream;
+               TRACE_USER("rcvd H2 trailers on closed stream", H2_EV_RX_FRAME|H2_EV_RX_HDR|H2_EV_STRM_NEW|H2_EV_STRM_END, h2c->conn, h2s, &rxbuf);
                goto send_rst;
        }
        else if (h2c->dsi <= h2c->max_id || !(h2c->dsi & 1)) {
@@ -2805,6 +2806,7 @@ static struct h2s *h2c_frt_handle_headers(struct h2c *h2c, struct h2s *h2s)
                 */
                sess_log(h2c->conn->owner);
                h2s = (struct h2s*)h2_error_stream;
+               TRACE_USER("rcvd unparsable H2 request", H2_EV_RX_FRAME|H2_EV_RX_HDR|H2_EV_STRM_NEW|H2_EV_STRM_END, h2c->conn, h2s, &rxbuf);
                goto send_rst;
        }
 
@@ -2816,7 +2818,7 @@ static struct h2s *h2c_frt_handle_headers(struct h2c *h2c, struct h2s *h2s)
        if (h2c->dsi > h2c->max_id)
                h2c->max_id = h2c->dsi;
 
-       /* Note: we don't emit any other logs below because ff we return
+       /* Note: we don't emit any other logs below because if we return
         * positively from h2c_frt_stream_new(), the stream will report the error,
         * and if we return in error, h2c_frt_stream_new() will emit the error.
         *
@@ -2826,6 +2828,7 @@ static struct h2s *h2c_frt_handle_headers(struct h2c *h2c, struct h2s *h2s)
        h2s = h2c_frt_stream_new(h2c, h2c->dsi, &rxbuf, flags);
        if (!h2s) {
                h2s = (struct h2s*)h2_refused_stream;
+               TRACE_USER("refused H2 req.  ", H2_EV_RX_FRAME|H2_EV_RX_HDR|H2_EV_STRM_NEW|H2_EV_STRM_END, h2c->conn, h2s, &rxbuf);
                goto send_rst;
        }
 
@@ -2861,7 +2864,6 @@ static struct h2s *h2c_frt_handle_headers(struct h2c *h2c, struct h2s *h2s)
        h2_release_buf(h2c, &rxbuf);
        h2c->st0 = H2_CS_FRAME_E;
 
-       TRACE_USER("rejected H2 request", H2_EV_RX_FRAME|H2_EV_RX_HDR|H2_EV_STRM_NEW|H2_EV_STRM_END, h2c->conn, h2s, &rxbuf);
        TRACE_DEVEL("leaving on error", H2_EV_RX_FRAME|H2_EV_RX_HDR, h2c->conn, h2s);
        return h2s;
 }