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