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

diff --git a/src/event/quic/ngx_event_quic.c b/src/event/quic/ngx_event_quic.c
index 17143f3f782a027cdc2131e420e0447a4f4e9af8..2a51c79a76410ce3014d46f2d9c74ea51f387354 100644 (file)
--- a/src/event/quic/ngx_event_quic.c
+++ b/src/event/quic/ngx_event_quic.c
@@ -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 */