nginx: src/event/ngx_event_quic_transport.c comparison

comparison src/event/ngx_event_quic_transport.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	2a6e91a1691d
children	f175006124d0

comparison

equal deleted inserted replaced

-:2a6e91a1691d
+:2f900ae486bc
 uint8_t  idlen;
 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) {
 ngx_log_error(NGX_LOG_INFO, pkt->log, 0,
 "packet is too small to read flags");
 "packet is too small to read version");
 return NGX_ERROR;
 }
 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,
 "unsupported quic version: 0x%xi", pkt->version);
 return NGX_ERROR;
 u_char  *p, *end;
 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) {
 ngx_log_error(NGX_LOG_INFO, pkt->log, 0,
 "packet is too small to read flags");
 ngx_log_error(NGX_LOG_INFO, pkt->log, 0, "not a short packet");
 return NGX_ERROR;
 }
 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");
 return NGX_ERROR;
 }
 ngx_log_error(NGX_LOG_INFO, pkt->log, 0, "bad packet length");
 return NGX_ERROR;
 }
 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");
 return NGX_ERROR;
 }
 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;
 }
 ngx_log_error(NGX_LOG_INFO, pkt->log, 0, "bad packet length");
 return NGX_ERROR;
 }
 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");
 return NGX_ERROR;
 }
 "failed to parse crypto frame data");
 return NGX_ERROR;
 }
 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:
 /* allowed in any packet type */
 }
 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}",
+"quic frame in ACK largest:%ui delay:%ui"
-f->u.ack.largest,
+" count:%ui first:%ui", f->u.ack.largest,
 f->u.ack.delay,
 f->u.ack.range_count,
 f->u.ack.first_range);
 if (f->type == NGX_QUIC_FT_ACK_ECN) {
 "failed to parse ack frame ECT counts", i);
 return NGX_ERROR;
 }
 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);
 }
 break;
 "failed to parse new connection id srt");
 return NGX_ERROR;
 }
 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;
 case NGX_QUIC_FT_CONNECTION_CLOSE2:
 }
 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);
 }
 break;
 "offset=%ui", f->u.stream.length, f->u.stream.offset);
 return NGX_ERROR;
 }
 ngx_log_debug7(NGX_LOG_DEBUG_EVENT, pkt->log, 0,
-"STREAM frame { 0x%xi id 0x%xi offset 0x%xi "
+"quic frame in: STREAM type:0x%xi id:0x%xi offset:0x%xi "
-"len 0x%xi bits:off=%d len=%d fin=%d }",
+"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:
 if (!(ngx_quic_short_pkt(flags) || ngx_quic_pkt_zrtt(flags))) {
 "failed to parse max data frame");
 return NGX_ERROR;
 }
 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;
 case NGX_QUIC_FT_RESET_STREAM:
 "failed to parse reset stream frame");
 return NGX_ERROR;
 }
 ngx_log_debug3(NGX_LOG_DEBUG_EVENT, pkt->log, 0,
-"RESET STREAM frame"
+"quic frame in: RESET_STREAM"
-" { id 0x%xi error_code 0x%xi final_size 0x%xi }",
+" 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;
 case NGX_QUIC_FT_STOP_SENDING:
 "failed to parse stop sending frame error code");
 return NGX_ERROR;
 }
 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;
 case NGX_QUIC_FT_STREAMS_BLOCKED:
 f->u.streams_blocked.bidi =
 (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);
 break;
 }
 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;
 case NGX_QUIC_FT_MAX_STREAM_DATA:
 "failed to parse max stream data frame data limit");
 return NGX_ERROR;
 }
 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;
 case NGX_QUIC_FT_DATA_BLOCKED:
 "failed to parse data blocked frame limit");
 return NGX_ERROR;
 }
 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;
 case NGX_QUIC_FT_STREAM_DATA_BLOCKED:
 "failed to parse tream data blocked frame limit");
 return NGX_ERROR;
 }
 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;
 case NGX_QUIC_FT_RETIRE_CONNECTION_ID:
 " frame sequence number");
 return NGX_ERROR;
 }
 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;
 case NGX_QUIC_FT_PATH_CHALLENGE:
 "failed to get path challenge frame data");
 return NGX_ERROR;
 }
 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:
 if (!(ngx_quic_short_pkt(flags) || ngx_quic_pkt_zrtt(flags))) {
 "failed to get path response frame data");
 return NGX_ERROR;
 }
 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:
 ngx_log_error(NGX_LOG_INFO, pkt->log, 0,
 "unknown frame type 0x%xi in packet", f->type);
 "failed to parse ack frame range");
 return NGX_ERROR;
 }
 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;
 }
 end - p);
 return NGX_ERROR;
 }
 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;
 }
 ssize_t
 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)                                              \
 + ngx_quic_varint_len(ngx_quic_varint_len(value))
 tp->initial_max_stream_data_uni);
 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;
 }
 static size_t

Mercurial > hg > nginx

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