nginx: src/event/ngx_event_quic.c comparison

comparison src/event/ngx_event_quic.c @ 8359: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

comparison

equal deleted inserted replaced

-:2a6e91a1691d
+:2f900ae486bc
 ngx_connection_t    *c;
 ngx_quic_secrets_t  *keys;
 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];
 if (level == ssl_encryption_early_data) {
 c->quic->state = NGX_QUIC_ST_EARLY_DATA;
 ngx_connection_t    *c;
 ngx_quic_secrets_t  *keys;
 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];
 return ngx_quic_set_encryption_secret(c->pool, ssl_conn, level,
 wsecret, secret_len,
 ngx_connection_t    *c;
 ngx_quic_secrets_t  *keys;
 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];
 rc = ngx_quic_set_encryption_secret(c->pool, ssl_conn, level,
 rsecret, secret_len,
 if (level == ssl_encryption_early_data) {
 c->quic->state = NGX_QUIC_ST_EARLY_DATA;
 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,
 &keys->server);
 }
 c = ngx_ssl_get_connection((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) {
 SSL_get_peer_quic_transport_params(ssl_conn, &client_params,
 &client_params_len);
 ngx_log_debug1(NGX_LOG_DEBUG_EVENT, c->log, 0,
-"SSL_get_peer_quic_transport_params(): params_len %ui",
+"quic SSL_get_peer_quic_transport_params():"
-client_params_len);
+" params_len %ui", client_params_len);
 if (client_params_len != 0) {
 p = (u_char *) client_params;
 end = p + client_params_len;
 {
 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, "ngx_quic_flush_flight()");
+ngx_log_debug0(NGX_LOG_DEBUG_EVENT, c->log, 0,
+"quic ngx_quic_flush_flight()");
 return 1;
 }
 ngx_connection_t  *c;
 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) {
 return 1;
 }
 len = ngx_quic_create_transport_params(p, p + len, &qc->tp);
 if (len < 0) {
 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");
 return NGX_ERROR;
 }
 qc->max_streams = qc->tp.initial_max_streams_bidi;
 qc->state = NGX_QUIC_ST_HANDSHAKE;
 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",
