lsquic_ev_log.c revision a74702c6
1/* Copyright (c) 2017 - 2022 LiteSpeed Technologies Inc. See LICENSE. */ 2#ifndef WIN32 3#include <arpa/inet.h> 4#else 5#include <vc_compat.h> 6#endif 7#include <errno.h> 8#include <inttypes.h> 9#include <stdlib.h> 10#include <string.h> 11#include <sys/queue.h> 12 13#include <openssl/x509.h> 14 15#include "lsquic.h" 16#include "lsquic_types.h" 17#include "lsquic_int_types.h" 18#include "lsquic_packet_common.h" 19#include "lsquic_packet_gquic.h" 20#include "lsquic_packet_in.h" 21#include "lsquic_packet_out.h" 22#include "lsquic_parse.h" 23#include "lsquic_frame_common.h" 24#include "lsquic_headers.h" 25#include "lsquic_str.h" 26#include "lsquic_frame_reader.h" 27#include "lsquic_enc_sess.h" 28#include "lsquic_ev_log.h" 29#include "lsquic_sizes.h" 30#include "lsquic_trans_params.h" 31#include "lsquic_util.h" 32#include "lsquic_hash.h" 33#include "lsquic_conn.h" 34#include "lsxpack_header.h" 35 36#define LSQUIC_LOGGER_MODULE LSQLM_EVENT 37#include "lsquic_logger.h" 38 39 40/* ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ */ 41/* |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| */ 42/* Messages that do not include connection ID go above this point */ 43 44#define LSQUIC_LOG_CONN_ID cid 45#define LCID(...) LSQ_LOG2(LSQ_LOG_DEBUG, __VA_ARGS__) /* LCID: log with CID */ 46 47/* Messages that are to include connection ID go below this point */ 48/* |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| */ 49/* VVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVV */ 50 51void 52lsquic_ev_log_packet_in (const lsquic_cid_t *cid, 53 const lsquic_packet_in_t *packet_in) 54{ 55 unsigned packet_sz; 56 57 switch (packet_in->pi_flags & (PI_FROM_MINI|PI_GQUIC)) 58 { 59 case PI_FROM_MINI|PI_GQUIC: 60 LCID("packet in: %"PRIu64" (from mini)", packet_in->pi_packno); 61 break; 62 case PI_FROM_MINI: 63 LCID("packet in: %"PRIu64" (from mini), type: %s, ecn: %u", 64 packet_in->pi_packno, lsquic_hety2str[packet_in->pi_header_type], 65 lsquic_packet_in_ecn(packet_in)); 66 break; 67 case PI_GQUIC: 68 packet_sz = packet_in->pi_data_sz 69 + (packet_in->pi_flags & PI_DECRYPTED ? GQUIC_PACKET_HASH_SZ : 0); 70 LCID("packet in: %"PRIu64", size: %u", packet_in->pi_packno, packet_sz); 71 break; 72 default: 73 packet_sz = packet_in->pi_data_sz 74 + (packet_in->pi_flags & PI_DECRYPTED ? IQUIC_TAG_LEN : 0); 75 if (packet_in->pi_flags & PI_LOG_QL_BITS) 76 LCID("packet in: %"PRIu64", type: %s, size: %u; ecn: %u, spin: %d; " 77 "path: %hhu; Q: %d; L: %d", 78 packet_in->pi_packno, lsquic_hety2str[packet_in->pi_header_type], 79 packet_sz, 80 lsquic_packet_in_ecn(packet_in), 81 /* spin bit value is only valid for short packet headers */ 82 lsquic_packet_in_spin_bit(packet_in), packet_in->pi_path_id, 83 ((packet_in->pi_flags & PI_SQUARE_BIT) > 0), 84 ((packet_in->pi_flags & PI_LOSS_BIT) > 0)); 85 else 86 LCID("packet in: %"PRIu64", type: %s, size: %u; ecn: %u, spin: %d; " 87 "path: %hhu", 88 packet_in->pi_packno, lsquic_hety2str[packet_in->pi_header_type], 89 packet_sz, 90 lsquic_packet_in_ecn(packet_in), 91 /* spin bit value is only valid for short packet headers */ 92 lsquic_packet_in_spin_bit(packet_in), packet_in->pi_path_id); 93 break; 94 } 95} 96 97 98void 99lsquic_ev_log_ack_frame_in (const lsquic_cid_t *cid, 100 const struct ack_info *acki) 101{ 102 char buf[MAX_ACKI_STR_SZ]; 103 104 lsquic_acki2str(acki, buf, sizeof(buf)); 105 LCID("ACK frame in: %s", buf); 106} 107 108 109void 110lsquic_ev_log_stream_frame_in (const lsquic_cid_t *cid, 111 const struct stream_frame *frame) 112{ 113 LCID("STREAM frame in: stream %"PRIu64"; offset %"PRIu64"; size %"PRIu16 114 "; fin: %d", frame->stream_id, frame->data_frame.df_offset, 115 frame->data_frame.df_size, (int) frame->data_frame.df_fin); 116} 117 118 119void 120lsquic_ev_log_crypto_frame_in (const lsquic_cid_t *cid, 121 const struct stream_frame *frame, unsigned enc_level) 122{ 123 LCID("CRYPTO frame in: level %u; offset %"PRIu64"; size %"PRIu16, 124 enc_level, frame->data_frame.df_offset, frame->data_frame.df_size); 125} 126 127 128void 129lsquic_ev_log_stop_waiting_frame_in (const lsquic_cid_t *cid, 130 lsquic_packno_t least) 131{ 132 LCID("STOP_WAITING frame in: least unacked packno %"PRIu64, least); 133} 134 135 136void 137lsquic_ev_log_window_update_frame_in (const lsquic_cid_t *cid, 138 lsquic_stream_id_t stream_id, uint64_t offset) 139{ 140 LCID("WINDOW_UPDATE frame in: stream %"PRIu64"; offset %"PRIu64, 141 stream_id, offset); 142} 143 144 145void 146lsquic_ev_log_blocked_frame_in (const lsquic_cid_t *cid, 147 lsquic_stream_id_t stream_id) 148{ 149 LCID("BLOCKED frame in: stream %"PRIu64, stream_id); 150} 151 152 153void 154lsquic_ev_log_connection_close_frame_in (const lsquic_cid_t *cid, 155 uint64_t error_code, int reason_len, const char *reason) 156{ 157 LCID("CONNECTION_CLOSE frame in: error code %"PRIu64", reason: %.*s", 158 error_code, reason_len, reason); 159} 160 161 162void 163lsquic_ev_log_goaway_frame_in (const lsquic_cid_t *cid, uint32_t error_code, 164 lsquic_stream_id_t stream_id, int reason_len, const char *reason) 165{ 166 LCID("GOAWAY frame in: error code %"PRIu32", stream %"PRIu64 167 ", reason: %.*s", error_code, stream_id, reason_len, reason); 168} 169 170 171void 172lsquic_ev_log_rst_stream_frame_in (const lsquic_cid_t *cid, 173 lsquic_stream_id_t stream_id, uint64_t offset, uint64_t error_code) 174{ 175 LCID("RST_STREAM frame in: error code %"PRIu64", stream %"PRIu64 176 ", offset: %"PRIu64, error_code, stream_id, offset); 177} 178 179 180void 181lsquic_ev_log_stop_sending_frame_in (const lsquic_cid_t *cid, 182 lsquic_stream_id_t stream_id, uint64_t error_code) 183{ 184 LCID("STOP_SENDING frame in: error code %"PRIu64", stream %"PRIu64, 185 error_code, stream_id); 186} 187 188 189void 190lsquic_ev_log_padding_frame_in (const lsquic_cid_t *cid, size_t len) 191{ 192 LCID("PADDING frame in of %zd bytes", len); 193} 194 195 196void 197lsquic_ev_log_ping_frame_in (const lsquic_cid_t *cid) 198{ 199 LCID("PING frame in"); 200} 201 202 203void 204lsquic_ev_log_packet_created (const lsquic_cid_t *cid, 205 const struct lsquic_packet_out *packet_out) 206{ 207 LCID("created packet %"PRIu64"; flags: version=%d, nonce=%d, conn_id=%d", 208 packet_out->po_packno, 209 !!(packet_out->po_flags & PO_VERSION), 210 !!(packet_out->po_flags & PO_NONCE), 211 !!(packet_out->po_flags & PO_CONN_ID)); 212} 213 214 215void 216lsquic_ev_log_packet_sent (const lsquic_cid_t *cid, 217 const struct lsquic_packet_out *packet_out) 218{ 219 char frames[lsquic_frame_types_str_sz]; 220 if (lsquic_packet_out_verneg(packet_out)) 221 LCID("sent version negotiation packet, size %hu", 222 packet_out->po_data_sz); 223 else if (lsquic_packet_out_retry(packet_out)) 224 LCID("sent stateless retry packet, size %hu", packet_out->po_data_sz); 225 else if (lsquic_packet_out_pubres(packet_out)) 226 LCID("sent public reset packet, size %hu", packet_out->po_data_sz); 227 else if (packet_out->po_lflags & POL_GQUIC) 228 LCID("sent packet %"PRIu64", size %hu, frame types: %s", 229 packet_out->po_packno, packet_out->po_enc_data_sz, 230 /* Frame types is a list of different frames types contained 231 * in the packet, no more. Count and order of frames is not 232 * printed. 233 */ 234 lsquic_frame_types_to_str(frames, sizeof(frames), 235 packet_out->po_frame_types)); 236 else if (packet_out->po_lflags & POL_LOG_QL_BITS) 237 LCID("sent packet %"PRIu64", type %s, crypto: %s, size %hu, frame " 238 "types: %s, ecn: %u, spin: %d; kp: %u, path: %hhu, flags: %u; " 239 "Q: %u; L: %u", 240 packet_out->po_packno, lsquic_hety2str[packet_out->po_header_type], 241 lsquic_enclev2str[ lsquic_packet_out_enc_level(packet_out) ], 242 packet_out->po_enc_data_sz, 243 /* Frame types is a list of different frames types contained 244 * in the packet, no more. Count and order of frames is not 245 * printed. 246 */ 247 lsquic_frame_types_to_str(frames, sizeof(frames), 248 packet_out->po_frame_types), 249 lsquic_packet_out_ecn(packet_out), 250 /* spin bit value is only valid for short packet headers */ 251 lsquic_packet_out_spin_bit(packet_out), 252 lsquic_packet_out_kp(packet_out), 253 packet_out->po_path->np_path_id, 254 (unsigned) packet_out->po_flags, 255 lsquic_packet_out_square_bit(packet_out), 256 lsquic_packet_out_loss_bit(packet_out)); 257 else 258 LCID("sent packet %"PRIu64", type %s, crypto: %s, size %hu, frame " 259 "types: %s, ecn: %u, spin: %d; kp: %u, path: %hhu, flags: %u", 260 packet_out->po_packno, lsquic_hety2str[packet_out->po_header_type], 261 lsquic_enclev2str[ lsquic_packet_out_enc_level(packet_out) ], 262 packet_out->po_enc_data_sz, 263 /* Frame types is a list of different frames types contained 264 * in the packet, no more. Count and order of frames is not 265 * printed. 266 */ 267 lsquic_frame_types_to_str(frames, sizeof(frames), 268 packet_out->po_frame_types), 269 lsquic_packet_out_ecn(packet_out), 270 /* spin bit value is only valid for short packet headers */ 271 lsquic_packet_out_spin_bit(packet_out), 272 lsquic_packet_out_kp(packet_out), 273 packet_out->po_path->np_path_id, 274 (unsigned) packet_out->po_flags); 275} 276 277 278void 279lsquic_ev_log_packet_not_sent (const lsquic_cid_t *cid, 280 const struct lsquic_packet_out *packet_out) 281{ 282 char frames[lsquic_frame_types_str_sz]; 283 LCID("unsent packet %"PRIu64", size %hu, frame types: %s", 284 packet_out->po_packno, packet_out->po_enc_data_sz, 285 /* Frame types is a list of different frames types contained in 286 * the packet, no more. Count and order of frames is not printed. 287 */ 288 lsquic_frame_types_to_str(frames, sizeof(frames), 289 packet_out->po_frame_types)); 290} 291 292 293void 294lsquic_ev_log_http_headers_in (const lsquic_cid_t *cid, int is_server, 295 const struct uncompressed_headers *uh) 296{ 297 const struct http1x_headers *h1h; 298 const char *cr, *p; 299 300 if (uh->uh_flags & UH_PP) 301 LCID("read push promise; stream %"PRIu64", promised stream %"PRIu64, 302 uh->uh_stream_id, uh->uh_oth_stream_id); 303 else 304 LCID("read %s headers; stream: %"PRIu64", depends on stream: %"PRIu64 305 ", weight: %hu, exclusive: %d, fin: %d", 306 is_server ? "request" : "response", 307 uh->uh_stream_id, uh->uh_oth_stream_id, uh->uh_weight, 308 (int) uh->uh_exclusive, !!(uh->uh_flags & UH_FIN)); 309 310 if (uh->uh_flags & UH_H1H) 311 { 312 h1h = uh->uh_hset; 313 for (p = h1h->h1h_buf; p < h1h->h1h_buf + h1h->h1h_size; p = cr + 2) 314 { 315 cr = strchr(p, '\r'); 316 if (cr && cr > p) 317 LCID(" %.*s", (int) (cr - p), p); 318 else 319 break; 320 } 321 } 322} 323 324 325void 326lsquic_ev_log_action_stream_frame (const lsquic_cid_t *cid, 327 const struct parse_funcs *pf, const unsigned char *buf, size_t bufsz, 328 const char *what) 329{ 330 struct stream_frame frame; 331 int len; 332 333 len = pf->pf_parse_stream_frame(buf, bufsz, &frame); 334 if (len > 0) 335 LCID("%s STREAM frame: stream %"PRIu64", offset: %"PRIu64 336 ", size: %"PRIu16", fin: %d", what, frame.stream_id, 337 frame.data_frame.df_offset, frame.data_frame.df_size, 338 frame.data_frame.df_fin); 339 else 340 LSQ_LOG2(LSQ_LOG_WARN, "cannot parse STREAM frame"); 341} 342 343 344void 345lsquic_ev_log_generated_crypto_frame (const lsquic_cid_t *cid, 346 const struct parse_funcs *pf, const unsigned char *buf, size_t bufsz) 347{ 348 struct stream_frame frame; 349 int len; 350 351 len = pf->pf_parse_crypto_frame(buf, bufsz, &frame); 352 if (len > 0) 353 LCID("generated CRYPTO frame: offset: %"PRIu64", size: %"PRIu16, 354 frame.data_frame.df_offset, frame.data_frame.df_size); 355 else 356 LSQ_LOG2(LSQ_LOG_WARN, "cannot parse CRYPTO frame"); 357} 358 359 360void 361lsquic_ev_log_generated_ack_frame (const lsquic_cid_t *cid, 362 const struct parse_funcs *pf, const unsigned char *ack_buf, 363 size_t ack_buf_sz) 364{ 365 struct ack_info acki; 366 int len; 367 char buf[MAX_ACKI_STR_SZ]; 368 369 len = pf->pf_parse_ack_frame(ack_buf, ack_buf_sz, &acki, 370 TP_DEF_ACK_DELAY_EXP); 371 if (len < 0) 372 { 373 LSQ_LOG2(LSQ_LOG_WARN, "cannot parse ACK frame"); 374 return; 375 } 376 377 lsquic_acki2str(&acki, buf, sizeof(buf)); 378 LCID("generated ACK frame: %s", buf); 379} 380 381 382void 383lsquic_ev_log_generated_new_token_frame (const lsquic_cid_t *cid, 384 const struct parse_funcs *pf, const unsigned char *frame_buf, 385 size_t frame_buf_sz) 386{ 387 const unsigned char *token; 388 size_t sz; 389 char *buf; 390 int len; 391 392 len = pf->pf_parse_new_token_frame(frame_buf, frame_buf_sz, &token, &sz); 393 if (len < 0) 394 { 395 LSQ_LOG2(LSQ_LOG_WARN, "cannot parse NEW_TOKEN frame"); 396 return; 397 } 398 399 buf = malloc(sz * 2 + 1); 400 if (buf) 401 { 402 lsquic_hexstr(token, sz, buf, sz * 2 + 1); 403 LCID("generated NEW_TOKEN frame: %s", buf); 404 free(buf); 405 } 406} 407 408 409void 410lsquic_ev_log_generated_path_chal_frame (const lsquic_cid_t *cid, 411 const struct parse_funcs *pf, const unsigned char *frame_buf, 412 size_t frame_buf_sz) 413{ 414 uint64_t chal; 415 int len; 416 char hexbuf[sizeof(chal) * 2 + 1]; 417 418 len = pf->pf_parse_path_chal_frame(frame_buf, frame_buf_sz, &chal); 419 if (len > 0) 420 LCID("generated PATH_CHALLENGE(%s) frame", 421 HEXSTR((unsigned char *) &chal, sizeof(chal), hexbuf)); 422 else 423 LSQ_LOG2(LSQ_LOG_WARN, "cannot parse PATH_CHALLENGE frame"); 424} 425 426 427void 428lsquic_ev_log_generated_path_resp_frame (const lsquic_cid_t *cid, 429 const struct parse_funcs *pf, const unsigned char *frame_buf, 430 size_t frame_buf_sz) 431{ 432 uint64_t resp; 433 int len; 434 char hexbuf[sizeof(resp) * 2 + 1]; 435 436 len = pf->pf_parse_path_resp_frame(frame_buf, frame_buf_sz, &resp); 437 if (len > 0) 438 LCID("generated PATH_RESPONSE(%s) frame", 439 HEXSTR((unsigned char *) &resp, sizeof(resp), hexbuf)); 440 else 441 LSQ_LOG2(LSQ_LOG_WARN, "cannot parse PATH_RESPONSE frame"); 442} 443 444 445void 446lsquic_ev_log_generated_new_connection_id_frame (const lsquic_cid_t *cid, 447 const struct parse_funcs *pf, const unsigned char *frame_buf, 448 size_t frame_buf_sz) 449{ 450 const unsigned char *token; 451 lsquic_cid_t new_cid; 452 uint64_t seqno, retire_prior_to; 453 int len; 454 char token_buf[IQUIC_SRESET_TOKEN_SZ * 2 + 1]; 455 char cid_buf[MAX_CID_LEN * 2 + 1]; 456 457 len = pf->pf_parse_new_conn_id(frame_buf, frame_buf_sz, &seqno, 458 &retire_prior_to, &new_cid, &token); 459 if (len < 0) 460 { 461 LSQ_LOG2(LSQ_LOG_WARN, "cannot parse NEW_CONNECTION_ID frame"); 462 return; 463 } 464 465 lsquic_hexstr(new_cid.idbuf, new_cid.len, cid_buf, sizeof(cid_buf)); 466 lsquic_hexstr(token, IQUIC_SRESET_TOKEN_SZ, token_buf, sizeof(token_buf)); 467 LCID("generated NEW_CONNECTION_ID frame: seqno: %"PRIu64"; retire prior " 468 "to: %"PRIu64"; cid: %s; token: %s", seqno, retire_prior_to, 469 cid_buf, token_buf); 470} 471 472 473void 474lsquic_ev_log_generated_stop_waiting_frame (const lsquic_cid_t *cid, 475 lsquic_packno_t lunack) 476{ 477 LCID("generated STOP_WAITING frame; least unacked: %"PRIu64, lunack); 478} 479 480 481void 482lsquic_ev_log_generated_stop_sending_frame (const lsquic_cid_t *cid, 483 lsquic_stream_id_t stream_id, uint16_t error_code) 484{ 485 LCID("generated STOP_SENDING frame; stream ID: %"PRIu64"; error code: " 486 "%"PRIu16, stream_id, error_code); 487} 488 489 490void 491lsquic_ev_log_generated_http_headers (const lsquic_cid_t *cid, 492 lsquic_stream_id_t stream_id, 493 int is_server, const struct http_prio_frame *prio_frame, 494 const struct lsquic_http_headers *headers) 495{ 496 lsquic_stream_id_t dep_stream_id; 497 int exclusive, i; 498 unsigned short weight; 499 500 if (is_server) 501 LCID("generated HTTP response HEADERS for stream %"PRIu64, stream_id); 502 else 503 { 504 memcpy(&dep_stream_id, prio_frame->hpf_stream_id, 4); 505 dep_stream_id = htonl(dep_stream_id); 506 exclusive = dep_stream_id >> 31; 507 dep_stream_id &= ~(1 << 31); 508 weight = prio_frame->hpf_weight + 1; 509 LCID("generated HTTP request HEADERS for stream %"PRIu64 510 ", dep stream: %"PRIu64", weight: %hu, exclusive: %d", stream_id, 511 dep_stream_id, weight, exclusive); 512 } 513 514 for (i = 0; i < headers->count; ++i) 515 if (headers->headers[i].buf) 516 LCID(" %.*s: %.*s", 517 (int) headers->headers[i].name_len, 518 lsxpack_header_get_name(&headers->headers[i]), 519 (int) headers->headers[i].val_len, 520 lsxpack_header_get_value(&headers->headers[i])); 521} 522 523 524void 525lsquic_ev_log_generated_http_push_promise (const lsquic_cid_t *cid, 526 lsquic_stream_id_t stream_id, lsquic_stream_id_t promised_stream_id, 527 const struct lsquic_http_headers *headers) 528{ 529 int i; 530 531 LCID("generated HTTP PUSH_PROMISE for stream %"PRIu64"; promised stream %" 532 PRIu64, stream_id, promised_stream_id); 533 534 for (i = 0; i < headers->count; ++i) 535 if (headers->headers[i].buf) 536 LCID(" %.*s: %.*s", 537 (int) headers->headers[i].name_len, 538 lsxpack_header_get_name(&headers->headers[i]), 539 (int) headers->headers[i].val_len, 540 lsxpack_header_get_value(&headers->headers[i])); 541} 542 543void 544lsquic_ev_log_create_connection (const lsquic_cid_t *cid, 545 const struct sockaddr *local_sa, 546 const struct sockaddr *peer_sa) 547{ 548 LCID("connection created"); 549} 550 551 552void 553lsquic_ev_log_hsk_completed (const lsquic_cid_t *cid) 554{ 555 LCID("handshake completed"); 556} 557 558 559void 560lsquic_ev_log_sess_resume (const lsquic_cid_t *cid) 561{ 562 LCID("sess_resume successful"); 563} 564 565 566void 567lsquic_ev_log_check_certs (const lsquic_cid_t *cid, const lsquic_str_t **certs, 568 size_t count) 569{ 570 LCID("check certs"); 571} 572 573 574void 575lsquic_ev_log_cert_chain (const lsquic_cid_t *cid, struct stack_st_X509 *chain) 576{ 577 X509_NAME *name; 578 X509 *cert; 579 unsigned i; 580 char buf[0x100]; 581 582 for (i = 0; i < sk_X509_num(chain); ++i) 583 { 584 cert = sk_X509_value(chain, i); 585 name = X509_get_subject_name(cert); 586 LCID("cert #%u: name: %s", i, 587 X509_NAME_oneline(name, buf, sizeof(buf))); 588 } 589} 590 591 592void 593lsquic_ev_log_version_negotiation (const lsquic_cid_t *cid, 594 const char *action, const char *ver) 595{ 596 LCID("version negotiation: %s version %s", action, ver); 597} 598