Mercurial > hg > nginx
changeset 8998:308ac307b3e6 quic
QUIC: improved debug logging.
- wording in log->action is adjusted to match function names.
- connection close steps are made obvious and start with "quic close" prefix:
*1 quic close initiated rc:-4
*1 quic close silent drain:0 timedout:1
*1 quic close resumed rc:-1
*1 quic close resumed rc:-1
*1 quic close resumed rc:-4
*1 quic close completed
this makes it easy to understand if particular "close" record is an initial
cause or lasting process, or the final one.
- cases of close without quic connection now logged as "packet rejected":
*14 quic run
*14 quic packet rx long flags:ec version:1
*14 quic packet rx hs len:61
*14 quic packet rx dcid len:20 00000000000002c32f60e4aa2b90a64a39dc4228
*14 quic packet rx scid len:8 81190308612cd019
*14 quic expected initial, got handshake
*14 quic packet done rc:-1 level:hs decr:0 pn:0 perr:0
*14 quic packet rejected rc:-1, cleanup connection
*14 reusable connection: 0
this makes it easy to spot early packet rejection and avoid confuse with
quic connection closing (which in fact was not even created).
- packet processing summary now uses same prefix "quic packet done rc:"
- added debug to places where packet was rejected without any reason logged
author | Vladimir Homutov <vl@nginx.com> |
---|---|
date | Tue, 01 Feb 2022 15:43:56 +0300 |
parents | fab36e4abf83 |
children | 92729be0377b |
files | src/event/quic/ngx_event_quic.c |
diffstat | 1 files changed, 22 insertions(+), 21 deletions(-) [+] |
line wrap: on
line diff
--- a/src/event/quic/ngx_event_quic.c Fri Jan 28 14:57:33 2022 +0300 +++ b/src/event/quic/ngx_event_quic.c Tue Feb 01 15:43:56 2022 +0300 @@ -459,20 +459,18 @@ ngx_quic_send_ctx_t *ctx; ngx_quic_connection_t *qc; - ngx_log_debug1(NGX_LOG_DEBUG_EVENT, c->log, 0, - "quic ngx_quic_close_connection rc:%i", rc); - qc = ngx_quic_get_connection(c); if (qc == NULL) { - if (rc == NGX_ERROR) { - ngx_log_debug0(NGX_LOG_DEBUG_EVENT, c->log, 0, - "quic close connection early error"); - } - + ngx_log_debug1(NGX_LOG_DEBUG_EVENT, c->log, 0, + "quic packet rejected rc:%i, cleanup connection", rc); goto quic_done; } + ngx_log_debug2(NGX_LOG_DEBUG_EVENT, c->log, 0, + "quic close %s rc:%i", + qc->closing ? "resumed": "initiated", rc); + if (!qc->closing) { /* drop packets from retransmit queues, no ack is expected */ @@ -490,10 +488,11 @@ * closed and its state is discarded when it remains idle */ - ngx_log_debug1(NGX_LOG_DEBUG_EVENT, c->log, 0, - "quic closing %s connection", - qc->draining ? "drained" : "idle"); + /* this case also handles some errors from ngx_quic_run() */ + ngx_log_debug2(NGX_LOG_DEBUG_EVENT, c->log, 0, + "quic close silent drain:%d timedout:%d", + qc->draining, c->read->timedout); } else { /* @@ -508,7 +507,7 @@ if (rc == NGX_OK) { ngx_log_debug1(NGX_LOG_DEBUG_EVENT, c->log, 0, - "quic immediate close drain:%d", + "quic close immediate drain:%d", qc->draining); qc->close.log = c->log; @@ -528,7 +527,7 @@ } ngx_log_debug3(NGX_LOG_DEBUG_EVENT, c->log, 0, - "quic immediate close due to %s error: %ui %s", + "quic close immediate due to %serror: %ui %s", qc->error_app ? "app " : "", qc->error, qc->error_reason ? qc->error_reason : ""); } @@ -576,8 +575,7 @@ ngx_quic_close_sockets(c); - ngx_log_debug0(NGX_LOG_DEBUG_EVENT, c->log, 0, - "quic part of connection is terminated"); + ngx_log_debug0(NGX_LOG_DEBUG_EVENT, c->log, 0, "quic close completed"); /* may be tested from SSL callback during SSL shutdown */ c->udp = NULL; @@ -685,12 +683,13 @@ #if (NGX_DEBUG) if (pkt.parsed) { ngx_log_debug5(NGX_LOG_DEBUG_EVENT, c->log, 0, - "quic packet %s done decr:%d pn:%L perr:%ui rc:%i", - ngx_quic_level_name(pkt.level), pkt.decrypted, - pkt.pn, pkt.error, rc); + "quic packet done rc:%i level:%s" + " decr:%d pn:%L perr:%ui", + rc, ngx_quic_level_name(pkt.level), + pkt.decrypted, pkt.pn, pkt.error); } else { ngx_log_debug1(NGX_LOG_DEBUG_EVENT, c->log, 0, - "quic packet done parse failed rc:%i", rc); + "quic packet done rc:%i parse failed", rc); } #endif @@ -770,7 +769,7 @@ pkt->parsed = 1; - c->log->action = "processing quic packet"; + c->log->action = "handling quic packet"; ngx_log_debug2(NGX_LOG_DEBUG_EVENT, c->log, 0, "quic packet rx dcid len:%uz %xV", @@ -855,10 +854,12 @@ } if (pkt->level != ssl_encryption_initial) { + ngx_log_debug0(NGX_LOG_DEBUG_EVENT, c->log, 0, + "quic expected initial, got handshake"); return NGX_ERROR; } - c->log->action = "processing initial packet"; + c->log->action = "handling initial packet"; if (pkt->dcid.len < NGX_QUIC_CID_LEN_MIN) { /* RFC 9000, 7.2. Negotiating Connection IDs */