Mercurial > hg > nginx-quic
diff src/event/ngx_event_quic.c @ 7836:2f900ae486bc quic
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
author | Vladimir Homutov <vl@nginx.com> |
---|---|
date | Fri, 24 Apr 2020 10:11:47 +0300 |
parents | 42198f77ac85 |
children | f175006124d0 |
line wrap: on
line diff
--- 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 }