# HG changeset patch # User Vladimir Homutov # Date 1587712307 -10800 # Node ID 2f900ae486bce7a032cb0b60a4422bc9036276ea # Parent 2a6e91a1691decc8f31f544ec5bbed5f7c86ccd2 Debug cleanup. + 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 diff --git a/src/event/ngx_event_quic.c b/src/event/ngx_event_quic.c --- a/src/event/ngx_event_quic.c +++ b/src/event/ngx_event_quic.c @@ -251,8 +251,10 @@ 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); +#endif keys = &c->quic->keys[level]; @@ -276,8 +278,10 @@ 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); +#endif keys = &c->quic->keys[level]; @@ -299,7 +303,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); +#endif keys = &c->quic->keys[level]; @@ -315,7 +321,9 @@ ngx_quic_set_encryption_secrets(ngx_ssl_ 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 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 &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 *ss 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_ 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_ 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_ 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_ } 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 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 { 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_ /* 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 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 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_connec 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_connec 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_connec 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_connect /* 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 * 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 * 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 * 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 * "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 * } 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_connect 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 * 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 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 { 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 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 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 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_connectio | 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 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 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 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 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 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 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 *da 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 *da 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 *da 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 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 ++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_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 } diff --git a/src/event/ngx_event_quic.h b/src/event/ngx_event_quic.h --- a/src/event/ngx_event_quic.h +++ b/src/event/ngx_event_quic.h @@ -82,6 +82,12 @@ ngx_connection_t *ngx_quic_create_uni_st /********************************* 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, ...) \ diff --git a/src/event/ngx_event_quic_protection.c b/src/event/ngx_event_quic_protection.c --- a/src/event/ngx_event_quic_protection.c +++ b/src/event/ngx_event_quic_protection.c @@ -156,8 +156,10 @@ ngx_quic_set_initial_secret(ngx_pool_t * .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, c 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_hea 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_hea 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_he 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_he 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, 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, 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_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, 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; } diff --git a/src/event/ngx_event_quic_transport.c b/src/event/ngx_event_quic_transport.c --- a/src/event/ngx_event_quic_transport.c +++ b/src/event/ngx_event_quic_transport.c @@ -234,7 +234,9 @@ ngx_quic_parse_long_header(ngx_quic_head 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_head } 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_hea 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_hea } 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_h } 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_h 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 } 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 * } 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 * 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 * } 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 * } 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 * 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 * } 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 * } 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 * } 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 * } 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 * (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 * 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 * } 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 * } 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 * } 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 * } 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 * } 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 * } 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 } 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 * } 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 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 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; }