QUIC: improved huffman decode debug tracing.
Sergey Kandaurov
pluknet at nginx.com
Tue Nov 14 11:57:24 UTC 2023
On Tue, Oct 31, 2023 at 09:06:03PM +0800, winshining wrote:
> Previously, only HTTP2 used huffman encoding (gRPC is util now
> HTTP2 based), as HTTP3 becomes available, both of them uses huffman
> encoding. But existed debug log in huffman decode function is hard
> coded using "http2" prefixes, if a client transports an incorrect
> huffman encoded field value in an HTTP3 request, it will give an
> erroneous log. With the patch, it will properly log a bad field value.
While indeed it makes sense to adjust hardcoded "http2" prefixes,
I don't think this is a reason to break ngx_http_huff_decode() API.
(It was once broken when moving Huffman coding out of HTTP/2,
but that was quite justified).
> Alternatively, removing "http2" prefixes only is ok, but it can not
> differentiate whether it is caused by an HTTP2 or an HTTP3 request.
Affected messages are logged at the debug level anyway, so this
should not be a problem, it can be easily seen from the context -
by looking at the adjacent messages belonging to the connection.
[ Note that your attachment is sent as application/octet-stream,
I had to adjust my mailcap in order to include it in the reply.]
> # HG changeset patch
> # User XingY Wang <winshining at 163.com>
> # Date 1698714765 -28800
> # Tue Oct 31 09:12:45 2023 +0800
> # Node ID 760857905505f91c9627f3bfeb5b6e496f4992a8
> # Parent 7ec761f0365f418511e30b82e9adf80bc56681df
> QUIC: improved huffman decode debug tracing.
>
> Previously, only HTTP2 used huffman encoding (gRPC is util now
> HTTP2 based), as HTTP3 becomes available, both of them uses huffman
> encoding. But existed debug log in huffman decode function is hard
> coded using "http2" prefixes, if a client transports an incorrect
> huffman encoded field value in an HTTP3 request, it will give an
> erroneous log. With the patch, it will properly log a bad field value.
> Alternatively, removing "http2" prefixes only is ok, but it can not
> differentiate whether it is caused by an HTTP2 or an HTTP3 request.
>
> diff -r 7ec761f0365f -r 760857905505 src/http/modules/ngx_http_grpc_module.c
> --- a/src/http/modules/ngx_http_grpc_module.c Thu Oct 26 23:35:09 2023 +0300
> +++ b/src/http/modules/ngx_http_grpc_module.c Tue Oct 31 09:12:45 2023 +0800
> @@ -3189,6 +3189,7 @@
> if (ngx_http_huff_decode(&ctx->field_state, p, size,
> &ctx->field_end,
> ctx->field_rest == 0,
> + NGX_HTTP_VERSION_20,
> r->connection->log)
> != NGX_OK)
> {
> @@ -3298,6 +3299,7 @@
> if (ngx_http_huff_decode(&ctx->field_state, p, size,
> &ctx->field_end,
> ctx->field_rest == 0,
> + NGX_HTTP_VERSION_20,
> r->connection->log)
> != NGX_OK)
> {
> diff -r 7ec761f0365f -r 760857905505 src/http/ngx_http.h
> --- a/src/http/ngx_http.h Thu Oct 26 23:35:09 2023 +0300
> +++ b/src/http/ngx_http.h Tue Oct 31 09:12:45 2023 +0800
> @@ -179,7 +179,7 @@
>
> #if (NGX_HTTP_V2 || NGX_HTTP_V3)
> ngx_int_t ngx_http_huff_decode(u_char *state, u_char *src, size_t len,
> - u_char **dst, ngx_uint_t last, ngx_log_t *log);
> + u_char **dst, ngx_uint_t last, ngx_uint_t http_version, ngx_log_t *log);
> size_t ngx_http_huff_encode(u_char *src, size_t len, u_char *dst,
> ngx_uint_t lower);
> #endif
> diff -r 7ec761f0365f -r 760857905505 src/http/ngx_http_huff_decode.c
> --- a/src/http/ngx_http_huff_decode.c Thu Oct 26 23:35:09 2023 +0300
> +++ b/src/http/ngx_http_huff_decode.c Tue Oct 31 09:12:45 2023 +0800
> @@ -2641,9 +2641,22 @@
>
> ngx_int_t
> ngx_http_huff_decode(u_char *state, u_char *src, size_t len, u_char **dst,
> - ngx_uint_t last, ngx_log_t *log)
> + ngx_uint_t last, ngx_uint_t http_version, ngx_log_t *log)
> {
> u_char *end, ch, ending;
> +#if (NGX_DEBUG)
> + char *from = NULL;
> +
> + switch (http_version) {
> +
> + case NGX_HTTP_VERSION_30:
> + from = "http3";
> + break;
> +
> + default:
> + from = "http2";
> + }
> +#endif
>
> ch = 0;
> ending = 1;
> @@ -2656,9 +2669,9 @@
> if (ngx_http_huff_decode_bits(state, &ending, ch >> 4, dst)
> != NGX_OK)
> {
> - ngx_log_debug2(NGX_LOG_DEBUG_HTTP, log, 0,
> - "http2 huffman decoding error at state %d: "
> - "bad code 0x%Xd", *state, ch >> 4);
> + ngx_log_debug3(NGX_LOG_DEBUG_HTTP, log, 0,
> + "%s huffman decoding error at state %d: "
> + "bad code 0x%Xd", from, *state, ch >> 4);
>
> return NGX_ERROR;
> }
> @@ -2666,9 +2679,9 @@
> if (ngx_http_huff_decode_bits(state, &ending, ch & 0xf, dst)
> != NGX_OK)
> {
> - ngx_log_debug2(NGX_LOG_DEBUG_HTTP, log, 0,
> - "http2 huffman decoding error at state %d: "
> - "bad code 0x%Xd", *state, ch & 0xf);
> + ngx_log_debug3(NGX_LOG_DEBUG_HTTP, log, 0,
> + "%s huffman decoding error at state %d: "
> + "bad code 0x%Xd", from, *state, ch & 0xf);
>
> return NGX_ERROR;
> }
> @@ -2676,9 +2689,9 @@
>
> if (last) {
> if (!ending) {
> - ngx_log_debug1(NGX_LOG_DEBUG_HTTP, log, 0,
> - "http2 huffman decoding error: "
> - "incomplete code 0x%Xd", ch);
> + ngx_log_debug2(NGX_LOG_DEBUG_HTTP, log, 0,
> + "%s huffman decoding error: "
> + "incomplete code 0x%Xd", from, ch);
>
> return NGX_ERROR;
> }
> diff -r 7ec761f0365f -r 760857905505 src/http/v2/ngx_http_v2.c
> --- a/src/http/v2/ngx_http_v2.c Thu Oct 26 23:35:09 2023 +0300
> +++ b/src/http/v2/ngx_http_v2.c Tue Oct 31 09:12:45 2023 +0800
> @@ -1579,6 +1579,7 @@
> if (ngx_http_huff_decode(&h2c->state.field_state, pos, size,
> &h2c->state.field_end,
> h2c->state.field_rest == 0,
> + NGX_HTTP_VERSION_20,
> h2c->connection->log)
> != NGX_OK)
> {
> diff -r 7ec761f0365f -r 760857905505 src/http/v3/ngx_http_v3_parse.c
> --- a/src/http/v3/ngx_http_v3_parse.c Thu Oct 26 23:35:09 2023 +0300
> +++ b/src/http/v3/ngx_http_v3_parse.c Tue Oct 31 09:12:45 2023 +0800
> @@ -647,7 +647,8 @@
>
> if (st->huffman) {
> if (ngx_http_huff_decode(&st->huffstate, &ch, 1, &st->last,
> - st->length == 1, c->log)
> + st->length == 1, NGX_HTTP_VERSION_30,
> + c->log)
> != NGX_OK)
> {
> return NGX_ERROR;
This introduces complexity just for debugging purpose.
Removing any mention of HTTP protocol version should be enough.
Huffman coding routines do not depend on HTTP protocol versions,
both HPACK and QPACK refer to the same part of specification,
that is Appendix B of RFC 7541.
Also, while looking at ngx_http_huff_decode() use-cases,
I noticed that HTTP/3 doesn't log Huffman decoding errors,
which it probably should because this is a user-induced
error, and for consistency with other nginx core modules.
# HG changeset patch
# User Sergey Kandaurov <pluknet at nginx.com>
# Date 1699959003 -14400
# Tue Nov 14 14:50:03 2023 +0400
# Node ID c458cd00bb0bca8804ed831474533a813bcfd134
# Parent 7ec761f0365f418511e30b82e9adf80bc56681df
Adjusted Huffman coding debug logging, missed in 7977:336084ff943b.
Spotted by XingY Wang.
diff --git a/src/http/ngx_http_huff_decode.c b/src/http/ngx_http_huff_decode.c
--- a/src/http/ngx_http_huff_decode.c
+++ b/src/http/ngx_http_huff_decode.c
@@ -2657,7 +2657,7 @@ ngx_http_huff_decode(u_char *state, u_ch
!= NGX_OK)
{
ngx_log_debug2(NGX_LOG_DEBUG_HTTP, log, 0,
- "http2 huffman decoding error at state %d: "
+ "http huffman decoding error at state %d: "
"bad code 0x%Xd", *state, ch >> 4);
return NGX_ERROR;
@@ -2667,7 +2667,7 @@ ngx_http_huff_decode(u_char *state, u_ch
!= NGX_OK)
{
ngx_log_debug2(NGX_LOG_DEBUG_HTTP, log, 0,
- "http2 huffman decoding error at state %d: "
+ "http huffman decoding error at state %d: "
"bad code 0x%Xd", *state, ch & 0xf);
return NGX_ERROR;
@@ -2677,7 +2677,7 @@ ngx_http_huff_decode(u_char *state, u_ch
if (last) {
if (!ending) {
ngx_log_debug1(NGX_LOG_DEBUG_HTTP, log, 0,
- "http2 huffman decoding error: "
+ "http huffman decoding error: "
"incomplete code 0x%Xd", ch);
return NGX_ERROR;
# HG changeset patch
# User Sergey Kandaurov <pluknet at nginx.com>
# Date 1699961162 -14400
# Tue Nov 14 15:26:02 2023 +0400
# Node ID f366007dd23a6ce8e8427c1b3042781b618a2ade
# Parent c458cd00bb0bca8804ed831474533a813bcfd134
HTTP/3: added Huffman decoding error logging.
diff --git a/src/http/v3/ngx_http_v3_parse.c b/src/http/v3/ngx_http_v3_parse.c
--- a/src/http/v3/ngx_http_v3_parse.c
+++ b/src/http/v3/ngx_http_v3_parse.c
@@ -650,6 +650,8 @@ ngx_http_v3_parse_literal(ngx_connection
st->length == 1, c->log)
!= NGX_OK)
{
+ ngx_log_error(NGX_LOG_INFO, c->log, 0,
+ "client sent invalid encoded field line");
return NGX_ERROR;
}
More information about the nginx-devel
mailing list