QUIC: improved huffman decode debug tracing.
XingY Wang
winshining at 163.com
Fri Nov 17 18:24:44 UTC 2023
Hi, Sergey Kandaurov, thanks for your review.
>Date: Tue, 14 Nov 2023 15:57:24 +0400
>From: Sergey Kandaurov <pluknet at nginx.com>
>To: nginx-devel at nginx.org
>Subject: Re: QUIC: improved huffman decode debug tracing.
>Message-ID: <20231114115724.ub2d6qp5cbmsfj7x at Y9MQ9X2QVV>
>Content-Type: text/plain; charset=us-ascii
>
>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.
Yes. I didn't find any error in log when I debugged a client which showed
the request didn't work until I turned on the debug level.
>
>[ 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.
OK.
>
>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;
> }
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://mailman.nginx.org/pipermail/nginx-devel/attachments/20231118/8a36994b/attachment-0001.htm>
More information about the nginx-devel
mailing list