2 * Copyright 2023 The OpenSSL Project Authors. All Rights Reserved.
4 * Licensed under the Apache License 2.0 (the "License"). You may not use
5 * this file except in compliance with the License. You can obtain a copy
6 * in the file LICENSE in the source distribution or at
7 * https://www.openssl.org/source/license.html
10 #include "internal/qlog_event_helpers.h"
11 #include "internal/common.h"
12 #include "internal/packet.h"
13 #include "internal/quic_channel.h"
14 #include "internal/quic_error.h"
16 void ossl_qlog_event_connectivity_connection_started(QLOG *qlog,
17 const QUIC_CONN_ID *init_dcid)
19 #ifndef OPENSSL_NO_QLOG
20 QLOG_EVENT_BEGIN(qlog, connectivity, connection_started)
21 QLOG_STR("protocol", "quic");
22 QLOG_CID("dst_cid", init_dcid);
27 #ifndef OPENSSL_NO_QLOG
28 static const char *map_state_to_qlog(uint32_t state,
29 int handshake_complete,
30 int handshake_confirmed)
34 case QUIC_CHANNEL_STATE_IDLE:
37 case QUIC_CHANNEL_STATE_ACTIVE:
38 if (handshake_confirmed)
39 return "handshake_confirmed";
40 else if (handshake_complete)
41 return "handshake_complete";
45 case QUIC_CHANNEL_STATE_TERMINATING_CLOSING:
48 case QUIC_CHANNEL_STATE_TERMINATING_DRAINING:
51 case QUIC_CHANNEL_STATE_TERMINATED:
57 void ossl_qlog_event_connectivity_connection_state_updated(QLOG *qlog,
60 int handshake_complete,
61 int handshake_confirmed)
63 #ifndef OPENSSL_NO_QLOG
66 QLOG_EVENT_BEGIN(qlog, connectivity, connection_state_updated)
67 state_s = map_state_to_qlog(new_state,
72 QLOG_STR("state", state_s);
77 #ifndef OPENSSL_NO_QLOG
78 static const char *quic_err_to_qlog(uint64_t error_code)
81 case QUIC_ERR_INTERNAL_ERROR:
82 return "internal_error";
83 case QUIC_ERR_CONNECTION_REFUSED:
84 return "connection_refused";
85 case QUIC_ERR_FLOW_CONTROL_ERROR:
86 return "flow_control_error";
87 case QUIC_ERR_STREAM_LIMIT_ERROR:
88 return "stream_limit_error";
89 case QUIC_ERR_STREAM_STATE_ERROR:
90 return "stream_state_error";
91 case QUIC_ERR_FINAL_SIZE_ERROR:
92 return "final_size_error";
93 case QUIC_ERR_FRAME_ENCODING_ERROR:
94 return "frame_encoding_error";
95 case QUIC_ERR_TRANSPORT_PARAMETER_ERROR:
96 return "transport_parameter_error";
97 case QUIC_ERR_CONNECTION_ID_LIMIT_ERROR:
98 return "connection_id_limit_error";
99 case QUIC_ERR_PROTOCOL_VIOLATION:
100 return "protocol_violation";
101 case QUIC_ERR_INVALID_TOKEN:
102 return "invalid_token";
103 case QUIC_ERR_APPLICATION_ERROR:
104 return "application_error";
105 case QUIC_ERR_CRYPTO_BUFFER_EXCEEDED:
106 return "crypto_buffer_exceeded";
107 case QUIC_ERR_KEY_UPDATE_ERROR:
108 return "key_update_error";
109 case QUIC_ERR_AEAD_LIMIT_REACHED:
110 return "aead_limit_reached";
111 case QUIC_ERR_NO_VIABLE_PATH:
112 return "no_viable_path";
119 void ossl_qlog_event_connectivity_connection_closed(QLOG *qlog,
120 const QUIC_TERMINATE_CAUSE *tcause)
122 #ifndef OPENSSL_NO_QLOG
123 QLOG_EVENT_BEGIN(qlog, connectivity, connection_closed)
124 QLOG_STR("owner", tcause->remote ? "remote" : "local");
126 QLOG_U64("application_code", tcause->error_code);
128 const char *m = quic_err_to_qlog(tcause->error_code);
131 if (tcause->error_code >= QUIC_ERR_CRYPTO_ERR_BEGIN
132 && tcause->error_code <= QUIC_ERR_CRYPTO_ERR_END) {
133 snprintf(ce, sizeof(ce), "crypto_error_0x%03llx",
134 (unsigned long long)tcause->error_code);
137 /* TODO(QLOG): Consider adding ERR information in the output. */
140 QLOG_STR("connection_code", m);
142 QLOG_U64("connection_code", tcause->error_code);
145 QLOG_STR_LEN("reason", tcause->reason, tcause->reason_len);
150 #ifndef OPENSSL_NO_QLOG
151 static const char *quic_pkt_type_to_qlog(uint32_t pkt_type)
154 case QUIC_PKT_TYPE_INITIAL:
156 case QUIC_PKT_TYPE_HANDSHAKE:
158 case QUIC_PKT_TYPE_0RTT:
160 case QUIC_PKT_TYPE_1RTT:
162 case QUIC_PKT_TYPE_VERSION_NEG:
163 return "version_negotiation";
164 case QUIC_PKT_TYPE_RETRY:
172 void ossl_qlog_event_recovery_packet_lost(QLOG *qlog,
173 const QUIC_TXPIM_PKT *tpkt)
175 #ifndef OPENSSL_NO_QLOG
176 QLOG_EVENT_BEGIN(qlog, recovery, packet_lost)
178 QLOG_STR("packet_type", quic_pkt_type_to_qlog(tpkt->pkt_type));
179 if (ossl_quic_pkt_type_has_pn(tpkt->pkt_type))
180 QLOG_U64("packet_number", tpkt->ackm_pkt.pkt_num);
186 #ifndef OPENSSL_NO_QLOG
187 # define MAX_ACK_RANGES 32
189 static void ignore_res(int x) {}
192 * For logging received packets, we need to parse all the frames in the packet
193 * to log them. We should do this separately to the RXDP code because we want to
194 * log the packet and its contents before we start to actually process it in
195 * case it causes an error. We also in general don't want to do other
196 * non-logging related work in the middle of an event logging transaction.
197 * Reparsing packet data allows us to meet these needs while avoiding the need
198 * to keep around bookkeeping data on what frames were in a packet, etc.
200 * For logging transmitted packets, we actually reuse the same code and reparse
201 * the outgoing packet's payload. This again has the advantage that we only log
202 * a packet when it is actually queued for transmission (and not if something
203 * goes wrong before then) while avoiding the need to keep around bookkeeping
204 * data on what frames it contained.
206 static int log_frame_actual(QLOG *qlog_instance, PACKET *pkt,
210 OSSL_QUIC_FRAME_ACK ack;
211 OSSL_QUIC_ACK_RANGE ack_ranges[MAX_ACK_RANGES];
212 uint64_t num_ranges, total_ranges;
214 PACKET orig_pkt = *pkt;
216 if (!ossl_quic_wire_peek_frame_header(pkt, &frame_type, NULL))
220 * If something goes wrong decoding a frame we cannot log it as that frame
221 * as we need to know how to decode it in order to be able to do so, but in
222 * that case we log it as an unknown frame to assist with diagnosis.
224 switch (frame_type) {
225 case OSSL_QUIC_FRAME_TYPE_PADDING:
226 QLOG_STR("frame_type", "padding");
227 QLOG_U64("payload_length",
228 ossl_quic_wire_decode_padding(pkt));
230 case OSSL_QUIC_FRAME_TYPE_PING:
231 if (!ossl_quic_wire_decode_frame_ping(pkt))
234 QLOG_STR("frame_type", "ping");
236 case OSSL_QUIC_FRAME_TYPE_ACK_WITHOUT_ECN:
237 case OSSL_QUIC_FRAME_TYPE_ACK_WITH_ECN:
238 if (!ossl_quic_wire_peek_frame_ack_num_ranges(pkt, &num_ranges))
241 ack.ack_ranges = ack_ranges;
242 ack.num_ack_ranges = OSSL_NELEM(ack_ranges);
243 if (!ossl_quic_wire_decode_frame_ack(pkt, 3, &ack, &total_ranges))
246 QLOG_STR("frame_type", "ack");
247 QLOG_U64("ack_delay", ossl_time2ms(ack.delay_time));
248 if (ack.ecn_present) {
249 QLOG_U64("ect1", ack.ect0);
250 QLOG_U64("ect0", ack.ect1);
251 QLOG_U64("ce", ack.ecnce);
253 QLOG_BEGIN_ARRAY("acked_ranges");
254 for (i = 0; i < ack.num_ack_ranges; ++i) {
255 QLOG_BEGIN_ARRAY(NULL)
256 QLOG_U64(NULL, ack.ack_ranges[i].start);
257 if (ack.ack_ranges[i].end != ack.ack_ranges[i].start)
258 QLOG_U64(NULL, ack.ack_ranges[i].end);
263 case OSSL_QUIC_FRAME_TYPE_RESET_STREAM:
265 OSSL_QUIC_FRAME_RESET_STREAM f;
267 if (!ossl_quic_wire_decode_frame_reset_stream(pkt, &f))
270 QLOG_STR("frame_type", "reset_stream");
271 QLOG_U64("stream_id", f.stream_id);
272 QLOG_U64("error_code", f.app_error_code);
273 QLOG_U64("final_size", f.final_size);
276 case OSSL_QUIC_FRAME_TYPE_STOP_SENDING:
278 OSSL_QUIC_FRAME_STOP_SENDING f;
280 if (!ossl_quic_wire_decode_frame_stop_sending(pkt, &f))
283 QLOG_STR("frame_type", "stop_sending");
284 QLOG_U64("stream_id", f.stream_id);
285 QLOG_U64("error_code", f.app_error_code);
288 case OSSL_QUIC_FRAME_TYPE_CRYPTO:
290 OSSL_QUIC_FRAME_CRYPTO f;
292 if (!ossl_quic_wire_decode_frame_crypto(pkt, 1, &f))
295 QLOG_STR("frame_type", "crypto");
296 QLOG_U64("offset", f.offset);
297 QLOG_U64("payload_length", f.len);
301 case OSSL_QUIC_FRAME_TYPE_STREAM:
302 case OSSL_QUIC_FRAME_TYPE_STREAM_FIN:
303 case OSSL_QUIC_FRAME_TYPE_STREAM_LEN:
304 case OSSL_QUIC_FRAME_TYPE_STREAM_LEN_FIN:
305 case OSSL_QUIC_FRAME_TYPE_STREAM_OFF:
306 case OSSL_QUIC_FRAME_TYPE_STREAM_OFF_FIN:
307 case OSSL_QUIC_FRAME_TYPE_STREAM_OFF_LEN:
308 case OSSL_QUIC_FRAME_TYPE_STREAM_OFF_LEN_FIN:
310 OSSL_QUIC_FRAME_STREAM f;
312 if (!ossl_quic_wire_decode_frame_stream(pkt, 1, &f))
315 QLOG_STR("frame_type", "stream");
316 QLOG_U64("stream_id", f.stream_id);
317 QLOG_U64("offset", f.offset);
318 QLOG_U64("payload_length", f.len);
319 QLOG_BOOL("explicit_length", f.has_explicit_len);
322 *need_skip = f.has_explicit_len ? *need_skip + f.len : UINT64_MAX;
325 case OSSL_QUIC_FRAME_TYPE_MAX_DATA:
329 if (!ossl_quic_wire_decode_frame_max_data(pkt, &x))
332 QLOG_STR("frame_type", "max_data");
333 QLOG_U64("maximum", x);
336 case OSSL_QUIC_FRAME_TYPE_MAX_STREAMS_BIDI:
337 case OSSL_QUIC_FRAME_TYPE_MAX_STREAMS_UNI:
341 if (!ossl_quic_wire_decode_frame_max_streams(pkt, &x))
344 QLOG_STR("frame_type", "max_streams");
345 QLOG_STR("stream_type",
346 frame_type == OSSL_QUIC_FRAME_TYPE_MAX_STREAMS_BIDI
347 ? "bidirectional" : "unidirectional");
348 QLOG_U64("maximum", x);
351 case OSSL_QUIC_FRAME_TYPE_MAX_STREAM_DATA:
353 uint64_t stream_id, max_data;
355 if (!ossl_quic_wire_decode_frame_max_stream_data(pkt, &stream_id,
359 QLOG_STR("frame_type", "max_stream_data");
360 QLOG_U64("stream_id", stream_id);
361 QLOG_U64("maximum", max_data);
364 case OSSL_QUIC_FRAME_TYPE_PATH_CHALLENGE:
368 if (!ossl_quic_wire_decode_frame_path_challenge(pkt, &challenge))
371 QLOG_STR("frame_type", "path_challenge");
374 case OSSL_QUIC_FRAME_TYPE_PATH_RESPONSE:
378 if (!ossl_quic_wire_decode_frame_path_response(pkt, &challenge))
381 QLOG_STR("frame_type", "path_response");
384 case OSSL_QUIC_FRAME_TYPE_CONN_CLOSE_APP:
385 case OSSL_QUIC_FRAME_TYPE_CONN_CLOSE_TRANSPORT:
387 OSSL_QUIC_FRAME_CONN_CLOSE f;
389 if (!ossl_quic_wire_decode_frame_conn_close(pkt, &f))
392 QLOG_STR("frame_type", "connection_close");
393 QLOG_STR("error_space", f.is_app ? "application" : "transport");
394 QLOG_U64("error_code_value", f.error_code);
396 QLOG_U64("error_code", f.error_code);
397 if (!f.is_app && f.frame_type != 0)
398 QLOG_U64("trigger_frame_type", f.frame_type);
399 QLOG_STR_LEN("reason", f.reason, f.reason_len);
402 case OSSL_QUIC_FRAME_TYPE_HANDSHAKE_DONE:
404 if (!ossl_quic_wire_decode_frame_handshake_done(pkt))
407 QLOG_STR("frame_type", "handshake_done");
410 case OSSL_QUIC_FRAME_TYPE_NEW_CONN_ID:
412 OSSL_QUIC_FRAME_NEW_CONN_ID f;
414 if (!ossl_quic_wire_decode_frame_new_conn_id(pkt, &f))
417 QLOG_STR("frame_type", "new_connection_id");
418 QLOG_U64("sequence_number", f.seq_num);
419 QLOG_U64("retire_prior_to", f.retire_prior_to);
420 QLOG_CID("connection_id", &f.conn_id);
421 QLOG_BIN("stateless_reset_token",
422 f.stateless_reset.token,
423 sizeof(f.stateless_reset.token));
426 case OSSL_QUIC_FRAME_TYPE_RETIRE_CONN_ID:
430 if (!ossl_quic_wire_decode_frame_retire_conn_id(pkt, &seq_num))
433 QLOG_STR("frame_type", "retire_connection_id");
434 QLOG_U64("sequence_number", seq_num);
437 case OSSL_QUIC_FRAME_TYPE_DATA_BLOCKED:
441 if (!ossl_quic_wire_decode_frame_data_blocked(pkt, &x))
444 QLOG_STR("frame_type", "data_blocked");
445 QLOG_U64("limit", x);
448 case OSSL_QUIC_FRAME_TYPE_STREAM_DATA_BLOCKED:
450 uint64_t stream_id, x;
452 if (!ossl_quic_wire_decode_frame_stream_data_blocked(pkt,
457 QLOG_STR("frame_type", "stream_data_blocked");
458 QLOG_U64("stream_id", stream_id);
459 QLOG_U64("limit", x);
462 case OSSL_QUIC_FRAME_TYPE_STREAMS_BLOCKED_BIDI:
463 case OSSL_QUIC_FRAME_TYPE_STREAMS_BLOCKED_UNI:
467 if (!ossl_quic_wire_decode_frame_streams_blocked(pkt, &x))
470 QLOG_STR("frame_type", "streams_blocked");
471 QLOG_STR("stream_type",
472 frame_type == OSSL_QUIC_FRAME_TYPE_STREAMS_BLOCKED_BIDI
473 ? "bidirectional" : "unidirectional");
474 QLOG_U64("limit", x);
477 case OSSL_QUIC_FRAME_TYPE_NEW_TOKEN:
479 const unsigned char *token;
482 if (!ossl_quic_wire_decode_frame_new_token(pkt, &token, &token_len))
485 QLOG_STR("frame_type", "new_token");
488 QLOG_BIN("data", token, token_len);
495 QLOG_STR("frame_type", "unknown");
496 QLOG_U64("frame_type_value", frame_type);
499 * Can't continue scanning for frames in this case as the frame length
500 * is unknown. We log the entire body the rest of the packet payload
501 * as the raw data of the frame.
504 QLOG_BIN("data", PACKET_data(&orig_pkt),
505 PACKET_remaining(&orig_pkt));
507 ignore_res(PACKET_forward(pkt, PACKET_remaining(pkt)));
514 static void log_frame(QLOG *qlog_instance, PACKET *pkt,
517 size_t rem_before, rem_after;
519 rem_before = PACKET_remaining(pkt);
521 if (!log_frame_actual(qlog_instance, pkt, need_skip))
524 rem_after = PACKET_remaining(pkt);
525 QLOG_U64("length", rem_before - rem_after);
528 static int log_frames(QLOG *qlog_instance,
529 const OSSL_QTX_IOVEC *iovec,
534 uint64_t need_skip = 0;
536 for (i = 0; i < num_iovec; ++i) {
537 if (!PACKET_buf_init(&pkt, iovec[i].buf, iovec[i].buf_len))
540 while (PACKET_remaining(&pkt) > 0) {
542 size_t adv = need_skip;
544 if (adv < PACKET_remaining(&pkt))
545 adv = PACKET_remaining(&pkt);
547 if (!PACKET_forward(&pkt, adv))
556 log_frame(qlog_instance, &pkt, &need_skip);
565 static void log_packet(QLOG *qlog_instance,
566 const QUIC_PKT_HDR *hdr,
568 const OSSL_QTX_IOVEC *iovec,
570 uint64_t datagram_id)
575 type_s = quic_pkt_type_to_qlog(hdr->type);
579 QLOG_STR("packet_type", type_s);
580 if (ossl_quic_pkt_type_has_pn(hdr->type))
581 QLOG_U64("packet_number", pn);
583 QLOG_CID("dcid", &hdr->dst_conn_id);
584 if (ossl_quic_pkt_type_has_scid(hdr->type))
585 QLOG_CID("scid", &hdr->src_conn_id);
587 if (hdr->token_len > 0) {
590 QLOG_BIN("data", hdr->token, hdr->token_len);
594 /* TODO(QLOG): flags, length */
596 QLOG_U64("datagram_id", datagram_id);
598 if (ossl_quic_pkt_type_is_encrypted(hdr->type)) {
599 QLOG_BEGIN_ARRAY("frames")
600 log_frames(qlog_instance, iovec, num_iovec);
607 void ossl_qlog_event_transport_packet_sent(QLOG *qlog,
608 const QUIC_PKT_HDR *hdr,
610 const OSSL_QTX_IOVEC *iovec,
612 uint64_t datagram_id)
614 #ifndef OPENSSL_NO_QLOG
615 QLOG_EVENT_BEGIN(qlog, transport, packet_sent)
616 log_packet(qlog, hdr, pn, iovec, num_iovec, datagram_id);
621 void ossl_qlog_event_transport_packet_received(QLOG *qlog,
622 const QUIC_PKT_HDR *hdr,
624 const OSSL_QTX_IOVEC *iovec,
626 uint64_t datagram_id)
628 #ifndef OPENSSL_NO_QLOG
629 QLOG_EVENT_BEGIN(qlog, transport, packet_received)
630 log_packet(qlog, hdr, pn, iovec, num_iovec, datagram_id);