Skip to content

Commit

Permalink
QUIC: improved debug logging.
Browse files Browse the repository at this point in the history
 - 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
  • Loading branch information
vlhomutov committed Feb 1, 2022
1 parent 26bc237 commit b9e398d
Showing 1 changed file with 22 additions and 21 deletions.
43 changes: 22 additions & 21 deletions src/event/quic/ngx_event_quic.c
Original file line number Diff line number Diff line change
Expand Up @@ -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 */
Expand All @@ -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 {

/*
Expand All @@ -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;
Expand All @@ -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 : "");
}
Expand Down Expand Up @@ -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;
Expand Down Expand Up @@ -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

Expand Down Expand Up @@ -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",
Expand Down Expand Up @@ -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 */
Expand Down

0 comments on commit b9e398d

Please sign in to comment.