From: Willy Tarreau <w@1wt.eu>
Date: Fri, 20 Oct 2023 15:47:33 +0000 (+0200)
Subject: MINOR: mux-h2/traces: clarify the "rejected H2 request" event
X-Git-Tag: v2.9-dev8~3
X-Git-Url: http://git.ipfire.org/?a=commitdiff_plain;h=08f3bb5bd567fda7f326723eb0c7f94a930f638a;p=thirdparty%2Fhaproxy.git

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 8544dcc52a..ee5d0deda9 100644
--- 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;
 }