changeset 8360:f175006124d0 quic

Cleaned up hexdumps in debug output. - the ngx_quic_hexdump0() macro is renamed to ngx_quic_hexdump(); the original ngx_quic_hexdump() macro with variable argument is removed, extra information is logged normally, with ngx_log_debug() - all labels in hex dumps are prefixed with "quic" - the hexdump format is simplified, length is moved forward to avoid situations when the dump is truncated, and length is not shown - ngx_quic_flush_flight() function contents is debug-only, placed under NGX_DEBUG macro to avoid "unused variable" warnings from compiler - frame names in labels are capitalized, similar to other places
author Vladimir Homutov <vl@nginx.com>
date Fri, 24 Apr 2020 11:33:00 +0300
parents 2f900ae486bc
children 336d527ca031
files src/event/ngx_event_quic.c src/event/ngx_event_quic.h src/event/ngx_event_quic_protection.c src/event/ngx_event_quic_transport.c
diffstat 4 files changed, 63 insertions(+), 54 deletions(-) [+]
line wrap: on
line diff
--- a/src/event/ngx_event_quic.c
+++ b/src/event/ngx_event_quic.c
@@ -252,8 +252,9 @@ ngx_quic_set_read_secret(ngx_ssl_conn_t 
     c = ngx_ssl_get_connection((ngx_ssl_conn_t *) ssl_conn);
 
 #ifdef NGX_QUIC_DEBUG_CRYPTO
-    ngx_quic_hexdump(c->log, "level:%d read secret",
-                     rsecret, secret_len, level);
+    ngx_log_debug1(NGX_LOG_DEBUG_EVENT, c->log, 0,
+                   "quic ngx_quic_set_read_secret() level:%d", level);
+    ngx_quic_hexdump(c->log, "quic read secret", rsecret, secret_len);
 #endif
 
     keys = &c->quic->keys[level];
@@ -279,8 +280,9 @@ ngx_quic_set_write_secret(ngx_ssl_conn_t
     c = ngx_ssl_get_connection((ngx_ssl_conn_t *) ssl_conn);
 
 #ifdef NGX_QUIC_DEBUG_CRYPTO
-    ngx_quic_hexdump(c->log, "level:%d write secret",
-                     wsecret, secret_len, level);
+    ngx_log_debug1(NGX_LOG_DEBUG_EVENT, c->log, 0,
+                   "quic ngx_quic_set_write_secret() level:%d", level);
+    ngx_quic_hexdump(c->log, "quic write secret", wsecret, secret_len);
 #endif
 
     keys = &c->quic->keys[level];
@@ -304,7 +306,9 @@ ngx_quic_set_encryption_secrets(ngx_ssl_
     c = ngx_ssl_get_connection((ngx_ssl_conn_t *) ssl_conn);
 
 #ifdef NGX_QUIC_DEBUG_CRYPTO
-    ngx_quic_hexdump(c->log, "level:%d read", rsecret, secret_len, level);
+    ngx_log_debug1(NGX_LOG_DEBUG_EVENT, c->log, 0,
+                   "quic ngx_quic_set_encryption_secrets() level:%d", level);
+    ngx_quic_hexdump(c->log, "quic read", rsecret, secret_len);
 #endif
 
     keys = &c->quic->keys[level];
@@ -322,7 +326,7 @@ ngx_quic_set_encryption_secrets(ngx_ssl_
     }
 
 #ifdef NGX_QUIC_DEBUG_CRYPTO
-    ngx_quic_hexdump(c->log, "level:%d write", wsecret, secret_len, level);
+    ngx_quic_hexdump(c->log, "quic write", wsecret, secret_len);
 #endif
 
     return ngx_quic_set_encryption_secret(c->pool, ssl_conn, level,
@@ -434,13 +438,14 @@ ngx_quic_add_handshake_data(ngx_ssl_conn
 static int
 ngx_quic_flush_flight(ngx_ssl_conn_t *ssl_conn)
 {
+#if (NGX_DEBUG)
     ngx_connection_t  *c;
 
     c = ngx_ssl_get_connection((ngx_ssl_conn_t *) ssl_conn);
 
     ngx_log_debug0(NGX_LOG_DEBUG_EVENT, c->log, 0,
                    "quic ngx_quic_flush_flight()");
-
+#endif
     return 1;
 }
 
@@ -676,7 +681,7 @@ ngx_quic_init_connection(ngx_connection_
     }
 
 #ifdef NGX_QUIC_DEBUG_PACKETS
-    ngx_quic_hexdump0(c->log, "quic transport parameters", p, len);
+    ngx_quic_hexdump(c->log, "quic transport parameters", p, len);
 #endif
 
     if (SSL_set_quic_transport_params(ssl_conn, p, len) == 0) {
@@ -2456,7 +2461,7 @@ ngx_quic_send_frames(ngx_connection_t *c
     }
 
 #ifdef NGX_QUIC_DEBUG_PACKETS
-    ngx_quic_hexdump0(c->log, "packet to send", res.data, res.len);
+    ngx_quic_hexdump(c->log, "quic packet to send", res.data, res.len);
 #endif
 
     len = c->send(c, res.data, res.len);
--- a/src/event/ngx_event_quic.h
+++ b/src/event/ngx_event_quic.h
@@ -87,31 +87,25 @@ ngx_connection_t *ngx_quic_create_uni_st
 //#define NGX_QUIC_DEBUG_FRAMES_ALLOC  /* log frames alloc/reuse/free */
 //#define NGX_QUIC_DEBUG_CRYPTO
 
-
 #if (NGX_DEBUG)
 
-#define ngx_quic_hexdump(log, fmt, data, len, ...)                            \
+#define ngx_quic_hexdump(log, label, data, len)                               \
 do {                                                                          \
     ngx_int_t  m;                                                             \
     u_char     buf[2048];                                                     \
                                                                               \
     if (log->log_level & NGX_LOG_DEBUG_EVENT) {                               \
         m = ngx_hex_dump(buf, (u_char *) data, ngx_min(len, 1024)) - buf;     \
-        ngx_log_debug(NGX_LOG_DEBUG_EVENT, log, 0,                            \
-                   "%s: " fmt " %*s%s, len: %uz",                             \
-                   __FUNCTION__,  __VA_ARGS__, m, buf,                        \
-                   len < 2048 ? "" : "...", len);                             \
+        ngx_log_debug4(NGX_LOG_DEBUG_EVENT, log, 0,                           \
+                      label " len:%uz data:%*s%s",                            \
+                      len, m, buf, len < 2048 ? "" : "...");                  \
     }                                                                         \
 } while (0)
 
 #else
 
-#define ngx_quic_hexdump(log, fmt, data, len, ...)
+#define ngx_quic_hexdump(log, fmt, data, len)
 
 #endif
 
-#define ngx_quic_hexdump0(log, fmt, data, len)                                \
-    ngx_quic_hexdump(log, fmt "%s", data, len, "")                            \
-
-
 #endif /* _NGX_EVENT_QUIC_H_INCLUDED_ */
--- a/src/event/ngx_event_quic_protection.c
+++ b/src/event/ngx_event_quic_protection.c
@@ -157,8 +157,10 @@ ngx_quic_set_initial_secret(ngx_pool_t *
     };
 
 #ifdef NGX_QUIC_DEBUG_CRYPTO
-    ngx_quic_hexdump0(pool->log, "salt", salt, sizeof(salt));
-    ngx_quic_hexdump0(pool->log, "initial secret", is, is_len);
+    ngx_log_debug0(NGX_LOG_DEBUG_EVENT, pool->log, 0,
+                  "quic ngx_quic_set_initial_secret");
+    ngx_quic_hexdump(pool->log, "quic salt", salt, sizeof(salt));
+    ngx_quic_hexdump(pool->log, "quic initial secret", is, is_len);
 #endif
 
     /* draft-ietf-quic-tls-23#section-5.2 */
@@ -266,8 +268,10 @@ ngx_quic_hkdf_expand(ngx_pool_t *pool, c
     }
 
 #ifdef NGX_QUIC_DEBUG_CRYPTO
-    ngx_quic_hexdump(pool->log, "%V info", info, info_len, label);
-    ngx_quic_hexdump(pool->log, "%V key", out->data, out->len, label);
+    ngx_log_debug1(NGX_LOG_DEBUG_EVENT, pool->log, 0,
+                   "quic ngx_quic_hkdf_expand %V keys", label);
+    ngx_quic_hexdump(pool->log, "quic info", info, info_len);
+    ngx_quic_hexdump(pool->log, "quic key", out->data, out->len);
 #endif
 
     return NGX_OK;
@@ -678,7 +682,7 @@ ngx_quic_key_update(ngx_connection_t *c,
     ngx_uint_t          i;
     ngx_quic_ciphers_t  ciphers;
 
-    ngx_log_debug(NGX_LOG_DEBUG_EVENT, c->log, 0, "quic key update");
+    ngx_log_debug0(NGX_LOG_DEBUG_EVENT, c->log, 0, "quic key update");
 
     if (ngx_quic_ciphers(c->ssl->connection, &ciphers,
                          ssl_encryption_application)
@@ -766,7 +770,9 @@ ngx_quic_create_long_packet(ngx_quic_hea
     out.data = res->data + ad.len;
 
 #ifdef NGX_QUIC_DEBUG_CRYPTO
-    ngx_quic_hexdump0(pkt->log, "ad", ad.data, ad.len);
+    ngx_log_debug0(NGX_LOG_DEBUG_EVENT, pkt->log, 0,
+                   "quic ngx_quic_create_long_packet");
+    ngx_quic_hexdump(pkt->log, "quic ad", ad.data, ad.len);
 #endif
 
     if (ngx_quic_ciphers(ssl_conn, &ciphers, pkt->level) == NGX_ERROR) {
@@ -777,8 +783,8 @@ ngx_quic_create_long_packet(ngx_quic_hea
     ngx_quic_compute_nonce(nonce, sizeof(nonce), pkt->number);
 
 #ifdef NGX_QUIC_DEBUG_CRYPTO
-    ngx_quic_hexdump0(pkt->log, "server_iv", pkt->secret->iv.data, 12);
-    ngx_quic_hexdump0(pkt->log, "nonce", nonce, 12);
+    ngx_quic_hexdump(pkt->log, "quic server_iv", pkt->secret->iv.data, 12);
+    ngx_quic_hexdump(pkt->log, "quic nonce", nonce, 12);
 #endif
 
     if (ngx_quic_tls_seal(ciphers.c, pkt->secret, &out,
@@ -796,8 +802,8 @@ ngx_quic_create_long_packet(ngx_quic_hea
     }
 
 #ifdef NGX_QUIC_DEBUG_CRYPTO
-    ngx_quic_hexdump0(pkt->log, "sample", sample, 16);
-    ngx_quic_hexdump0(pkt->log, "mask", mask, 5);
+    ngx_quic_hexdump(pkt->log, "quic sample", sample, 16);
+    ngx_quic_hexdump(pkt->log, "quic mask", mask, 5);
 #endif
 
     /* quic-tls: 5.4.1.  Header Protection Application */
@@ -831,7 +837,9 @@ ngx_quic_create_short_packet(ngx_quic_he
     out.data = res->data + ad.len;
 
 #ifdef NGX_QUIC_DEBUG_CRYPTO
-    ngx_quic_hexdump0(pkt->log, "ad", ad.data, ad.len);
+    ngx_log_debug0(NGX_LOG_DEBUG_EVENT, pkt->log, 0,
+                   "quic ngx_quic_create_short_packet");
+    ngx_quic_hexdump(pkt->log, "quic ad", ad.data, ad.len);
 #endif
 
     if (ngx_quic_ciphers(ssl_conn, &ciphers, pkt->level) == NGX_ERROR) {
@@ -847,8 +855,8 @@ ngx_quic_create_short_packet(ngx_quic_he
     ngx_quic_compute_nonce(nonce, sizeof(nonce), pkt->number);
 
 #ifdef NGX_QUIC_DEBUG_CRYPTO
-    ngx_quic_hexdump0(pkt->log, "server_iv", pkt->secret->iv.data, 12);
-    ngx_quic_hexdump0(pkt->log, "nonce", nonce, 12);
+    ngx_quic_hexdump(pkt->log, "quic server_iv", pkt->secret->iv.data, 12);
+    ngx_quic_hexdump(pkt->log, "quic nonce", nonce, 12);
 #endif
 
     if (ngx_quic_tls_seal(ciphers.c, pkt->secret, &out,
@@ -866,8 +874,8 @@ ngx_quic_create_short_packet(ngx_quic_he
     }
 
 #ifdef NGX_QUIC_DEBUG_CRYPTO
-    ngx_quic_hexdump0(pkt->log, "sample", sample, 16);
-    ngx_quic_hexdump0(pkt->log, "mask", mask, 5);
+    ngx_quic_hexdump(pkt->log, "quic sample", sample, 16);
+    ngx_quic_hexdump(pkt->log, "quic mask", mask, 5);
 #endif
 
     /* quic-tls: 5.4.1.  Header Protection Application */
@@ -977,7 +985,9 @@ ngx_quic_decrypt(ngx_quic_header_t *pkt,
     sample = p + 4;
 
 #ifdef NGX_QUIC_DEBUG_CRYPTO
-    ngx_quic_hexdump0(pkt->log, "sample", sample, 16);
+    ngx_log_debug0(NGX_LOG_DEBUG_EVENT, pkt->log, 0,
+                   "quic ngx_quic_decrypt()");
+    ngx_quic_hexdump(pkt->log, "quic sample", sample, 16);
 #endif
 
     /* header protection */
@@ -1007,7 +1017,7 @@ ngx_quic_decrypt(ngx_quic_header_t *pkt,
     pkt->pn = pn;
 
 #ifdef NGX_QUIC_DEBUG_CRYPTO
-    ngx_quic_hexdump0(pkt->log, "mask", mask, 5);
+    ngx_quic_hexdump(pkt->log, "quic mask", mask, 5);
 #endif
 
     ngx_log_debug1(NGX_LOG_DEBUG_EVENT, pkt->log, 0,
@@ -1040,8 +1050,8 @@ ngx_quic_decrypt(ngx_quic_header_t *pkt,
     ngx_quic_compute_nonce(nonce, sizeof(nonce), pn);
 
 #ifdef NGX_QUIC_DEBUG_CRYPTO
-    ngx_quic_hexdump0(pkt->log, "nonce", nonce, 12);
-    ngx_quic_hexdump0(pkt->log, "ad", ad.data, ad.len);
+    ngx_quic_hexdump(pkt->log, "quic nonce", nonce, 12);
+    ngx_quic_hexdump(pkt->log, "quic ad", ad.data, ad.len);
 #endif
 
     pkt->payload.len = in.len - EVP_GCM_TLS_TAG_LEN;
@@ -1056,8 +1066,8 @@ ngx_quic_decrypt(ngx_quic_header_t *pkt,
                            nonce, &in, &ad, pkt->log);
 
 #if defined(NGX_QUIC_DEBUG_CRYPTO) && defined(NGX_QUIC_DEBUG_PACKETS)
-    ngx_quic_hexdump0(pkt->log, "packet payload",
-                      pkt->payload.data, pkt->payload.len);
+    ngx_quic_hexdump(pkt->log, "quic packet payload",
+                     pkt->payload.data, pkt->payload.len);
 #endif
 
     return rc;
--- a/src/event/ngx_event_quic_transport.c
+++ b/src/event/ngx_event_quic_transport.c
@@ -235,7 +235,7 @@ ngx_quic_parse_long_header(ngx_quic_head
     end = pkt->data + pkt->len;
 
 #ifdef NGX_QUIC_DEBUG_PACKETS
-    ngx_quic_hexdump0(pkt->log, "long input", pkt->data, pkt->len);
+    ngx_quic_hexdump(pkt->log, "quic long packet in", pkt->data, pkt->len);
 #endif
 
     p = ngx_quic_read_uint8(p, end, &pkt->flags);
@@ -392,7 +392,7 @@ ngx_quic_parse_short_header(ngx_quic_hea
     end = pkt->data + pkt->len;
 
 #ifdef NGX_QUIC_DEBUG_PACKETS
-    ngx_quic_hexdump0(pkt->log, "short input", pkt->data, pkt->len);
+    ngx_quic_hexdump(pkt->log, "quic short packet in", pkt->data, pkt->len);
 #endif
 
     p = ngx_quic_read_uint8(p, end, &pkt->flags);
@@ -476,9 +476,9 @@ ngx_quic_parse_initial_header(ngx_quic_h
     pkt->len = varint;
 
 #ifdef NGX_QUIC_DEBUG_PACKETS
-    ngx_quic_hexdump0(pkt->log, "DCID", pkt->dcid.data, pkt->dcid.len);
-    ngx_quic_hexdump0(pkt->log, "SCID", pkt->scid.data, pkt->scid.len);
-    ngx_quic_hexdump0(pkt->log, "token", pkt->token.data, pkt->token.len);
+    ngx_quic_hexdump(pkt->log, "quic DCID", pkt->dcid.data, pkt->dcid.len);
+    ngx_quic_hexdump(pkt->log, "quic SCID", pkt->scid.data, pkt->scid.len);
+    ngx_quic_hexdump(pkt->log, "quic token", pkt->token.data, pkt->token.len);
 #endif
 
     return NGX_OK;
@@ -577,8 +577,8 @@ ngx_quic_parse_frame(ngx_quic_header_t *
                        f->u.crypto.data);
 
 #ifdef NGX_QUIC_DEBUG_FRAMES
-        ngx_quic_hexdump0(pkt->log, "CRYPTO frame contents",
-                          f->u.crypto.data, f->u.crypto.length);
+        ngx_quic_hexdump(pkt->log, "quic CRYPTO frame",
+                         f->u.crypto.data, f->u.crypto.length);
 #endif
         break;
 
@@ -837,8 +837,8 @@ ngx_quic_parse_frame(ngx_quic_header_t *
                        f->u.stream.fin);
 
 #ifdef NGX_QUIC_DEBUG_FRAMES
-            ngx_quic_hexdump0(pkt->log, "STREAM frame contents",
-                              f->u.stream.data, f->u.stream.length);
+            ngx_quic_hexdump(pkt->log, "quic STREAM frame",
+                             f->u.stream.data, f->u.stream.length);
 #endif
         break;
 
@@ -1080,8 +1080,8 @@ ngx_quic_parse_frame(ngx_quic_header_t *
                        "quic frame in: PATH_CHALLENGE");
 
 #ifdef NGX_QUIC_DEBUG_FRAMES
-        ngx_quic_hexdump0(pkt->log, "path challenge data",
-                          f->u.path_challenge.data, 8);
+        ngx_quic_hexdump(pkt->log, "quic PATH_CHALLENGE frame data",
+                         f->u.path_challenge.data, 8);
 #endif
         break;
 
@@ -1102,8 +1102,8 @@ ngx_quic_parse_frame(ngx_quic_header_t *
                        "quic frame in: PATH_RESPONSE");
 
 #ifdef NGX_QUIC_DEBUG_FRAMES
-        ngx_quic_hexdump0(pkt->log, "path response data",
-                          f->u.path_response.data, 8);
+        ngx_quic_hexdump(pkt->log, "quic PATH_RESPONSE frame data",
+                         f->u.path_response.data, 8);
 #endif
         break;