Fijxu
/
nginx-quic
1
0
Fork 0
Code Issues Pull Requests Packages Projects Releases Wiki Activity

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
This commit is contained in:
Vladimir Homutov 2022-02-01 15:43:56 +03:00
parent bda9e27f29
commit e16352881a
1 changed files with 22 additions and 21 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

43
src/event/quic/ngx_event_quic.c
View File

@ -459,20 +459,18 @@ ngx_quic_close_connection(ngx_connection_t *c, ngx_int_t rc)
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 @@ ngx_quic_close_connection(ngx_connection_t *c, ngx_int_t rc)
* 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 @@ ngx_quic_close_connection(ngx_connection_t *c, ngx_int_t rc)
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_quic_close_connection(ngx_connection_t *c, ngx_int_t rc)
}
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_connection(ngx_connection_t *c, ngx_int_t rc)
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 @@ ngx_quic_handle_datagram(ngx_connection_t *c, ngx_buf_t *b,
#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 @@ ngx_quic_handle_packet(ngx_connection_t *c, ngx_quic_conf_t *conf,
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 @@ ngx_quic_handle_packet(ngx_connection_t *c, ngx_quic_conf_t *conf,
}
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 */