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