+ngx_log_debug1(NGX_LOG_DEBUG_EVENT, c->log, 0,
-sslerr);
+"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");
 return NGX_ERROR;
 }
 }
 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));
 return NGX_OK;
 }
 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;
 }
 static void
 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);
 }
 case NGX_QUIC_FT_PATH_RESPONSE:
 case NGX_QUIC_FT_MAX_STREAM_DATA:
 /* 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;
 }
 }
 if (p != end) {
 ngx_quic_send_ctx_t  *ctx;
 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
 *       generate a connection error of type FRAME_ENCODING_ERROR.
 *       (19.3.1)
 /* 13.2.3.  Receiver Tracking of ACK Frames */
 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;
 end = ack->ranges_end;
 f = &frame->u.ord;
 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);
 }
 /* old/duplicate data range */
 ngx_queue_remove(q);
 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;
 }
 /* frame was adjusted, proceed to input */
 fs->total -= full_len;
 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);
 } while (1);
 if (tail >= f->length) {
 /* 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 */
 f->offset += tail;
 f->data += tail;
 u_char                    *data;
 ngx_queue_t               *q;
 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;
 /* frame start offset is in the future, buffer it */
 df->data = dst->data;
 fs->total += f->length;
 ngx_log_debug1(NGX_LOG_DEBUG_EVENT, c->log, 0,
-"ordered frame with unexpected offset: buffered, total %ui",
+"quic ordered frame with unexpected offset:"
-fs->total);
+" buffered, total %ui", fs->total);
 /* TODO: do we need some timeout for this queue ?  */
 if (ngx_queue_empty(&fs->frames)) {
 ngx_queue_insert_after(&fs->frames, &dst->queue);
 f = &frame->u.crypto;
 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));
 if (!SSL_provide_quic_data(ssl_conn, SSL_quic_read_level(ssl_conn),
 f->data, f->length))
 ngx_log_debug1(NGX_LOG_DEBUG_EVENT, c->log, 0,
 "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) {
 return NGX_ERROR;
 }
 return NGX_ERROR;
 }
 }
 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));
 return NGX_OK;
 }
 f = &frame->u.stream;
 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
 : qc->tp.initial_max_stream_data_bidi_remote;
 // TODO: possible?
 // stream was deleted while in reordering queue ?
 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;
 if ((size_t) ((b->pos - b->start) + (b->end - b->last)) < f->length) {
 ngx_log_error(NGX_LOG_INFO, c->log, 0, "no space in stream buffer");
 ngx_quic_connection_t  *qc;
 static ngx_str_t        initial_token = ngx_null_string;
 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);
 ctx = ngx_quic_get_send_ctx(c->quic, start->level);
 q != ngx_queue_sentinel(frames);
 q = ngx_queue_next(q))
 {
 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) {
 return NGX_ERROR;
 }
 while (out.len < 4) {
 *p++ = NGX_QUIC_FT_PADDING;
 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];
 pkt.secret = &keys->server;
 pkt.scid = qc->dcid;
 pkt.payload = out;
 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) {
 return NGX_ERROR;
 }
 ngx_msec_t              wait, nswait;
 ngx_connection_t       *c;
 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;
 wait = 0;
 static void
 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;
 if (ngx_quic_output(c) != NGX_OK) {
 ngx_quic_close_connection(c, NGX_ERROR);
 id = (qc->streams.id_counter << 2)
 | NGX_QUIC_STREAM_SERVER_INITIATED
 | 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++;
 sn = ngx_quic_create_stream(qs->parent, id, 0);
 b = qs->b;
 pc = qs->parent;
 qc = pc->quic;
 rev = c->read;
-ngx_log_debug2(NGX_LOG_DEBUG_EVENT, c->log, 0,
+ngx_log_debug3(NGX_LOG_DEBUG_EVENT, c->log, 0,
-"quic recv: eof:%d, avail:%z",
+"quic stream id 0x%xi recv: eof:%d, avail:%z",
-rev->pending_eof, b->last - b->pos);
+qs->id, rev->pending_eof, b->last - b->pos);
 if (b->pos == b->last) {
 rev->ready = 0;
 if (rev->pending_eof) {
 rev->eof = 1;
 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;
 }
 len = ngx_min(b->last - b->pos, (ssize_t) size);
 b->pos = b->start;
 b->last = b->start;
 rev->ready = rev->pending_eof;
 }
-ngx_log_debug2(NGX_LOG_DEBUG_EVENT, c->log, 0,
+ngx_log_debug3(NGX_LOG_DEBUG_EVENT, c->log, 0,
-"quic recv: %z of %uz", len, size);
+"quic stream id 0x%xi recv: %z of %uz", qs->id, len, size);
 if (!rev->pending_eof) {
 frame = ngx_quic_alloc_frame(pc, 0);
 if (frame == NULL) {
 return NGX_ERROR;
 ngx_sprintf(frame->info, "MAX_DATA max_data:%d level=%d on recv",
 (int) frame->u.max_data.max_data, frame->level);
 ngx_quic_queue_frame(pc->quic, frame);
-ngx_log_debug1(NGX_LOG_DEBUG_EVENT, c->log, 0,
+ngx_log_debug2(NGX_LOG_DEBUG_EVENT, c->log, 0,
-"quic recv: increased max data: %ui",
+"quic stream id 0x%xi recv: increased max data: %ui",
-qc->streams.max_data);
+qs->id, qc->streams.max_data);
 }
 return len;
 }
 if (qc->closing) {
 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;
 * 25 = 1 + 8x3 is max header for STREAM frame, with 1 byte for frame type
 */
 frame->u.stream.data = frame->data;
 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);
 }
 qs = c->qs;
 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);
 if (qc->closing) {
 if ((qs->id & 0x03) == NGX_QUIC_STREAM_UNIDIRECTIONAL) {
 /* do not send fin for client unidirectional streams */
 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) {
 return;
 }
 frame->u.stream.stream_id = qs->id;
 frame->u.stream.offset = c->sent;
 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);
 (void) ngx_quic_output(pc);
 }
 q = ngx_queue_head(&qc->free_frames);
 frame = ngx_queue_data(q, ngx_quic_frame_t, queue);
 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));
 if (frame == NULL) {
 ngx_free(p);
 #if (NGX_DEBUG)
 ++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));
 frame->data = p;
 ngx_free(frame->data);
 }
 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
+}

Mercurial > hg > nginx

comparison src/event/ngx_event_quic.c @ 8359:2f900ae486bc quic