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