mirror/nginx
1
0
Fork 0
mirror of https://github.com/nginx/nginx.git synced 2025-06-22 13:51:12 +08:00
Code Issues Actions 1 Packages Projects Releases Wiki Activity

Debug cleanup.

Browse Source 
+ all dumps are moved under one of the following macros (undefined by default):
    NGX_QUIC_DEBUG_PACKETS
    NGX_QUIC_DEBUG_FRAMES
    NGX_QUIC_DEBUG_FRAMES_ALLOC
    NGX_QUIC_DEBUG_CRYPTO

 + all QUIC debug messages got "quic " prefix

 + all input frames are reported as "quic frame in FOO_FRAME bar:1 baz:2"

 + all outgoing frames re reported as "quic frame out foo bar baz"

 + all stream operations are prefixed with id, like: "quic stream id 0x33 recv"

 + all transport parameters are prefixed with "quic tp"
   (hex dump is moved to caller, to avoid using ngx_cycle->log)

 + packet flags and some other debug messages are updated to
   include packet type
This commit is contained in:
Vladimir Homutov 2020-04-24 10:11:47 +03:00
parent ed506f8e15
commit a9ef6ed17d
4 changed files with 184 additions and 104 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

144
src/event/ngx_event_quic.c
View File

@ -251,8 +251,10 @@ 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);
#endif
keys = &c->quic->keys[level];
@ -276,8 +278,10 @@ 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);
#endif
keys = &c->quic->keys[level];
@ -299,7 +303,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);
#endif
keys = &c->quic->keys[level];
@ -315,7 +321,9 @@ ngx_quic_set_encryption_secrets(ngx_ssl_conn_t *ssl_conn,
return 1;
}
#ifdef NGX_QUIC_DEBUG_CRYPTO
ngx_quic_hexdump(c->log, "level:%d write", wsecret, secret_len, level);
#endif
return ngx_quic_set_encryption_secret(c->pool, ssl_conn, level,
wsecret, secret_len,
@ -341,7 +349,7 @@ ngx_quic_add_handshake_data(ngx_ssl_conn_t *ssl_conn,
qc = c->quic;
ngx_log_debug0(NGX_LOG_DEBUG_EVENT, c->log, 0,
"ngx_quic_add_handshake_data");
"quic ngx_quic_add_handshake_data");
/* XXX: obtain client parameters after the handshake? */
if (!qc->client_tp_done) {
@ -350,8 +358,8 @@ ngx_quic_add_handshake_data(ngx_ssl_conn_t *ssl_conn,
&client_params_len);
ngx_log_debug1(NGX_LOG_DEBUG_EVENT, c->log, 0,
"SSL_get_peer_quic_transport_params(): params_len %ui",
client_params_len);
"quic SSL_get_peer_quic_transport_params():"
" params_len %ui", client_params_len);
if (client_params_len != 0) {
p = (u_char *) client_params;
@ -430,7 +438,8 @@ ngx_quic_flush_flight(ngx_ssl_conn_t *ssl_conn)
c = ngx_ssl_get_connection((ngx_ssl_conn_t *) ssl_conn);
ngx_log_debug0(NGX_LOG_DEBUG_EVENT, c->log, 0, "ngx_quic_flush_flight()");
ngx_log_debug0(NGX_LOG_DEBUG_EVENT, c->log, 0,
"quic ngx_quic_flush_flight()");
return 1;
}
@ -445,7 +454,7 @@ ngx_quic_send_alert(ngx_ssl_conn_t *ssl_conn, enum ssl_encryption_level_t level,
c = ngx_ssl_get_connection((ngx_ssl_conn_t *) ssl_conn);
ngx_log_debug2(NGX_LOG_DEBUG_EVENT, c->log, 0,
"ngx_quic_send_alert(), lvl=%d, alert=%d",
"quic ngx_quic_send_alert(), lvl=%d, alert=%d",
(int) level, (int) alert);
if (c->quic == NULL) {
@ -666,6 +675,10 @@ ngx_quic_init_connection(ngx_connection_t *c)
return NGX_ERROR;
}
#ifdef NGX_QUIC_DEBUG_PACKETS
ngx_quic_hexdump0(c->log, "quic transport parameters", p, len);
#endif
if (SSL_set_quic_transport_params(ssl_conn, p, len) == 0) {
ngx_log_error(NGX_LOG_INFO, c->log, 0,
"SSL_set_quic_transport_params() failed");
@ -677,13 +690,14 @@ ngx_quic_init_connection(ngx_connection_t *c)
n = SSL_do_handshake(ssl_conn);
ngx_log_debug1(NGX_LOG_DEBUG_EVENT, c->log, 0, "SSL_do_handshake: %d", n);
ngx_log_debug1(NGX_LOG_DEBUG_EVENT, c->log, 0,
"quic SSL_do_handshake: %d", n);
if (n == -1) {
sslerr = SSL_get_error(ssl_conn, n);
ngx_log_debug1(NGX_LOG_DEBUG_EVENT, c->log, 0, "SSL_get_error: %d",
sslerr);
ngx_log_debug1(NGX_LOG_DEBUG_EVENT, c->log, 0,
"quic SSL_get_error: %d", sslerr);
if (sslerr != SSL_ERROR_WANT_READ) {
ngx_ssl_error(NGX_LOG_ERR, c->log, 0, "SSL_do_handshake() failed");
@ -692,7 +706,7 @@ ngx_quic_init_connection(ngx_connection_t *c)
}
ngx_log_debug2(NGX_LOG_DEBUG_EVENT, c->log, 0,
"SSL_quic_read_level: %d, SSL_quic_write_level: %d",
"quic SSL_quic_read_level: %d, SSL_quic_write_level: %d",
(int) SSL_quic_read_level(ssl_conn),
(int) SSL_quic_write_level(ssl_conn));
@ -762,11 +776,11 @@ ngx_quic_close_connection(ngx_connection_t *c, ngx_int_t rc)
ngx_pool_t *pool;
ngx_log_debug1(NGX_LOG_DEBUG_EVENT, c->log, 0,
"close quic connection, rc: %i", rc);
"quic ngx_quic_close_connection, rc: %i", rc);
if (!c->quic) {
ngx_log_debug0(NGX_LOG_DEBUG_EVENT, c->log, 0,
"close quic connection: early error");
"quic close connection early error");
} else if (ngx_quic_close_quic(c, rc) == NGX_AGAIN) {
return;
@ -906,7 +920,7 @@ ngx_quic_close_timer_handler(ngx_event_t *ev)
{
ngx_connection_t *c;
ngx_log_debug0(NGX_LOG_DEBUG_EVENT, ev->log, 0, "close timer");
ngx_log_debug0(NGX_LOG_DEBUG_EVENT, ev->log, 0, "quic close timer");
c = ev->data;
ngx_quic_close_connection(c, NGX_DONE);
@ -1416,13 +1430,13 @@ ngx_quic_payload_handler(ngx_connection_t *c, ngx_quic_header_t *pkt)
/* TODO: handle */
ngx_log_debug0(NGX_LOG_DEBUG_EVENT, c->log, 0,
"frame handler not implemented");
"quic frame handler not implemented");
ack_this = 1;
break;
default:
ngx_log_debug0(NGX_LOG_DEBUG_EVENT, c->log, 0,
"missing frame handler");
"quic missing frame handler");
return NGX_ERROR;
}
}
@ -1522,7 +1536,7 @@ ngx_quic_handle_ack_frame(ngx_connection_t *c, ngx_quic_header_t *pkt,
ctx = ngx_quic_get_send_ctx(c->quic, pkt->level);
ngx_log_debug1(NGX_LOG_DEBUG_EVENT, c->log, 0,
"ngx_quic_handle_ack_frame level %d", pkt->level);
"quic ngx_quic_handle_ack_frame level %d", pkt->level);
/*
* TODO: If any computed packet number is negative, an endpoint MUST
@ -1547,7 +1561,7 @@ ngx_quic_handle_ack_frame(ngx_connection_t *c, ngx_quic_header_t *pkt,
if (ctx->largest_ack < max) {
ctx->largest_ack = max;
ngx_log_debug1(NGX_LOG_DEBUG_EVENT, c->log, 0,
"updated largest received: %ui", max);
"quic updated largest received ack: %ui", max);
}
pos = ack->ranges_start;
@ -1643,7 +1657,7 @@ ngx_quic_handle_ordered_frame(ngx_connection_t *c, ngx_quic_frames_stream_t *fs,
if (f->offset > fs->received) {
ngx_log_debug2(NGX_LOG_DEBUG_EVENT, c->log, 0,
"out-of-order frame: expecting %ui got %ui",
"quic out-of-order frame: expecting %ui got %ui",
fs->received, f->offset);
return ngx_quic_buffer_frame(c, fs, frame);
@ -1704,7 +1718,8 @@ ngx_quic_handle_ordered_frame(ngx_connection_t *c, ngx_quic_frames_stream_t *fs,
fs->total -= f->length;
ngx_log_debug1(NGX_LOG_DEBUG_EVENT, c->log, 0,
"skipped buffered frame, total %ui", fs->total);
"quic skipped buffered frame, total %ui",
fs->total);
ngx_quic_free_frame(c, frame);
continue;
}
@ -1730,7 +1745,7 @@ ngx_quic_handle_ordered_frame(ngx_connection_t *c, ngx_quic_frames_stream_t *fs,
ngx_queue_remove(q);
ngx_log_debug1(NGX_LOG_DEBUG_EVENT, c->log, 0,
"consumed buffered frame, total %ui", fs->total);
"quic consumed buffered frame, total %ui", fs->total);
ngx_quic_free_frame(c, frame);
@ -1755,12 +1770,12 @@ ngx_quic_adjust_frame_offset(ngx_connection_t *c, ngx_quic_frame_t *frame,
/* range preceeding already received data or duplicate, ignore */
ngx_log_debug0(NGX_LOG_DEBUG_EVENT, c->log, 0,
"old or duplicate data in ordered frame, ignored");
"quic old or duplicate data in ordered frame, ignored");
return NGX_DONE;
}
ngx_log_debug0(NGX_LOG_DEBUG_EVENT, c->log, 0,
"adjusted ordered frame data start to expected offset");
"quic adjusted ordered frame data start to expected offset");
/* intersecting range: adjust data size */
@ -1781,7 +1796,8 @@ ngx_quic_buffer_frame(ngx_connection_t *c, ngx_quic_frames_stream_t *fs,
ngx_quic_frame_t *dst, *item;
ngx_quic_ordered_frame_t *f, *df;
ngx_log_debug0(NGX_LOG_DEBUG_EVENT, c->log, 0, "ngx_quic_buffer_frame");
ngx_log_debug0(NGX_LOG_DEBUG_EVENT, c->log, 0,
"quic ngx_quic_buffer_frame");
f = &frame->u.ord;
@ -1811,8 +1827,8 @@ ngx_quic_buffer_frame(ngx_connection_t *c, ngx_quic_frames_stream_t *fs,
fs->total += f->length;
ngx_log_debug1(NGX_LOG_DEBUG_EVENT, c->log, 0,
"ordered frame with unexpected offset: buffered, total %ui",
fs->total);
"quic ordered frame with unexpected offset:"
" buffered, total %ui", fs->total);
/* TODO: do we need some timeout for this queue ? */
@ -1867,7 +1883,7 @@ ngx_quic_crypto_input(ngx_connection_t *c, ngx_quic_frame_t *frame)
ssl_conn = c->ssl->connection;
ngx_log_debug2(NGX_LOG_DEBUG_EVENT, c->log, 0,
"SSL_quic_read_level: %d, SSL_quic_write_level: %d",
"quic SSL_quic_read_level: %d, SSL_quic_write_level: %d",
(int) SSL_quic_read_level(ssl_conn),
(int) SSL_quic_write_level(ssl_conn));
@ -1901,7 +1917,7 @@ ngx_quic_crypto_input(ngx_connection_t *c, ngx_quic_frame_t *frame)
"quic ssl cipher: %s", SSL_get_cipher(ssl_conn));
ngx_log_debug0(NGX_LOG_DEBUG_EVENT, c->log, 0,
"handshake completed successfully");
"quic handshake completed successfully");
frame = ngx_quic_alloc_frame(c, 0);
if (frame == NULL) {
@ -1928,7 +1944,7 @@ ngx_quic_crypto_input(ngx_connection_t *c, ngx_quic_frame_t *frame)
}
ngx_log_debug2(NGX_LOG_DEBUG_EVENT, c->log, 0,
"SSL_quic_read_level: %d, SSL_quic_write_level: %d",
"quic SSL_quic_read_level: %d, SSL_quic_write_level: %d",
(int) SSL_quic_read_level(ssl_conn),
(int) SSL_quic_write_level(ssl_conn));
@ -1954,7 +1970,8 @@ ngx_quic_handle_stream_frame(ngx_connection_t *c, ngx_quic_header_t *pkt,
sn = ngx_quic_find_stream(&qc->streams.tree, f->stream_id);
if (sn == NULL) {
ngx_log_debug0(NGX_LOG_DEBUG_EVENT, c->log, 0, "stream is new");
ngx_log_debug1(NGX_LOG_DEBUG_EVENT, c->log, 0,
"quic stream id 0x%xi is new", f->stream_id);
n = (f->stream_id & NGX_QUIC_STREAM_UNIDIRECTIONAL)
? qc->tp.initial_max_stream_data_uni
@ -2042,7 +2059,7 @@ ngx_quic_stream_input(ngx_connection_t *c, ngx_quic_frame_t *frame)
return NGX_ERROR;
}
ngx_log_debug0(NGX_LOG_DEBUG_EVENT, c->log, 0, "existing stream");
ngx_log_debug0(NGX_LOG_DEBUG_EVENT, c->log, 0, "quic existing stream");
b = sn->b;
@ -2350,7 +2367,8 @@ ngx_quic_send_frames(ngx_connection_t *c, ngx_queue_t *frames)
static u_char src[NGX_QUIC_DEFAULT_MAX_PACKET_SIZE];
static u_char dst[NGX_QUIC_DEFAULT_MAX_PACKET_SIZE];
ngx_log_debug0(NGX_LOG_DEBUG_EVENT, c->log, 0, "ngx_quic_send_frames");
ngx_log_debug0(NGX_LOG_DEBUG_EVENT, c->log, 0,
"quic ngx_quic_send_frames");
q = ngx_queue_head(frames);
start = ngx_queue_data(q, ngx_quic_frame_t, queue);
@ -2368,7 +2386,8 @@ ngx_quic_send_frames(ngx_connection_t *c, ngx_queue_t *frames)
{
f = ngx_queue_data(q, ngx_quic_frame_t, queue);
ngx_log_debug1(NGX_LOG_DEBUG_EVENT, c->log, 0, "frame: %s", f->info);
ngx_log_debug1(NGX_LOG_DEBUG_EVENT, c->log, 0,
"quic frame out: %s", f->info);
len = ngx_quic_create_frame(p, f);
if (len == -1) {
@ -2398,10 +2417,6 @@ ngx_quic_send_frames(ngx_connection_t *c, ngx_queue_t *frames)
out.len++;
}
ngx_log_debug3(NGX_LOG_DEBUG_EVENT, c->log, 0,
"packet ready: %ui bytes at level %d need_ack: %ui",
out.len, start->level, pkt.need_ack);
qc = c->quic;
keys = &c->quic->keys[start->level];
@ -2430,11 +2445,19 @@ ngx_quic_send_frames(ngx_connection_t *c, ngx_queue_t *frames)
res.data = dst;
ngx_log_debug6(NGX_LOG_DEBUG_EVENT, c->log, 0,
"quic packet ready: %ui bytes at level %d"
" need_ack: %d number: %L encoded %d:0x%xD",
out.len, start->level, pkt.need_ack, pkt.number,
pkt.num_len, pkt.trunc);
if (ngx_quic_encrypt(&pkt, c->ssl->connection, &res) != NGX_OK) {
return NGX_ERROR;
}
#ifdef NGX_QUIC_DEBUG_PACKETS
ngx_quic_hexdump0(c->log, "packet to send", res.data, res.len);
#endif
len = c->send(c, res.data, res.len);
if (len == NGX_ERROR || (size_t) len != res.len) {
@ -2490,7 +2513,7 @@ ngx_quic_retransmit_handler(ngx_event_t *ev)
ngx_quic_connection_t *qc;
ngx_log_debug0(NGX_LOG_DEBUG_EVENT, ev->log, 0,
"retransmit timer");
"quic retransmit timer");
c = ev->data;
qc = c->quic;
@ -2522,7 +2545,7 @@ ngx_quic_push_handler(ngx_event_t *ev)
{
ngx_connection_t *c;
ngx_log_debug0(NGX_LOG_DEBUG_EVENT, ev->log, 0, "push timer");
ngx_log_debug0(NGX_LOG_DEBUG_EVENT, ev->log, 0, "quic push timer");
c = ev->data;
@ -2619,7 +2642,7 @@ ngx_quic_create_uni_stream(ngx_connection_t *c)
| NGX_QUIC_STREAM_UNIDIRECTIONAL;
ngx_log_debug2(NGX_LOG_DEBUG_EVENT, c->log, 0,
"creating server uni stream #%ui id %ui",
"quic creating server uni stream #%ui id %ui",
qc->streams.id_counter, id);
qc->streams.id_counter++;
@ -2779,9 +2802,9 @@ ngx_quic_stream_recv(ngx_connection_t *c, u_char *buf, size_t size)
qc = pc->quic;
rev = c->read;
ngx_log_debug2(NGX_LOG_DEBUG_EVENT, c->log, 0,
"quic recv: eof:%d, avail:%z",
rev->pending_eof, b->last - b->pos);
ngx_log_debug3(NGX_LOG_DEBUG_EVENT, c->log, 0,
"quic stream id 0x%xi recv: eof:%d, avail:%z",
qs->id, rev->pending_eof, b->last - b->pos);
if (b->pos == b->last) {
rev->ready = 0;
@ -2791,7 +2814,8 @@ ngx_quic_stream_recv(ngx_connection_t *c, u_char *buf, size_t size)
return 0;
}
ngx_log_debug0(NGX_LOG_DEBUG_EVENT, c->log, 0, "quic recv() not ready");
ngx_log_debug1(NGX_LOG_DEBUG_EVENT, c->log, 0,
"quic stream id 0x%xi recv() not ready", qs->id);
return NGX_AGAIN;
}
@ -2808,8 +2832,8 @@ ngx_quic_stream_recv(ngx_connection_t *c, u_char *buf, size_t size)
rev->ready = rev->pending_eof;
}
ngx_log_debug2(NGX_LOG_DEBUG_EVENT, c->log, 0,
"quic recv: %z of %uz", len, size);
ngx_log_debug3(NGX_LOG_DEBUG_EVENT, c->log, 0,
"quic stream id 0x%xi recv: %z of %uz", qs->id, len, size);
if (!rev->pending_eof) {
frame = ngx_quic_alloc_frame(pc, 0);
@ -2850,9 +2874,9 @@ ngx_quic_stream_recv(ngx_connection_t *c, u_char *buf, size_t size)
ngx_quic_queue_frame(pc->quic, frame);
ngx_log_debug1(NGX_LOG_DEBUG_EVENT, c->log, 0,
"quic recv: increased max data: %ui",
qc->streams.max_data);
ngx_log_debug2(NGX_LOG_DEBUG_EVENT, c->log, 0,
"quic stream id 0x%xi recv: increased max data: %ui",
qs->id, qc->streams.max_data);
}
return len;
@ -2877,7 +2901,8 @@ ngx_quic_stream_send(ngx_connection_t *c, u_char *buf, size_t size)
return NGX_ERROR;
}
ngx_log_debug1(NGX_LOG_DEBUG_EVENT, c->log, 0, "quic send: %uz", size);
ngx_log_debug2(NGX_LOG_DEBUG_EVENT, c->log, 0,
"quic stream id 0x%xi send: %uz", qs->id, size);
/*
* we need to fit at least 1 frame into a packet, thus account head/tail;
@ -2915,7 +2940,7 @@ ngx_quic_stream_send(ngx_connection_t *c, u_char *buf, size_t size)
c->sent += fsize;
p += fsize;
ngx_sprintf(frame->info, "stream %xi len=%ui level=%d",
ngx_sprintf(frame->info, "stream 0x%xi len=%ui level=%d",
qs->id, fsize, frame->level);
ngx_quic_queue_frame(qc, frame);
@ -2939,7 +2964,8 @@ ngx_quic_stream_cleanup_handler(void *data)
pc = qs->parent;
qc = pc->quic;
ngx_log_debug0(NGX_LOG_DEBUG_EVENT, c->log, 0, "quic stream cleanup");
ngx_log_debug1(NGX_LOG_DEBUG_EVENT, c->log, 0,
"quic stream id 0x%xi cleanup", qs->id);
ngx_rbtree_delete(&qc->streams.tree, &qs->node);
ngx_quic_free_frames(pc, &qs->fs.frames);
@ -2955,7 +2981,8 @@ ngx_quic_stream_cleanup_handler(void *data)
return;
}
ngx_log_debug0(NGX_LOG_DEBUG_EVENT, c->log, 0, "quic send fin");
ngx_log_debug1(NGX_LOG_DEBUG_EVENT, c->log, 0,
"quic stream id 0x%xi send fin", qs->id);
frame = ngx_quic_alloc_frame(pc, 0);
if (frame == NULL) {
@ -2974,7 +3001,8 @@ ngx_quic_stream_cleanup_handler(void *data)
frame->u.stream.length = 0;
frame->u.stream.data = NULL;
ngx_sprintf(frame->info, "stream %xi fin=1 level=%d", qs->id, frame->level);
ngx_sprintf(frame->info, "stream 0x%xi fin=1 level=%d",
qs->id, frame->level);
ngx_quic_queue_frame(qc, frame);
@ -3051,8 +3079,10 @@ ngx_quic_alloc_frame(ngx_connection_t *c, size_t size)
ngx_queue_remove(&frame->queue);
#ifdef NGX_QUIC_DEBUG_FRAMES_ALLOC
ngx_log_debug1(NGX_LOG_DEBUG_EVENT, c->log, 0,
"reuse quic frame n:%ui", qc->nframes);
"quic reuse frame n:%ui", qc->nframes);
#endif
} else {
frame = ngx_pcalloc(c->pool, sizeof(ngx_quic_frame_t));
@ -3065,8 +3095,10 @@ ngx_quic_alloc_frame(ngx_connection_t *c, size_t size)
++qc->nframes;
#endif
#ifdef NGX_QUIC_DEBUG_FRAMES_ALLOC
ngx_log_debug1(NGX_LOG_DEBUG_EVENT, c->log, 0,
"alloc quic frame n:%ui", qc->nframes);
"quic alloc frame n:%ui", qc->nframes);
#endif
}
ngx_memzero(frame, sizeof(ngx_quic_frame_t));
@ -3090,6 +3122,8 @@ ngx_quic_free_frame(ngx_connection_t *c, ngx_quic_frame_t *frame)
ngx_queue_insert_head(&qc->free_frames, &frame->queue);
#ifdef NGX_QUIC_DEBUG_FRAMES_ALLOC
ngx_log_debug1(NGX_LOG_DEBUG_EVENT, c->log, 0,
"free quic frame n:%ui", qc->nframes);
"quic free frame n:%ui", qc->nframes);
#endif
}

6
src/event/ngx_event_quic.h
View File

@ -82,6 +82,12 @@ ngx_connection_t *ngx_quic_create_uni_stream(ngx_connection_t *c);
/********************************* DEBUG *************************************/
//#define NGX_QUIC_DEBUG_PACKETS /* dump packet contents */
//#define NGX_QUIC_DEBUG_FRAMES /* dump frames contents */
//#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, ...) \

