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
This commit is contained in:
Vladimir Homutov 2020-04-24 11:33:00 +03:00
parent a9ef6ed17d
commit 62943dfa08
4 changed files with 63 additions and 54 deletions

View File

@ -252,8 +252,9 @@ ngx_quic_set_read_secret(ngx_ssl_conn_t *ssl_conn,
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 *ssl_conn,
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_conn_t *ssl_conn,
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_conn_t *ssl_conn,
}
#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_t *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_t *c)
}
#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, ngx_queue_t *frames)
}
#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);

View File

@ -87,31 +87,25 @@ ngx_connection_t *ngx_quic_create_uni_stream(ngx_connection_t *c);
//#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_ */

View File

@ -157,8 +157,10 @@ ngx_quic_set_initial_secret(ngx_pool_t *pool, ngx_quic_secret_t *client,
};
#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, const EVP_MD *digest, ngx_str_t *out,
}
#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_quic_secrets_t *current,
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_header_t *pkt, ngx_ssl_conn_t *ssl_conn,
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_header_t *pkt, ngx_ssl_conn_t *ssl_conn,
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_header_t *pkt, ngx_ssl_conn_t *ssl_conn,
}
#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_header_t *pkt, ngx_ssl_conn_t *ssl_conn,
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_header_t *pkt, ngx_ssl_conn_t *ssl_conn,
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_header_t *pkt, ngx_ssl_conn_t *ssl_conn,
}
#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, ngx_ssl_conn_t *ssl_conn,
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, ngx_ssl_conn_t *ssl_conn,
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_ssl_conn_t *ssl_conn,
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, ngx_ssl_conn_t *ssl_conn,
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;

View File

@ -235,7 +235,7 @@ ngx_quic_parse_long_header(ngx_quic_header_t *pkt)
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_header_t *pkt, ngx_str_t *dcid)
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_header_t *pkt)
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 *pkt, u_char *start, u_char *end,
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 *pkt, u_char *start, u_char *end,
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 *pkt, u_char *start, u_char *end,
"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 *pkt, u_char *start, u_char *end,
"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;