MINOR: mux-h2/trace: add traces at level ERROR for protocol errors

A number of traces could be added, and a few TRACE_PROTO were replaced
with TRACE_ERROR. The goal is to be able to enable error tracing only
to detect anomalies.

It looks like they're mostly correct as they don't seem to strike on
valid H2 traffic but are very verbose on h2spec.

diff --git a/src/mux_h2.c b/src/mux_h2.c
index b81d79970276e0ad553e4718acbb2aa87bd0a9d6..ce39f750b547a04d92c055475c4b142aa767cdf6 100644 (file)
--- a/src/mux_h2.c
+++ b/src/mux_h2.c
@@ -1666,6 +1666,7 @@ static int h2c_frt_recv_preface(struct h2c *h2c)
                        sess_log(h2c->conn->owner);
 
                if (ret1 < 0 || conn_xprt_read0_pending(h2c->conn)) {
+                       TRACE_ERROR("I/O error or short read", H2_EV_RX_FRAME|H2_EV_RX_PREFACE, h2c->conn);
                        h2c_error(h2c, H2_ERR_PROTOCOL_ERROR);
                        HA_ATOMIC_ADD(&h2c->px_counters->conn_proto_err, 1);
                }
@@ -2148,6 +2149,7 @@ static int h2c_handle_settings(struct h2c *h2c)
                        break;
                case H2_SETTINGS_MAX_FRAME_SIZE:
                        if (arg < 16384 || arg > 16777215) { // RFC7540#6.5.2
+                               TRACE_ERROR("MAX_FRAME_SIZE out of range", H2_EV_RX_FRAME|H2_EV_RX_SETTINGS, h2c->conn);
                                error = H2_ERR_PROTOCOL_ERROR;
                                HA_ATOMIC_ADD(&h2c->px_counters->conn_proto_err, 1);
                                goto fail;
@@ -2156,6 +2158,7 @@ static int h2c_handle_settings(struct h2c *h2c)
                        break;
                case H2_SETTINGS_ENABLE_PUSH:
                        if (arg < 0 || arg > 1) { // RFC7540#6.5.2
+                               TRACE_ERROR("ENABLE_PUSH out of range", H2_EV_RX_FRAME|H2_EV_RX_SETTINGS, h2c->conn);
                                error = H2_ERR_PROTOCOL_ERROR;
                                HA_ATOMIC_ADD(&h2c->px_counters->conn_proto_err, 1);
                                goto fail;
@@ -2426,12 +2429,14 @@ static int h2c_handle_window_update(struct h2c *h2c, struct h2s *h2s)
                        goto done;
 
                if (!inc) {
+                       TRACE_ERROR("stream WINDOW_UPDATE inc=0", H2_EV_RX_FRAME|H2_EV_RX_WU, h2c->conn, h2s);
                        error = H2_ERR_PROTOCOL_ERROR;
                        HA_ATOMIC_ADD(&h2c->px_counters->strm_proto_err, 1);
                        goto strm_err;
                }
 
                if (h2s_mws(h2s) >= 0 && h2s_mws(h2s) + inc < 0) {
+                       TRACE_ERROR("stream WINDOW_UPDATE inc<0", H2_EV_RX_FRAME|H2_EV_RX_WU, h2c->conn, h2s);
                        error = H2_ERR_FLOW_CONTROL_ERROR;
                        HA_ATOMIC_ADD(&h2c->px_counters->strm_proto_err, 1);
                        goto strm_err;
@@ -2449,6 +2454,7 @@ static int h2c_handle_window_update(struct h2c *h2c, struct h2s *h2s)
        else {
                /* connection window update */
                if (!inc) {
+                       TRACE_ERROR("conn WINDOW_UPDATE inc=0", H2_EV_RX_FRAME|H2_EV_RX_WU, h2c->conn);
                        error = H2_ERR_PROTOCOL_ERROR;
                        HA_ATOMIC_ADD(&h2c->px_counters->conn_proto_err, 1);
                        goto conn_err;
@@ -2521,6 +2527,7 @@ static int h2c_handle_priority(struct h2c *h2c)
 
        if (h2_get_n32(&h2c->dbuf, 0) == h2c->dsi) {
                /* 7540#5.3 : can't depend on itself */
+               TRACE_ERROR("PRIORITY depends on itself", H2_EV_RX_FRAME|H2_EV_RX_WU, h2c->conn);
                h2c_error(h2c, H2_ERR_PROTOCOL_ERROR);
                HA_ATOMIC_ADD(&h2c->px_counters->conn_proto_err, 1);
                TRACE_DEVEL("leaving on error", H2_EV_RX_FRAME|H2_EV_RX_PRIO, h2c->conn);
@@ -2617,6 +2624,7 @@ static struct h2s *h2c_frt_handle_headers(struct h2c *h2c, struct h2s *h2s)
        else if (h2c->dsi <= h2c->max_id || !(h2c->dsi & 1)) {
                /* RFC7540#5.1.1 stream id > prev ones, and must be odd here */
                error = H2_ERR_PROTOCOL_ERROR;
+               TRACE_ERROR("HEADERS on invalid stream ID", H2_EV_RX_FRAME|H2_EV_RX_HDR, h2c->conn);
                HA_ATOMIC_ADD(&h2c->px_counters->conn_proto_err, 1);
                sess_log(h2c->conn->owner);
                goto conn_err;
@@ -2735,6 +2743,7 @@ static struct h2s *h2c_bck_handle_headers(struct h2c *h2c, struct h2s *h2s)
 
        if (h2s->st != H2_SS_OPEN && h2s->st != H2_SS_HLOC) {
                /* RFC7540#5.1 */
+               TRACE_ERROR("response HEADERS in invalid state", H2_EV_RX_FRAME|H2_EV_RX_HDR, h2c->conn, h2s);
                h2s_error(h2s, H2_ERR_STREAM_CLOSED);
                h2c->st0 = H2_CS_FRAME_E;
                HA_ATOMIC_ADD(&h2c->px_counters->strm_proto_err, 1);
@@ -2746,6 +2755,7 @@ static struct h2s *h2c_bck_handle_headers(struct h2c *h2c, struct h2s *h2s)
                        goto fail; // missing data
 
                /* stream error : send RST_STREAM */
+               TRACE_ERROR("couldn't decode response HEADERS", H2_EV_RX_FRAME|H2_EV_RX_HDR, h2c->conn, h2s);
                h2s_error(h2s, H2_ERR_PROTOCOL_ERROR);
                h2c->st0 = H2_CS_FRAME_E;
                HA_ATOMIC_ADD(&h2c->px_counters->strm_proto_err, 1);
@@ -2813,6 +2823,7 @@ static int h2c_frt_handle_data(struct h2c *h2c, struct h2s *h2s)
 
        if ((h2s->flags & H2_SF_DATA_CLEN) && (h2c->dfl - h2c->dpl) > h2s->body_len) {
                /* RFC7540#8.1.2 */
+               TRACE_ERROR("DATA frame larger than content-length", H2_EV_RX_FRAME|H2_EV_RX_DATA, h2c->conn, h2s);
                error = H2_ERR_PROTOCOL_ERROR;
                HA_ATOMIC_ADD(&h2c->px_counters->strm_proto_err, 1);
                goto strm_err;
@@ -2857,6 +2868,7 @@ static int h2c_frt_handle_data(struct h2c *h2c, struct h2s *h2s)
 
                if (h2s->flags & H2_SF_DATA_CLEN && h2s->body_len) {
                        /* RFC7540#8.1.2 */
+                       TRACE_ERROR("ES on DATA frame before content-length", H2_EV_RX_FRAME|H2_EV_RX_DATA, h2c->conn, h2s);
                        error = H2_ERR_PROTOCOL_ERROR;
                        HA_ATOMIC_ADD(&h2c->px_counters->strm_proto_err, 1);
                        goto strm_err;
@@ -2889,6 +2901,7 @@ static int h2_frame_check_vs_state(struct h2c *h2c, struct h2s *h2s)
                /* RFC7540#5.1: any frame other than HEADERS or PRIORITY in
                 * this state MUST be treated as a connection error
                 */
+               TRACE_ERROR("invalid frame type for IDLE state", H2_EV_RX_FRAME|H2_EV_RX_FHDR, h2c->conn, h2s);
                h2c_error(h2c, H2_ERR_PROTOCOL_ERROR);
                if (!h2c->nb_streams && !(h2c->flags & H2_CF_IS_BACK)) {
                        /* only log if no other stream can report the error */
@@ -2901,6 +2914,7 @@ static int h2_frame_check_vs_state(struct h2c *h2c, struct h2s *h2s)
 
        if (h2s->st == H2_SS_IDLE && (h2c->flags & H2_CF_IS_BACK)) {
                /* only PUSH_PROMISE would be permitted here */
+               TRACE_ERROR("invalid frame type for IDLE state (back)", H2_EV_RX_FRAME|H2_EV_RX_FHDR, h2c->conn, h2s);
                h2c_error(h2c, H2_ERR_PROTOCOL_ERROR);
                HA_ATOMIC_ADD(&h2c->px_counters->conn_proto_err, 1);
                TRACE_DEVEL("leaving in error (idle&back)", H2_EV_RX_FRAME|H2_EV_RX_FHDR|H2_EV_PROTO_ERR, h2c->conn, h2s);
@@ -2915,6 +2929,7 @@ static int h2_frame_check_vs_state(struct h2c *h2c, struct h2s *h2s)
                 * PUSH_PROMISE/CONTINUATION cause connection errors.
                 */
                if (h2_ft_bit(h2c->dft) & H2_FT_HDR_MASK) {
+                       TRACE_ERROR("invalid frame type for HREM state", H2_EV_RX_FRAME|H2_EV_RX_FHDR, h2c->conn, h2s);
                        h2c_error(h2c, H2_ERR_PROTOCOL_ERROR);
                        HA_ATOMIC_ADD(&h2c->px_counters->conn_proto_err, 1);
                }
@@ -3051,7 +3066,7 @@ static void h2_process_demux(struct h2c *h2c)
                        if (!h2_get_frame_hdr(&h2c->dbuf, &hdr)) {
                                /* RFC7540#3.5: a GOAWAY frame MAY be omitted */
                                if (h2c->st0 == H2_CS_ERROR) {
-                                       TRACE_PROTO("failed to receive settings", H2_EV_RX_FRAME|H2_EV_RX_FHDR|H2_EV_RX_SETTINGS|H2_EV_PROTO_ERR, h2c->conn);
+                                       TRACE_ERROR("failed to receive settings", H2_EV_RX_FRAME|H2_EV_RX_FHDR|H2_EV_RX_SETTINGS|H2_EV_PROTO_ERR, h2c->conn);
                                        h2c->st0 = H2_CS_ERROR2;
                                        if (!(h2c->flags & H2_CF_IS_BACK))
                                                sess_log(h2c->conn->owner);
@@ -3061,7 +3076,7 @@ static void h2_process_demux(struct h2c *h2c)
 
                        if (hdr.sid || hdr.ft != H2_FT_SETTINGS || hdr.ff & H2_F_SETTINGS_ACK) {
                                /* RFC7540#3.5: a GOAWAY frame MAY be omitted */
-                               TRACE_PROTO("unexpected frame type or flags", H2_EV_RX_FRAME|H2_EV_RX_FHDR|H2_EV_RX_SETTINGS|H2_EV_PROTO_ERR, h2c->conn);
+                               TRACE_ERROR("unexpected frame type or flags", H2_EV_RX_FRAME|H2_EV_RX_FHDR|H2_EV_RX_SETTINGS|H2_EV_PROTO_ERR, h2c->conn);
                                h2c_error(h2c, H2_ERR_PROTOCOL_ERROR);
                                h2c->st0 = H2_CS_ERROR2;
                                if (!(h2c->flags & H2_CF_IS_BACK))
@@ -3072,7 +3087,7 @@ static void h2_process_demux(struct h2c *h2c)
 
                        if ((int)hdr.len < 0 || (int)hdr.len > global.tune.bufsize) {
                                /* RFC7540#3.5: a GOAWAY frame MAY be omitted */
-                               TRACE_PROTO("invalid settings frame length", H2_EV_RX_FRAME|H2_EV_RX_FHDR|H2_EV_RX_SETTINGS|H2_EV_PROTO_ERR, h2c->conn);
+                               TRACE_ERROR("invalid settings frame length", H2_EV_RX_FRAME|H2_EV_RX_FHDR|H2_EV_RX_SETTINGS|H2_EV_PROTO_ERR, h2c->conn);
                                h2c_error(h2c, H2_ERR_FRAME_SIZE_ERROR);
                                h2c->st0 = H2_CS_ERROR2;
                                if (!(h2c->flags & H2_CF_IS_BACK))
@@ -3112,7 +3127,7 @@ static void h2_process_demux(struct h2c *h2c)
                                break;
 
                        if ((int)hdr.len < 0 || (int)hdr.len > global.tune.bufsize) {
-                               TRACE_PROTO("invalid H2 frame length", H2_EV_RX_FRAME|H2_EV_RX_FHDR|H2_EV_PROTO_ERR, h2c->conn);
+                               TRACE_ERROR("invalid H2 frame length", H2_EV_RX_FRAME|H2_EV_RX_FHDR|H2_EV_PROTO_ERR, h2c->conn);
                                h2c_error(h2c, H2_ERR_FRAME_SIZE_ERROR);
                                if (!h2c->nb_streams && !(h2c->flags & H2_CF_IS_BACK)) {
                                        /* only log if no other stream can report the error */
@@ -3132,7 +3147,7 @@ static void h2_process_demux(struct h2c *h2c)
                                 * padlen in the flow control, so it must be adjusted.
                                 */
                                if (hdr.len < 1) {
-                                       TRACE_PROTO("invalid H2 padded frame length", H2_EV_RX_FRAME|H2_EV_RX_FHDR|H2_EV_PROTO_ERR, h2c->conn);
+                                       TRACE_ERROR("invalid H2 padded frame length", H2_EV_RX_FRAME|H2_EV_RX_FHDR|H2_EV_PROTO_ERR, h2c->conn);
                                        h2c_error(h2c, H2_ERR_FRAME_SIZE_ERROR);
                                        if (!(h2c->flags & H2_CF_IS_BACK))
                                                sess_log(h2c->conn->owner);
@@ -3147,7 +3162,7 @@ static void h2_process_demux(struct h2c *h2c)
                                padlen = *(uint8_t *)b_peek(&h2c->dbuf, 9);
 
                                if (padlen > hdr.len) {
-                                       TRACE_PROTO("invalid H2 padding length", H2_EV_RX_FRAME|H2_EV_RX_FHDR|H2_EV_PROTO_ERR, h2c->conn);
+                                       TRACE_ERROR("invalid H2 padding length", H2_EV_RX_FRAME|H2_EV_RX_FHDR|H2_EV_PROTO_ERR, h2c->conn);
                                        /* RFC7540#6.1 : pad length = length of
                                         * frame payload or greater => error.
                                         */
@@ -3178,7 +3193,7 @@ static void h2_process_demux(struct h2c *h2c)
                        /* check for minimum basic frame format validity */
                        ret = h2_frame_check(h2c->dft, 1, h2c->dsi, h2c->dfl, global.tune.bufsize);
                        if (ret != H2_ERR_NO_ERROR) {
-                               TRACE_PROTO("received invalid H2 frame header", H2_EV_RX_FRAME|H2_EV_RX_FHDR|H2_EV_PROTO_ERR, h2c->conn);
+                               TRACE_ERROR("received invalid H2 frame header", H2_EV_RX_FRAME|H2_EV_RX_FHDR|H2_EV_PROTO_ERR, h2c->conn);
                                h2c_error(h2c, ret);
                                if (!(h2c->flags & H2_CF_IS_BACK))
                                        sess_log(h2c->conn->owner);
@@ -3254,7 +3269,7 @@ static void h2_process_demux(struct h2c *h2c)
                         * frames' parsers consume all following CONTINUATION
                         * frames so this one is out of sequence.
                         */
-                       TRACE_PROTO("received unexpected H2 CONTINUATION frame", H2_EV_RX_FRAME|H2_EV_RX_CONT|H2_EV_H2C_ERR, h2c->conn, h2s);
+                       TRACE_ERROR("received unexpected H2 CONTINUATION frame", H2_EV_RX_FRAME|H2_EV_RX_CONT|H2_EV_H2C_ERR, h2c->conn, h2s);
                        h2c_error(h2c, H2_ERR_PROTOCOL_ERROR);
                        if (!(h2c->flags & H2_CF_IS_BACK))
                                sess_log(h2c->conn->owner);
@@ -4834,7 +4849,7 @@ static size_t h2s_frt_make_resp_headers(struct h2s *h2s, struct htx *htx)
        sl = htx_get_blk_ptr(htx, blk);
        h2s->status = sl->info.res.status;
        if (h2s->status < 100 || h2s->status > 999) {
-               TRACE_PROTO("will not encode an invalid status code", H2_EV_TX_FRAME|H2_EV_TX_HDR|H2_EV_H2S_ERR, h2c->conn, h2s);
+               TRACE_ERROR("will not encode an invalid status code", H2_EV_TX_FRAME|H2_EV_TX_HDR|H2_EV_H2S_ERR, h2c->conn, h2s);
                goto fail;
        }
 
@@ -4853,7 +4868,7 @@ static size_t h2s_frt_make_resp_headers(struct h2s *h2s, struct htx *htx)
                        break;
 
                if (unlikely(hdr >= sizeof(list)/sizeof(list[0]) - 1)) {
-                       TRACE_PROTO("too many headers", H2_EV_TX_FRAME|H2_EV_TX_HDR|H2_EV_H2S_ERR, h2c->conn, h2s);
+                       TRACE_ERROR("too many headers", H2_EV_TX_FRAME|H2_EV_TX_HDR|H2_EV_H2S_ERR, h2c->conn, h2s);
                        goto fail;
                }
 
@@ -5070,7 +5085,7 @@ static size_t h2s_bck_make_req_headers(struct h2s *h2s, struct htx *htx)
        meth = htx_sl_req_meth(sl);
        uri  = htx_sl_req_uri(sl);
        if (unlikely(uri.len == 0)) {
-               TRACE_PROTO("no URI in HTX request", H2_EV_TX_FRAME|H2_EV_TX_HDR|H2_EV_H2S_ERR, h2c->conn, h2s);
+               TRACE_ERROR("no URI in HTX request", H2_EV_TX_FRAME|H2_EV_TX_HDR|H2_EV_H2S_ERR, h2c->conn, h2s);
                goto fail;
        }
 
@@ -5089,7 +5104,7 @@ static size_t h2s_bck_make_req_headers(struct h2s *h2s, struct htx *htx)
                        break;
 
                if (unlikely(hdr >= sizeof(list)/sizeof(list[0]) - 1)) {
-                       TRACE_PROTO("too many headers", H2_EV_TX_FRAME|H2_EV_TX_HDR|H2_EV_H2S_ERR, h2c->conn, h2s);
+                       TRACE_ERROR("too many headers", H2_EV_TX_FRAME|H2_EV_TX_HDR|H2_EV_H2S_ERR, h2c->conn, h2s);
                        goto fail;
                }
 
@@ -5707,7 +5722,7 @@ static size_t h2s_make_trailers(struct h2s *h2s, struct htx *htx)
                        break;
 
                if (unlikely(hdr >= sizeof(list)/sizeof(list[0]) - 1)) {
-                       TRACE_PROTO("too many headers", H2_EV_TX_FRAME|H2_EV_TX_HDR|H2_EV_H2S_ERR, h2c->conn, h2s);
+                       TRACE_ERROR("too many trailers", H2_EV_TX_FRAME|H2_EV_TX_HDR|H2_EV_H2S_ERR, h2c->conn, h2s);
                        goto fail;
                }