1 /* 2 * Copyright 2023-2025 The OpenSSL Project Authors. All Rights Reserved. 3 * 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 8 */ 9 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" 15 16 void ossl_qlog_event_connectivity_connection_started(QLOG *qlog, 17 const QUIC_CONN_ID *init_dcid) 18 { 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); 23 QLOG_EVENT_END() 24 #endif 25 } 26 27 #ifndef OPENSSL_NO_QLOG 28 static const char *map_state_to_qlog(uint32_t state, 29 int handshake_complete, 30 int handshake_confirmed) 31 { 32 switch (state) { 33 default: 34 case QUIC_CHANNEL_STATE_IDLE: 35 return NULL; 36 37 case QUIC_CHANNEL_STATE_ACTIVE: 38 if (handshake_confirmed) 39 return "handshake_confirmed"; 40 else if (handshake_complete) 41 return "handshake_complete"; 42 else 43 return "attempted"; 44 45 case QUIC_CHANNEL_STATE_TERMINATING_CLOSING: 46 return "closing"; 47 48 case QUIC_CHANNEL_STATE_TERMINATING_DRAINING: 49 return "draining"; 50 51 case QUIC_CHANNEL_STATE_TERMINATED: 52 return "closed"; 53 } 54 } 55 #endif 56 57 void ossl_qlog_event_connectivity_connection_state_updated(QLOG *qlog, 58 uint32_t old_state, 59 uint32_t new_state, 60 int handshake_complete, 61 int handshake_confirmed) 62 { 63 #ifndef OPENSSL_NO_QLOG 64 const char *state_s; 65 66 QLOG_EVENT_BEGIN(qlog, connectivity, connection_state_updated) 67 state_s = map_state_to_qlog(new_state, 68 handshake_complete, 69 handshake_confirmed); 70 71 if (state_s != NULL) 72 QLOG_STR("state", state_s); 73 QLOG_EVENT_END() 74 #endif 75 } 76 77 #ifndef OPENSSL_NO_QLOG 78 static const char *quic_err_to_qlog(uint64_t error_code) 79 { 80 switch (error_code) { 81 case OSSL_QUIC_ERR_INTERNAL_ERROR: 82 return "internal_error"; 83 case OSSL_QUIC_ERR_CONNECTION_REFUSED: 84 return "connection_refused"; 85 case OSSL_QUIC_ERR_FLOW_CONTROL_ERROR: 86 return "flow_control_error"; 87 case OSSL_QUIC_ERR_STREAM_LIMIT_ERROR: 88 return "stream_limit_error"; 89 case OSSL_QUIC_ERR_STREAM_STATE_ERROR: 90 return "stream_state_error"; 91 case OSSL_QUIC_ERR_FINAL_SIZE_ERROR: 92 return "final_size_error"; 93 case OSSL_QUIC_ERR_FRAME_ENCODING_ERROR: 94 return "frame_encoding_error"; 95 case OSSL_QUIC_ERR_TRANSPORT_PARAMETER_ERROR: 96 return "transport_parameter_error"; 97 case OSSL_QUIC_ERR_CONNECTION_ID_LIMIT_ERROR: 98 return "connection_id_limit_error"; 99 case OSSL_QUIC_ERR_PROTOCOL_VIOLATION: 100 return "protocol_violation"; 101 case OSSL_QUIC_ERR_INVALID_TOKEN: 102 return "invalid_token"; 103 case OSSL_QUIC_ERR_APPLICATION_ERROR: 104 return "application_error"; 105 case OSSL_QUIC_ERR_CRYPTO_BUFFER_EXCEEDED: 106 return "crypto_buffer_exceeded"; 107 case OSSL_QUIC_ERR_KEY_UPDATE_ERROR: 108 return "key_update_error"; 109 case OSSL_QUIC_ERR_AEAD_LIMIT_REACHED: 110 return "aead_limit_reached"; 111 case OSSL_QUIC_ERR_NO_VIABLE_PATH: 112 return "no_viable_path"; 113 default: 114 return NULL; 115 } 116 } 117 #endif 118 119 void ossl_qlog_event_connectivity_connection_closed(QLOG *qlog, 120 const QUIC_TERMINATE_CAUSE *tcause) 121 { 122 #ifndef OPENSSL_NO_QLOG 123 QLOG_EVENT_BEGIN(qlog, connectivity, connection_closed) 124 QLOG_STR("owner", tcause->remote ? "remote" : "local"); 125 if (tcause->app) { 126 QLOG_U64("application_code", tcause->error_code); 127 } else { 128 const char *m = quic_err_to_qlog(tcause->error_code); 129 char ce[32]; 130 131 if (tcause->error_code >= OSSL_QUIC_ERR_CRYPTO_ERR_BEGIN 132 && tcause->error_code <= OSSL_QUIC_ERR_CRYPTO_ERR_END) { 133 BIO_snprintf(ce, sizeof(ce), "crypto_error_0x%03llx", 134 (unsigned long long)tcause->error_code); 135 m = ce; 136 } 137 /* TODO(QLOG FUTURE): Consider adding ERR information in the output. */ 138 139 if (m != NULL) 140 QLOG_STR("connection_code", m); 141 else 142 QLOG_U64("connection_code", tcause->error_code); 143 } 144 145 QLOG_STR_LEN("reason", tcause->reason, tcause->reason_len); 146 QLOG_EVENT_END() 147 #endif 148 } 149 150 #ifndef OPENSSL_NO_QLOG 151 static const char *quic_pkt_type_to_qlog(uint32_t pkt_type) 152 { 153 switch (pkt_type) { 154 case QUIC_PKT_TYPE_INITIAL: 155 return "initial"; 156 case QUIC_PKT_TYPE_HANDSHAKE: 157 return "handshake"; 158 case QUIC_PKT_TYPE_0RTT: 159 return "0RTT"; 160 case QUIC_PKT_TYPE_1RTT: 161 return "1RTT"; 162 case QUIC_PKT_TYPE_VERSION_NEG: 163 return "version_negotiation"; 164 case QUIC_PKT_TYPE_RETRY: 165 return "retry"; 166 default: 167 return "unknown"; 168 } 169 } 170 #endif 171 172 void ossl_qlog_event_recovery_packet_lost(QLOG *qlog, 173 const QUIC_TXPIM_PKT *tpkt) 174 { 175 #ifndef OPENSSL_NO_QLOG 176 QLOG_EVENT_BEGIN(qlog, recovery, packet_lost) 177 QLOG_BEGIN("header") 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); 181 QLOG_END() 182 QLOG_EVENT_END() 183 #endif 184 } 185 186 #ifndef OPENSSL_NO_QLOG 187 #define MAX_ACK_RANGES 32 188 189 static void ignore_res(int x) { } 190 191 /* 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. 199 * 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. 205 */ 206 static int log_frame_actual(QLOG *qlog_instance, PACKET *pkt, 207 size_t *need_skip) 208 { 209 uint64_t frame_type; 210 OSSL_QUIC_FRAME_ACK ack; 211 OSSL_QUIC_ACK_RANGE ack_ranges[MAX_ACK_RANGES]; 212 uint64_t num_ranges, total_ranges; 213 size_t i; 214 PACKET orig_pkt = *pkt; 215 216 if (!ossl_quic_wire_peek_frame_header(pkt, &frame_type, NULL)) { 217 *need_skip = SIZE_MAX; 218 return 0; 219 } 220 221 /* 222 * If something goes wrong decoding a frame we cannot log it as that frame 223 * as we need to know how to decode it in order to be able to do so, but in 224 * that case we log it as an unknown frame to assist with diagnosis. 225 */ 226 switch (frame_type) { 227 case OSSL_QUIC_FRAME_TYPE_PADDING: 228 QLOG_STR("frame_type", "padding"); 229 QLOG_U64("payload_length", 230 ossl_quic_wire_decode_padding(pkt)); 231 break; 232 case OSSL_QUIC_FRAME_TYPE_PING: 233 if (!ossl_quic_wire_decode_frame_ping(pkt)) 234 goto unknown; 235 236 QLOG_STR("frame_type", "ping"); 237 break; 238 case OSSL_QUIC_FRAME_TYPE_ACK_WITHOUT_ECN: 239 case OSSL_QUIC_FRAME_TYPE_ACK_WITH_ECN: 240 if (!ossl_quic_wire_peek_frame_ack_num_ranges(pkt, &num_ranges)) 241 goto unknown; 242 243 ack.ack_ranges = ack_ranges; 244 ack.num_ack_ranges = OSSL_NELEM(ack_ranges); 245 if (!ossl_quic_wire_decode_frame_ack(pkt, 3, &ack, &total_ranges)) 246 goto unknown; 247 248 QLOG_STR("frame_type", "ack"); 249 QLOG_U64("ack_delay", ossl_time2ms(ack.delay_time)); 250 if (ack.ecn_present) { 251 QLOG_U64("ect1", ack.ect0); 252 QLOG_U64("ect0", ack.ect1); 253 QLOG_U64("ce", ack.ecnce); 254 } 255 QLOG_BEGIN_ARRAY("acked_ranges"); 256 for (i = 0; i < ack.num_ack_ranges; ++i) { 257 QLOG_BEGIN_ARRAY(NULL) 258 QLOG_U64(NULL, ack.ack_ranges[i].start); 259 if (ack.ack_ranges[i].end != ack.ack_ranges[i].start) 260 QLOG_U64(NULL, ack.ack_ranges[i].end); 261 QLOG_END_ARRAY() 262 } 263 QLOG_END_ARRAY() 264 break; 265 case OSSL_QUIC_FRAME_TYPE_RESET_STREAM: { 266 OSSL_QUIC_FRAME_RESET_STREAM f; 267 268 if (!ossl_quic_wire_decode_frame_reset_stream(pkt, &f)) 269 goto unknown; 270 271 QLOG_STR("frame_type", "reset_stream"); 272 QLOG_U64("stream_id", f.stream_id); 273 QLOG_U64("error_code", f.app_error_code); 274 QLOG_U64("final_size", f.final_size); 275 } break; 276 case OSSL_QUIC_FRAME_TYPE_STOP_SENDING: { 277 OSSL_QUIC_FRAME_STOP_SENDING f; 278 279 if (!ossl_quic_wire_decode_frame_stop_sending(pkt, &f)) 280 goto unknown; 281 282 QLOG_STR("frame_type", "stop_sending"); 283 QLOG_U64("stream_id", f.stream_id); 284 QLOG_U64("error_code", f.app_error_code); 285 } break; 286 case OSSL_QUIC_FRAME_TYPE_CRYPTO: { 287 OSSL_QUIC_FRAME_CRYPTO f; 288 289 if (!ossl_quic_wire_decode_frame_crypto(pkt, 1, &f)) 290 goto unknown; 291 292 QLOG_STR("frame_type", "crypto"); 293 QLOG_U64("offset", f.offset); 294 QLOG_U64("payload_length", f.len); 295 *need_skip += (size_t)f.len; 296 } break; 297 case OSSL_QUIC_FRAME_TYPE_STREAM: 298 case OSSL_QUIC_FRAME_TYPE_STREAM_FIN: 299 case OSSL_QUIC_FRAME_TYPE_STREAM_LEN: 300 case OSSL_QUIC_FRAME_TYPE_STREAM_LEN_FIN: 301 case OSSL_QUIC_FRAME_TYPE_STREAM_OFF: 302 case OSSL_QUIC_FRAME_TYPE_STREAM_OFF_FIN: 303 case OSSL_QUIC_FRAME_TYPE_STREAM_OFF_LEN: 304 case OSSL_QUIC_FRAME_TYPE_STREAM_OFF_LEN_FIN: { 305 OSSL_QUIC_FRAME_STREAM f; 306 307 if (!ossl_quic_wire_decode_frame_stream(pkt, 1, &f)) 308 goto unknown; 309 310 QLOG_STR("frame_type", "stream"); 311 QLOG_U64("stream_id", f.stream_id); 312 QLOG_U64("offset", f.offset); 313 QLOG_U64("payload_length", f.len); 314 QLOG_BOOL("explicit_length", f.has_explicit_len); 315 if (f.is_fin) 316 QLOG_BOOL("fin", 1); 317 *need_skip = f.has_explicit_len 318 ? *need_skip + (size_t)f.len 319 : SIZE_MAX; 320 } break; 321 case OSSL_QUIC_FRAME_TYPE_MAX_DATA: { 322 uint64_t x; 323 324 if (!ossl_quic_wire_decode_frame_max_data(pkt, &x)) 325 goto unknown; 326 327 QLOG_STR("frame_type", "max_data"); 328 QLOG_U64("maximum", x); 329 } break; 330 case OSSL_QUIC_FRAME_TYPE_MAX_STREAMS_BIDI: 331 case OSSL_QUIC_FRAME_TYPE_MAX_STREAMS_UNI: { 332 uint64_t x; 333 334 if (!ossl_quic_wire_decode_frame_max_streams(pkt, &x)) 335 goto unknown; 336 337 QLOG_STR("frame_type", "max_streams"); 338 QLOG_STR("stream_type", 339 frame_type == OSSL_QUIC_FRAME_TYPE_MAX_STREAMS_BIDI 340 ? "bidirectional" 341 : "unidirectional"); 342 QLOG_U64("maximum", x); 343 } break; 344 case OSSL_QUIC_FRAME_TYPE_MAX_STREAM_DATA: { 345 uint64_t stream_id, max_data; 346 347 if (!ossl_quic_wire_decode_frame_max_stream_data(pkt, &stream_id, 348 &max_data)) 349 goto unknown; 350 351 QLOG_STR("frame_type", "max_stream_data"); 352 QLOG_U64("stream_id", stream_id); 353 QLOG_U64("maximum", max_data); 354 } break; 355 case OSSL_QUIC_FRAME_TYPE_PATH_CHALLENGE: { 356 uint64_t challenge; 357 358 if (!ossl_quic_wire_decode_frame_path_challenge(pkt, &challenge)) 359 goto unknown; 360 361 QLOG_STR("frame_type", "path_challenge"); 362 } break; 363 case OSSL_QUIC_FRAME_TYPE_PATH_RESPONSE: { 364 uint64_t challenge; 365 366 if (!ossl_quic_wire_decode_frame_path_response(pkt, &challenge)) 367 goto unknown; 368 369 QLOG_STR("frame_type", "path_response"); 370 } break; 371 case OSSL_QUIC_FRAME_TYPE_CONN_CLOSE_APP: 372 case OSSL_QUIC_FRAME_TYPE_CONN_CLOSE_TRANSPORT: { 373 OSSL_QUIC_FRAME_CONN_CLOSE f; 374 375 if (!ossl_quic_wire_decode_frame_conn_close(pkt, &f)) 376 goto unknown; 377 378 QLOG_STR("frame_type", "connection_close"); 379 QLOG_STR("error_space", f.is_app ? "application" : "transport"); 380 QLOG_U64("error_code_value", f.error_code); 381 if (f.is_app) 382 QLOG_U64("error_code", f.error_code); 383 if (!f.is_app && f.frame_type != 0) 384 QLOG_U64("trigger_frame_type", f.frame_type); 385 QLOG_STR_LEN("reason", f.reason, f.reason_len); 386 } break; 387 case OSSL_QUIC_FRAME_TYPE_HANDSHAKE_DONE: { 388 if (!ossl_quic_wire_decode_frame_handshake_done(pkt)) 389 goto unknown; 390 391 QLOG_STR("frame_type", "handshake_done"); 392 } break; 393 case OSSL_QUIC_FRAME_TYPE_NEW_CONN_ID: { 394 OSSL_QUIC_FRAME_NEW_CONN_ID f; 395 396 if (!ossl_quic_wire_decode_frame_new_conn_id(pkt, &f)) 397 goto unknown; 398 399 QLOG_STR("frame_type", "new_connection_id"); 400 QLOG_U64("sequence_number", f.seq_num); 401 QLOG_U64("retire_prior_to", f.retire_prior_to); 402 QLOG_CID("connection_id", &f.conn_id); 403 QLOG_BIN("stateless_reset_token", 404 f.stateless_reset.token, 405 sizeof(f.stateless_reset.token)); 406 } break; 407 case OSSL_QUIC_FRAME_TYPE_RETIRE_CONN_ID: { 408 uint64_t seq_num; 409 410 if (!ossl_quic_wire_decode_frame_retire_conn_id(pkt, &seq_num)) 411 goto unknown; 412 413 QLOG_STR("frame_type", "retire_connection_id"); 414 QLOG_U64("sequence_number", seq_num); 415 } break; 416 case OSSL_QUIC_FRAME_TYPE_DATA_BLOCKED: { 417 uint64_t x; 418 419 if (!ossl_quic_wire_decode_frame_data_blocked(pkt, &x)) 420 goto unknown; 421 422 QLOG_STR("frame_type", "data_blocked"); 423 QLOG_U64("limit", x); 424 } break; 425 case OSSL_QUIC_FRAME_TYPE_STREAM_DATA_BLOCKED: { 426 uint64_t stream_id, x; 427 428 if (!ossl_quic_wire_decode_frame_stream_data_blocked(pkt, 429 &stream_id, 430 &x)) 431 goto unknown; 432 433 QLOG_STR("frame_type", "stream_data_blocked"); 434 QLOG_U64("stream_id", stream_id); 435 QLOG_U64("limit", x); 436 } break; 437 case OSSL_QUIC_FRAME_TYPE_STREAMS_BLOCKED_BIDI: 438 case OSSL_QUIC_FRAME_TYPE_STREAMS_BLOCKED_UNI: { 439 uint64_t x; 440 441 if (!ossl_quic_wire_decode_frame_streams_blocked(pkt, &x)) 442 goto unknown; 443 444 QLOG_STR("frame_type", "streams_blocked"); 445 QLOG_STR("stream_type", 446 frame_type == OSSL_QUIC_FRAME_TYPE_STREAMS_BLOCKED_BIDI 447 ? "bidirectional" 448 : "unidirectional"); 449 QLOG_U64("limit", x); 450 } break; 451 case OSSL_QUIC_FRAME_TYPE_NEW_TOKEN: { 452 const unsigned char *token; 453 size_t token_len; 454 455 if (!ossl_quic_wire_decode_frame_new_token(pkt, &token, &token_len)) 456 goto unknown; 457 458 QLOG_STR("frame_type", "new_token"); 459 QLOG_BEGIN("token"); 460 QLOG_BEGIN("raw"); 461 QLOG_BIN("data", token, token_len); 462 QLOG_END(); 463 QLOG_END(); 464 } break; 465 default: 466 unknown: 467 QLOG_STR("frame_type", "unknown"); 468 QLOG_U64("frame_type_value", frame_type); 469 470 /* 471 * Can't continue scanning for frames in this case as the frame length 472 * is unknown. We log the entire body of the rest of the packet payload 473 * as the raw data of the frame. 474 */ 475 QLOG_BEGIN("raw"); 476 QLOG_BIN("data", PACKET_data(&orig_pkt), 477 PACKET_remaining(&orig_pkt)); 478 QLOG_END(); 479 ignore_res(PACKET_forward(pkt, PACKET_remaining(pkt))); 480 break; 481 } 482 483 return 1; 484 } 485 486 static void log_frame(QLOG *qlog_instance, PACKET *pkt, 487 size_t *need_skip) 488 { 489 size_t rem_before, rem_after; 490 491 rem_before = PACKET_remaining(pkt); 492 493 if (!log_frame_actual(qlog_instance, pkt, need_skip)) 494 return; 495 496 rem_after = PACKET_remaining(pkt); 497 QLOG_U64("length", rem_before - rem_after); 498 } 499 500 static int log_frames(QLOG *qlog_instance, 501 const OSSL_QTX_IOVEC *iovec, 502 size_t num_iovec) 503 { 504 size_t i; 505 PACKET pkt; 506 size_t need_skip = 0; 507 508 for (i = 0; i < num_iovec; ++i) { 509 if (!PACKET_buf_init(&pkt, iovec[i].buf, iovec[i].buf_len)) 510 return 0; 511 512 while (PACKET_remaining(&pkt) > 0) { 513 if (need_skip > 0) { 514 size_t adv = need_skip; 515 516 if (adv > PACKET_remaining(&pkt)) 517 adv = PACKET_remaining(&pkt); 518 519 if (!PACKET_forward(&pkt, adv)) 520 return 0; 521 522 need_skip -= adv; 523 continue; 524 } 525 526 QLOG_BEGIN(NULL) 527 { 528 log_frame(qlog_instance, &pkt, &need_skip); 529 } 530 QLOG_END() 531 } 532 } 533 534 return 1; 535 } 536 537 static void log_packet(QLOG *qlog_instance, 538 const QUIC_PKT_HDR *hdr, 539 QUIC_PN pn, 540 const OSSL_QTX_IOVEC *iovec, 541 size_t num_iovec, 542 uint64_t datagram_id) 543 { 544 const char *type_s; 545 546 QLOG_BEGIN("header") 547 type_s = quic_pkt_type_to_qlog(hdr->type); 548 if (type_s == NULL) 549 type_s = "unknown"; 550 551 QLOG_STR("packet_type", type_s); 552 if (ossl_quic_pkt_type_has_pn(hdr->type)) 553 QLOG_U64("packet_number", pn); 554 555 QLOG_CID("dcid", &hdr->dst_conn_id); 556 if (ossl_quic_pkt_type_has_scid(hdr->type)) 557 QLOG_CID("scid", &hdr->src_conn_id); 558 559 if (hdr->token_len > 0) { 560 QLOG_BEGIN("token") 561 QLOG_BEGIN("raw") 562 QLOG_BIN("data", hdr->token, hdr->token_len); 563 QLOG_END() 564 QLOG_END() 565 } 566 /* TODO(QLOG FUTURE): flags, length */ 567 QLOG_END() 568 QLOG_U64("datagram_id", datagram_id); 569 570 if (ossl_quic_pkt_type_is_encrypted(hdr->type)) { 571 QLOG_BEGIN_ARRAY("frames") 572 log_frames(qlog_instance, iovec, num_iovec); 573 QLOG_END_ARRAY() 574 } 575 } 576 577 #endif 578 579 void ossl_qlog_event_transport_packet_sent(QLOG *qlog, 580 const QUIC_PKT_HDR *hdr, 581 QUIC_PN pn, 582 const OSSL_QTX_IOVEC *iovec, 583 size_t num_iovec, 584 uint64_t datagram_id) 585 { 586 #ifndef OPENSSL_NO_QLOG 587 QLOG_EVENT_BEGIN(qlog, transport, packet_sent) 588 log_packet(qlog, hdr, pn, iovec, num_iovec, datagram_id); 589 QLOG_EVENT_END() 590 #endif 591 } 592 593 void ossl_qlog_event_transport_packet_received(QLOG *qlog, 594 const QUIC_PKT_HDR *hdr, 595 QUIC_PN pn, 596 const OSSL_QTX_IOVEC *iovec, 597 size_t num_iovec, 598 uint64_t datagram_id) 599 { 600 #ifndef OPENSSL_NO_QLOG 601 QLOG_EVENT_BEGIN(qlog, transport, packet_received) 602 log_packet(qlog, hdr, pn, iovec, num_iovec, datagram_id); 603 QLOG_EVENT_END() 604 #endif 605 } 606
Indexes created Sat Jun 27 00:24:51 UTC 2026