34
src/event/ngx_event_quic_protection.c
View File

@ -156,8 +156,10 @@ ngx_quic_set_initial_secret(ngx_pool_t *pool, ngx_quic_secret_t *client,
.len = is_len
};
#ifdef NGX_QUIC_DEBUG_CRYPTO
ngx_quic_hexdump0(pool->log, "salt", salt, sizeof(salt));
ngx_quic_hexdump0(pool->log, "initial secret", is, is_len);
#endif
/* draft-ietf-quic-tls-23#section-5.2 */
client->secret.len = SHA256_DIGEST_LENGTH;
@ -263,8 +265,10 @@ ngx_quic_hkdf_expand(ngx_pool_t *pool, const EVP_MD *digest, ngx_str_t *out,
return NGX_ERROR;
}
#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);
#endif
return NGX_OK;
}
@ -761,21 +765,21 @@ 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);
#endif
if (ngx_quic_ciphers(ssl_conn, &ciphers, pkt->level) == NGX_ERROR) {
return NGX_ERROR;
}
ngx_log_debug3(NGX_LOG_DEBUG_EVENT, pkt->log, 0,
"ngx_quic_create_long_packet: number %L, encoded %d:0x%xD",
pkt->number, (int) pkt->num_len, pkt->trunc);
ngx_memcpy(nonce, pkt->secret->iv.data, pkt->secret->iv.len);
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);
#endif
if (ngx_quic_tls_seal(ciphers.c, pkt->secret, &out,
nonce, &pkt->payload, &ad, pkt->log)
@ -791,8 +795,10 @@ ngx_quic_create_long_packet(ngx_quic_header_t *pkt, ngx_ssl_conn_t *ssl_conn,
return NGX_ERROR;
}
#ifdef NGX_QUIC_DEBUG_CRYPTO
ngx_quic_hexdump0(pkt->log, "sample", sample, 16);
ngx_quic_hexdump0(pkt->log, "mask", mask, 5);
#endif
/* quic-tls: 5.4.1. Header Protection Application */
ad.data[0] ^= mask[0] & 0x0f;
@ -824,21 +830,26 @@ 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);
#endif
if (ngx_quic_ciphers(ssl_conn, &ciphers, pkt->level) == NGX_ERROR) {
return NGX_ERROR;
}
ngx_log_debug3(NGX_LOG_DEBUG_EVENT, pkt->log, 0,
"ngx_quic_create_short_packet: number %L, encoded %d:0x%xD",
pkt->number, (int) pkt->num_len, pkt->trunc);
"quic ngx_quic_create_short_packet: number %L,"
" encoded %d:0x%xD", pkt->number, (int) pkt->num_len,
pkt->trunc);
ngx_memcpy(nonce, pkt->secret->iv.data, pkt->secret->iv.len);
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);
#endif
if (ngx_quic_tls_seal(ciphers.c, pkt->secret, &out,
nonce, &pkt->payload, &ad, pkt->log)
@ -854,8 +865,10 @@ ngx_quic_create_short_packet(ngx_quic_header_t *pkt, ngx_ssl_conn_t *ssl_conn,
return NGX_ERROR;
}
#ifdef NGX_QUIC_DEBUG_CRYPTO
ngx_quic_hexdump0(pkt->log, "sample", sample, 16);
ngx_quic_hexdump0(pkt->log, "mask", mask, 5);
#endif
/* quic-tls: 5.4.1. Header Protection Application */
ad.data[0] ^= mask[0] & 0x1f;
@ -963,7 +976,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);
#endif
/* header protection */
@ -991,7 +1006,10 @@ 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);
#endif
ngx_log_debug1(NGX_LOG_DEBUG_EVENT, pkt->log, 0,
"quic clear flags: %xi", clearflags);
ngx_log_debug2(NGX_LOG_DEBUG_EVENT, pkt->log, 0,
@ -1021,8 +1039,10 @@ ngx_quic_decrypt(ngx_quic_header_t *pkt, ngx_ssl_conn_t *ssl_conn,
ngx_memcpy(nonce, secret->iv.data, secret->iv.len);
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);
#endif
pkt->payload.len = in.len - EVP_GCM_TLS_TAG_LEN;
@ -1035,8 +1055,10 @@ ngx_quic_decrypt(ngx_quic_header_t *pkt, ngx_ssl_conn_t *ssl_conn,
rc = ngx_quic_tls_open(ciphers.c, secret, &pkt->payload,
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);
#endif
return rc;
}

104
src/event/ngx_event_quic_transport.c
View File

@ -234,7 +234,9 @@ ngx_quic_parse_long_header(ngx_quic_header_t *pkt)
p = pkt->data;
end = pkt->data + pkt->len;
#ifdef NGX_QUIC_DEBUG_PACKETS
ngx_quic_hexdump0(pkt->log, "long input", pkt->data, pkt->len);
#endif
p = ngx_quic_read_uint8(p, end, &pkt->flags);
if (p == NULL) {
@ -256,7 +258,8 @@ ngx_quic_parse_long_header(ngx_quic_header_t *pkt)
}
ngx_log_debug2(NGX_LOG_DEBUG_EVENT, pkt->log, 0,
"quic flags:%xi version:%xD", pkt->flags, pkt->version);
"quic long packet flags:%xi version:%xD",
pkt->flags, pkt->version);
if (pkt->version != NGX_QUIC_VERSION) {
ngx_log_error(NGX_LOG_INFO, pkt->log, 0,
@ -388,7 +391,9 @@ ngx_quic_parse_short_header(ngx_quic_header_t *pkt, ngx_str_t *dcid)
p = pkt->data;
end = pkt->data + pkt->len;
#ifdef NGX_QUIC_DEBUG_PACKETS
ngx_quic_hexdump0(pkt->log, "short input", pkt->data, pkt->len);
#endif
p = ngx_quic_read_uint8(p, end, &pkt->flags);
if (p == NULL) {
@ -403,7 +408,7 @@ ngx_quic_parse_short_header(ngx_quic_header_t *pkt, ngx_str_t *dcid)
}
ngx_log_debug1(NGX_LOG_DEBUG_EVENT, pkt->log, 0,
"quic flags:%xi", pkt->flags);
"quic short packet flags:%xi", pkt->flags);
if (ngx_memcmp(p, dcid->data, dcid->len) != 0) {
ngx_log_error(NGX_LOG_INFO, pkt->log, 0, "unexpected quic dcid");
@ -460,7 +465,7 @@ ngx_quic_parse_initial_header(ngx_quic_header_t *pkt)
}
ngx_log_debug1(NGX_LOG_DEBUG_EVENT, pkt->log, 0,
"quic packet length: %uL", varint);
"quic initial packet length: %uL", varint);
if (varint > (uint64_t) ((pkt->data + pkt->len) - p)) {
ngx_log_error(NGX_LOG_INFO, pkt->log, 0, "truncated initial packet");
@ -470,9 +475,11 @@ ngx_quic_parse_initial_header(ngx_quic_header_t *pkt)
pkt->raw->pos = p;
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);
#endif
return NGX_OK;
}
@ -496,7 +503,7 @@ ngx_quic_parse_handshake_header(ngx_quic_header_t *pkt)
}
ngx_log_debug1(NGX_LOG_DEBUG_EVENT, pkt->log, 0,
"quic packet length: %uL", plen);
"quic handshake packet length: %uL", plen);
if (plen > (uint64_t)((pkt->data + pkt->len) - p)) {
ngx_log_error(NGX_LOG_INFO, pkt->log, 0, "truncated handshake packet");
@ -565,12 +572,14 @@ ngx_quic_parse_frame(ngx_quic_header_t *pkt, u_char *start, u_char *end,
}
ngx_log_debug3(NGX_LOG_DEBUG_EVENT, pkt->log, 0,
"quic CRYPTO frame length: %uL off:%uL pp:%p",
"quic frame in: CRYPTO length: %uL off:%uL pp:%p",
f->u.crypto.length, f->u.crypto.offset,
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);
#endif
break;
case NGX_QUIC_FT_PADDING:
@ -620,8 +629,8 @@ ngx_quic_parse_frame(ngx_quic_header_t *pkt, u_char *start, u_char *end,
f->u.ack.ranges_end = p;
ngx_log_debug4(NGX_LOG_DEBUG_EVENT, pkt->log, 0,
"ACK: { largest=%ui delay=%ui count=%ui first=%ui}",
f->u.ack.largest,
"quic frame in ACK largest:%ui delay:%ui"
" count:%ui first:%ui", f->u.ack.largest,
f->u.ack.delay,
f->u.ack.range_count,
f->u.ack.first_range);
@ -638,7 +647,7 @@ ngx_quic_parse_frame(ngx_quic_header_t *pkt, u_char *start, u_char *end,
}
ngx_log_debug3(NGX_LOG_DEBUG_EVENT, pkt->log, 0,
"ACK ECN counters: %ui %ui %ui",
"quic ACK ECN counters: %ui %ui %ui",
f->u.ack.ect0, f->u.ack.ect1, f->u.ack.ce);
}
@ -692,7 +701,7 @@ ngx_quic_parse_frame(ngx_quic_header_t *pkt, u_char *start, u_char *end,
}
ngx_log_debug3(NGX_LOG_DEBUG_EVENT, pkt->log, 0,
"NCID: { seq=%ui retire=%ui len=%ui}",
"quic frame in: NCID seq:%ui retire:%ui len:%ui",
f->u.ncid.seqnum, f->u.ncid.retire, f->u.ncid.len);
break;
@ -746,14 +755,16 @@ ngx_quic_parse_frame(ngx_quic_header_t *pkt, u_char *start, u_char *end,
if (f->type == NGX_QUIC_FT_CONNECTION_CLOSE) {
ngx_log_debug4(NGX_LOG_DEBUG_EVENT, pkt->log, 0,
"CONN.CLOSE: { %s (0x%xi) type=0x%xi reason='%V'}",
"quic frame in CONNECTION_CLOSE"
" err:%s code:0x%xi type:0x%xi reason:'%V'",
ngx_quic_error_text(f->u.close.error_code),
f->u.close.error_code, f->u.close.frame_type,
&f->u.close.reason);
} else {
ngx_log_debug2(NGX_LOG_DEBUG_EVENT, pkt->log, 0,
"CONN.CLOSE2: { (0x%xi) reason '%V'}",
"quic frame in: CONNECTION_CLOSE2:"
" code:0x%xi reason:'%V'",
f->u.close.error_code, &f->u.close.reason);
}
@ -819,14 +830,16 @@ ngx_quic_parse_frame(ngx_quic_header_t *pkt, u_char *start, u_char *end,
}
ngx_log_debug7(NGX_LOG_DEBUG_EVENT, pkt->log, 0,
"STREAM frame { 0x%xi id 0x%xi offset 0x%xi "
"len 0x%xi bits:off=%d len=%d fin=%d }",
"quic frame in: STREAM type:0x%xi id:0x%xi offset:0x%xi "
"len:0x%xi bits off:%d len:%d fin:%d",
f->type, f->u.stream.stream_id, f->u.stream.offset,
f->u.stream.length, f->u.stream.off, f->u.stream.len,
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);
#endif
break;
case NGX_QUIC_FT_MAX_DATA:
@ -843,7 +856,7 @@ ngx_quic_parse_frame(ngx_quic_header_t *pkt, u_char *start, u_char *end,
}
ngx_log_debug1(NGX_LOG_DEBUG_EVENT, pkt->log, 0,
"MAX_DATA frame { Maximum Data %ui }",
"quic frame in: MAX_DATA max_data:%ui",
f->u.max_data.max_data);
break;
@ -864,8 +877,8 @@ ngx_quic_parse_frame(ngx_quic_header_t *pkt, u_char *start, u_char *end,
}
ngx_log_debug3(NGX_LOG_DEBUG_EVENT, pkt->log, 0,
"RESET STREAM frame"
" { id 0x%xi error_code 0x%xi final_size 0x%xi }",
"quic frame in: RESET_STREAM"
" id:0x%xi error_code:0x%xi final_size:0x%xi",
f->u.reset_stream.id, f->u.reset_stream.error_code,
f->u.reset_stream.final_size);
break;
@ -891,7 +904,7 @@ ngx_quic_parse_frame(ngx_quic_header_t *pkt, u_char *start, u_char *end,
}
ngx_log_debug2(NGX_LOG_DEBUG_EVENT, pkt->log, 0,
"STOP SENDING frame { id 0x%xi error_code 0x%xi}",
"quic frame in: STOP_SENDING id:0x%xi error_code:0x%xi",
f->u.stop_sending.id, f->u.stop_sending.error_code);
break;
@ -914,7 +927,7 @@ ngx_quic_parse_frame(ngx_quic_header_t *pkt, u_char *start, u_char *end,
(f->type == NGX_QUIC_FT_STREAMS_BLOCKED) ? 1 : 0;
ngx_log_debug2(NGX_LOG_DEBUG_EVENT, pkt->log, 0,
"STREAMS BLOCKED frame { limit %ui bidi: %d }",
"quic frame in: STREAMS_BLOCKED limit:%ui bidi:%d",
f->u.streams_blocked.limit,
f->u.streams_blocked.bidi);
@ -954,7 +967,7 @@ ngx_quic_parse_frame(ngx_quic_header_t *pkt, u_char *start, u_char *end,
f->u.max_streams.bidi = (f->type == NGX_QUIC_FT_MAX_STREAMS) ? 1 : 0;
ngx_log_debug2(NGX_LOG_DEBUG_EVENT, pkt->log, 0,
"MAX STREAMS frame { limit %ui bidi: %d }",
"quic frame in: MAX_STREAMS limit:%ui bidi:%d",
f->u.max_streams.limit,
f->u.max_streams.bidi);
break;
@ -980,7 +993,7 @@ ngx_quic_parse_frame(ngx_quic_header_t *pkt, u_char *start, u_char *end,
}
ngx_log_debug2(NGX_LOG_DEBUG_EVENT, pkt->log, 0,
"MAX STREAM DATA frame { id: %ui limit: %ui }",
"quic frame in: MAX_STREAM_DATA id:%ui limit:%ui",
f->u.max_stream_data.id,
f->u.max_stream_data.limit);
break;
@ -999,7 +1012,7 @@ ngx_quic_parse_frame(ngx_quic_header_t *pkt, u_char *start, u_char *end,
}
ngx_log_debug1(NGX_LOG_DEBUG_EVENT, pkt->log, 0,
"DATA BLOCKED frame { limit %ui }",
"quic frame in: DATA_BLOCKED limit:%ui",
f->u.data_blocked.limit);
break;
@ -1024,7 +1037,8 @@ ngx_quic_parse_frame(ngx_quic_header_t *pkt, u_char *start, u_char *end,
}
ngx_log_debug2(NGX_LOG_DEBUG_EVENT, pkt->log, 0,
"STREAM DATA BLOCKED frame { id: %ui limit: %ui }",
"quic frame in: STREAM_DATA_BLOCKED"
" id:%ui limit:%ui",
f->u.stream_data_blocked.id,
f->u.stream_data_blocked.limit);
break;
@ -1044,7 +1058,8 @@ ngx_quic_parse_frame(ngx_quic_header_t *pkt, u_char *start, u_char *end,
}
ngx_log_debug1(NGX_LOG_DEBUG_EVENT, pkt->log, 0,
"RETIRE CONNECTION ID frame { sequence_number %ui }",
"quic frame in: RETIRE_CONNECTION_ID"
" sequence_number:%ui",
f->u.retire_cid.sequence_number);
break;
@ -1062,10 +1077,12 @@ ngx_quic_parse_frame(ngx_quic_header_t *pkt, u_char *start, u_char *end,
}
ngx_log_debug0(NGX_LOG_DEBUG_EVENT, pkt->log, 0,
"PATH CHALLENGE frame");
"quic frame in: PATH_CHALLENGE");
#ifdef NGX_QUIC_DEBUG_FRAMES
ngx_quic_hexdump0(pkt->log, "path challenge data",
f->u.path_challenge.data, 8);
#endif
break;
case NGX_QUIC_FT_PATH_RESPONSE:
@ -1082,10 +1099,12 @@ ngx_quic_parse_frame(ngx_quic_header_t *pkt, u_char *start, u_char *end,
}
ngx_log_debug0(NGX_LOG_DEBUG_EVENT, pkt->log, 0,
"PATH RESPONSE frame");
"quic frame in: PATH_RESPONSE");
#ifdef NGX_QUIC_DEBUG_FRAMES
ngx_quic_hexdump0(pkt->log, "path response data",
f->u.path_response.data, 8);
#endif
break;
default:
@ -1130,7 +1149,7 @@ ngx_quic_parse_ack_range(ngx_quic_header_t *pkt, u_char *start, u_char *end,
}
ngx_log_debug2(NGX_LOG_DEBUG_EVENT, pkt->log, 0,
"ACK range: gap %ui range %ui", *gap, *range);
"quic ACK range: gap %ui range %ui", *gap, *range);
return p - start;
}
@ -1472,47 +1491,50 @@ ngx_quic_parse_transport_params(u_char *p, u_char *end, ngx_quic_tp_t *tp,
}
ngx_log_debug0(NGX_LOG_DEBUG_EVENT, log, 0,
"client transport parameters parsed successfully");
"quic transport parameters parsed ok");
ngx_log_debug1(NGX_LOG_DEBUG_EVENT, log, 0,
"disable active migration: %ui",
"quic tp disable active migration: %ui",
tp->disable_active_migration);
ngx_log_debug1(NGX_LOG_DEBUG_EVENT, log, 0, "idle timeout: %ui",
ngx_log_debug1(NGX_LOG_DEBUG_EVENT, log, 0, "quic tp idle_timeout: %ui",
tp->max_idle_timeout);
ngx_log_debug1(NGX_LOG_DEBUG_EVENT, log, 0, "max packet size: %ui",
ngx_log_debug1(NGX_LOG_DEBUG_EVENT, log, 0, "quic tp max_packet_size: %ui",
tp->max_packet_size);
ngx_log_debug1(NGX_LOG_DEBUG_EVENT, log, 0, "max data: %ui",
ngx_log_debug1(NGX_LOG_DEBUG_EVENT, log, 0, "quic tp max_data: %ui",
tp->initial_max_data);
ngx_log_debug1(NGX_LOG_DEBUG_EVENT, log, 0,
"max stream data bidi local: %ui",
"quic tp max_stream_data_bidi_local: %ui",
tp->initial_max_stream_data_bidi_local);
ngx_log_debug1(NGX_LOG_DEBUG_EVENT, log, 0,
"max stream data bidi remote: %ui",
"quic tp max_stream_data_bidi_remote: %ui",
tp->initial_max_stream_data_bidi_remote);
ngx_log_debug1(NGX_LOG_DEBUG_EVENT, log, 0, "max stream data uni: %ui",
ngx_log_debug1(NGX_LOG_DEBUG_EVENT, log, 0,
"quic tp max_stream_data_uni: %ui",
tp->initial_max_stream_data_uni);
ngx_log_debug1(NGX_LOG_DEBUG_EVENT, log, 0,
"initial max streams bidi: %ui",
"quic tp initial_max_streams_bidi: %ui",
tp->initial_max_streams_bidi);
ngx_log_debug1(NGX_LOG_DEBUG_EVENT, log, 0, "initial max streams uni: %ui",
ngx_log_debug1(NGX_LOG_DEBUG_EVENT, log, 0,
"quic tp initial_max_streams_uni: %ui",
tp->initial_max_streams_uni);
ngx_log_debug1(NGX_LOG_DEBUG_EVENT, log, 0, "ack delay exponent: %ui",
ngx_log_debug1(NGX_LOG_DEBUG_EVENT, log, 0,
"quic tp ack_delay_exponent: %ui",
tp->ack_delay_exponent);
ngx_log_debug1(NGX_LOG_DEBUG_EVENT, log, 0, "max ack delay: %ui",
ngx_log_debug1(NGX_LOG_DEBUG_EVENT, log, 0, "quic tp max_ack_delay: %ui",
tp->max_ack_delay);
ngx_log_debug1(NGX_LOG_DEBUG_EVENT, log, 0,
"active connection id limit: %ui",
"quic tp active_connection_id_limit: %ui",
tp->active_connection_id_limit);
return NGX_OK;
@ -1569,8 +1591,6 @@ ngx_quic_create_transport_params(u_char *pos, u_char *end, ngx_quic_tp_t *tp)
u_char *p;
size_t len;
/* recent drafts with variable integer transport parameters encoding */
#define ngx_quic_tp_len(id, value) \
ngx_quic_varint_len(id) \
+ ngx_quic_varint_len(value) \
@ -1636,8 +1656,6 @@ ngx_quic_create_transport_params(u_char *pos, u_char *end, ngx_quic_tp_t *tp)
ngx_quic_tp_vint(NGX_QUIC_TP_MAX_IDLE_TIMEOUT,
tp->max_idle_timeout);
ngx_quic_hexdump0(ngx_cycle->log, "transport parameters", pos, p - pos);
return p - pos;
}