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 b81d799..ce39f75 100644
--- a/src/mux_h2.c
+++ b/src/mux_h2.c
@@ -1666,6 +1666,7 @@
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 @@
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 @@
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 @@
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 @@
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 @@
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 @@
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 @@
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 @@
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 @@
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 @@
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 @@
/* 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 @@
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 @@
* 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 @@
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 @@
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 @@
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 @@
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 @@
* 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 @@
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 @@
/* 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 @@
* 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 @@
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 @@
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 @@
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 @@
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 @@
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;
}