QUIC: improved huffman decode debug tracing.
Roman Arutyunyan
arut at nginx.com
Wed Nov 22 12:41:27 UTC 2023
Hi,
On Tue, Nov 14, 2023 at 03:57:24PM +0400, Sergey Kandaurov wrote:
> 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;
> }
Both patches look good to me.
--
Roman Arutyunyan
More information about the nginx-devel
mailing list