lsquic_ev_log.c revision a74702c6
1a74702c6SGeorge Wang/* Copyright (c) 2017 - 2022 LiteSpeed Technologies Inc. See LICENSE. */ 2461e84d8SAmol Deshpande#ifndef WIN32 350aadb33SDmitri Tikhonov#include <arpa/inet.h> 4461e84d8SAmol Deshpande#else 5461e84d8SAmol Deshpande#include <vc_compat.h> 6461e84d8SAmol Deshpande#endif 750aadb33SDmitri Tikhonov#include <errno.h> 850aadb33SDmitri Tikhonov#include <inttypes.h> 950aadb33SDmitri Tikhonov#include <stdlib.h> 1050aadb33SDmitri Tikhonov#include <string.h> 11461e84d8SAmol Deshpande#include <sys/queue.h> 1250aadb33SDmitri Tikhonov 13b55a5117SDmitri Tikhonov#include <openssl/x509.h> 14b55a5117SDmitri Tikhonov 1550aadb33SDmitri Tikhonov#include "lsquic.h" 1650aadb33SDmitri Tikhonov#include "lsquic_types.h" 1750aadb33SDmitri Tikhonov#include "lsquic_int_types.h" 1850aadb33SDmitri Tikhonov#include "lsquic_packet_common.h" 195392f7a3SLiteSpeed Tech#include "lsquic_packet_gquic.h" 2050aadb33SDmitri Tikhonov#include "lsquic_packet_in.h" 2150aadb33SDmitri Tikhonov#include "lsquic_packet_out.h" 2250aadb33SDmitri Tikhonov#include "lsquic_parse.h" 2350aadb33SDmitri Tikhonov#include "lsquic_frame_common.h" 243b55e6aeSDmitri Tikhonov#include "lsquic_headers.h" 259626cfc2SDmitri Tikhonov#include "lsquic_str.h" 265392f7a3SLiteSpeed Tech#include "lsquic_frame_reader.h" 275392f7a3SLiteSpeed Tech#include "lsquic_enc_sess.h" 2850aadb33SDmitri Tikhonov#include "lsquic_ev_log.h" 295392f7a3SLiteSpeed Tech#include "lsquic_sizes.h" 305392f7a3SLiteSpeed Tech#include "lsquic_trans_params.h" 315392f7a3SLiteSpeed Tech#include "lsquic_util.h" 325392f7a3SLiteSpeed Tech#include "lsquic_hash.h" 335392f7a3SLiteSpeed Tech#include "lsquic_conn.h" 3455613f44SDmitri Tikhonov#include "lsxpack_header.h" 3550aadb33SDmitri Tikhonov 3650aadb33SDmitri Tikhonov#define LSQUIC_LOGGER_MODULE LSQLM_EVENT 3750aadb33SDmitri Tikhonov#include "lsquic_logger.h" 3850aadb33SDmitri Tikhonov 3950aadb33SDmitri Tikhonov 4050aadb33SDmitri Tikhonov/* ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ */ 4150aadb33SDmitri Tikhonov/* |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| */ 4250aadb33SDmitri Tikhonov/* Messages that do not include connection ID go above this point */ 4350aadb33SDmitri Tikhonov 4450aadb33SDmitri Tikhonov#define LSQUIC_LOG_CONN_ID cid 45461e84d8SAmol Deshpande#define LCID(...) LSQ_LOG2(LSQ_LOG_DEBUG, __VA_ARGS__) /* LCID: log with CID */ 4650aadb33SDmitri Tikhonov 4750aadb33SDmitri Tikhonov/* Messages that are to include connection ID go below this point */ 4850aadb33SDmitri Tikhonov/* |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| */ 4950aadb33SDmitri Tikhonov/* VVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVV */ 5050aadb33SDmitri Tikhonov 5150aadb33SDmitri Tikhonovvoid 525392f7a3SLiteSpeed Techlsquic_ev_log_packet_in (const lsquic_cid_t *cid, 535392f7a3SLiteSpeed Tech const lsquic_packet_in_t *packet_in) 5450aadb33SDmitri Tikhonov{ 55bbee242aSDmitri Tikhonov unsigned packet_sz; 56bbee242aSDmitri Tikhonov 57bbee242aSDmitri Tikhonov switch (packet_in->pi_flags & (PI_FROM_MINI|PI_GQUIC)) 589626cfc2SDmitri Tikhonov { 595392f7a3SLiteSpeed Tech case PI_FROM_MINI|PI_GQUIC: 605392f7a3SLiteSpeed Tech LCID("packet in: %"PRIu64" (from mini)", packet_in->pi_packno); 615392f7a3SLiteSpeed Tech break; 625392f7a3SLiteSpeed Tech case PI_FROM_MINI: 635392f7a3SLiteSpeed Tech LCID("packet in: %"PRIu64" (from mini), type: %s, ecn: %u", 645392f7a3SLiteSpeed Tech packet_in->pi_packno, lsquic_hety2str[packet_in->pi_header_type], 655392f7a3SLiteSpeed Tech lsquic_packet_in_ecn(packet_in)); 665392f7a3SLiteSpeed Tech break; 679626cfc2SDmitri Tikhonov case PI_GQUIC: 68bbee242aSDmitri Tikhonov packet_sz = packet_in->pi_data_sz 69bbee242aSDmitri Tikhonov + (packet_in->pi_flags & PI_DECRYPTED ? GQUIC_PACKET_HASH_SZ : 0); 70bbee242aSDmitri Tikhonov LCID("packet in: %"PRIu64", size: %u", packet_in->pi_packno, packet_sz); 719626cfc2SDmitri Tikhonov break; 729626cfc2SDmitri Tikhonov default: 73bbee242aSDmitri Tikhonov packet_sz = packet_in->pi_data_sz 74bbee242aSDmitri Tikhonov + (packet_in->pi_flags & PI_DECRYPTED ? IQUIC_TAG_LEN : 0); 7502b6086dSDmitri Tikhonov if (packet_in->pi_flags & PI_LOG_QL_BITS) 7602b6086dSDmitri Tikhonov LCID("packet in: %"PRIu64", type: %s, size: %u; ecn: %u, spin: %d; " 7702b6086dSDmitri Tikhonov "path: %hhu; Q: %d; L: %d", 7802b6086dSDmitri Tikhonov packet_in->pi_packno, lsquic_hety2str[packet_in->pi_header_type], 79bbee242aSDmitri Tikhonov packet_sz, 8002b6086dSDmitri Tikhonov lsquic_packet_in_ecn(packet_in), 8102b6086dSDmitri Tikhonov /* spin bit value is only valid for short packet headers */ 8202b6086dSDmitri Tikhonov lsquic_packet_in_spin_bit(packet_in), packet_in->pi_path_id, 8302b6086dSDmitri Tikhonov ((packet_in->pi_flags & PI_SQUARE_BIT) > 0), 8402b6086dSDmitri Tikhonov ((packet_in->pi_flags & PI_LOSS_BIT) > 0)); 8502b6086dSDmitri Tikhonov else 8602b6086dSDmitri Tikhonov LCID("packet in: %"PRIu64", type: %s, size: %u; ecn: %u, spin: %d; " 8702b6086dSDmitri Tikhonov "path: %hhu", 8802b6086dSDmitri Tikhonov packet_in->pi_packno, lsquic_hety2str[packet_in->pi_header_type], 89bbee242aSDmitri Tikhonov packet_sz, 9002b6086dSDmitri Tikhonov lsquic_packet_in_ecn(packet_in), 9102b6086dSDmitri Tikhonov /* spin bit value is only valid for short packet headers */ 9202b6086dSDmitri Tikhonov lsquic_packet_in_spin_bit(packet_in), packet_in->pi_path_id); 939626cfc2SDmitri Tikhonov break; 949626cfc2SDmitri Tikhonov } 9550aadb33SDmitri Tikhonov} 9650aadb33SDmitri Tikhonov 9750aadb33SDmitri Tikhonov 9850aadb33SDmitri Tikhonovvoid 995392f7a3SLiteSpeed Techlsquic_ev_log_ack_frame_in (const lsquic_cid_t *cid, 1005392f7a3SLiteSpeed Tech const struct ack_info *acki) 10150aadb33SDmitri Tikhonov{ 102de46bf2fSDmitri Tikhonov char buf[MAX_ACKI_STR_SZ]; 10350aadb33SDmitri Tikhonov 104de46bf2fSDmitri Tikhonov lsquic_acki2str(acki, buf, sizeof(buf)); 105de46bf2fSDmitri Tikhonov LCID("ACK frame in: %s", buf); 10650aadb33SDmitri Tikhonov} 10750aadb33SDmitri Tikhonov 10850aadb33SDmitri Tikhonov 10950aadb33SDmitri Tikhonovvoid 1105392f7a3SLiteSpeed Techlsquic_ev_log_stream_frame_in (const lsquic_cid_t *cid, 11150aadb33SDmitri Tikhonov const struct stream_frame *frame) 11250aadb33SDmitri Tikhonov{ 1135392f7a3SLiteSpeed Tech LCID("STREAM frame in: stream %"PRIu64"; offset %"PRIu64"; size %"PRIu16 11450aadb33SDmitri Tikhonov "; fin: %d", frame->stream_id, frame->data_frame.df_offset, 11550aadb33SDmitri Tikhonov frame->data_frame.df_size, (int) frame->data_frame.df_fin); 11650aadb33SDmitri Tikhonov} 11750aadb33SDmitri Tikhonov 11850aadb33SDmitri Tikhonov 11950aadb33SDmitri Tikhonovvoid 1205392f7a3SLiteSpeed Techlsquic_ev_log_crypto_frame_in (const lsquic_cid_t *cid, 1215392f7a3SLiteSpeed Tech const struct stream_frame *frame, unsigned enc_level) 1225392f7a3SLiteSpeed Tech{ 1235392f7a3SLiteSpeed Tech LCID("CRYPTO frame in: level %u; offset %"PRIu64"; size %"PRIu16, 1245392f7a3SLiteSpeed Tech enc_level, frame->data_frame.df_offset, frame->data_frame.df_size); 1255392f7a3SLiteSpeed Tech} 1265392f7a3SLiteSpeed Tech 1275392f7a3SLiteSpeed Tech 1285392f7a3SLiteSpeed Techvoid 1295392f7a3SLiteSpeed Techlsquic_ev_log_stop_waiting_frame_in (const lsquic_cid_t *cid, 1305392f7a3SLiteSpeed Tech lsquic_packno_t least) 13150aadb33SDmitri Tikhonov{ 13250aadb33SDmitri Tikhonov LCID("STOP_WAITING frame in: least unacked packno %"PRIu64, least); 13350aadb33SDmitri Tikhonov} 13450aadb33SDmitri Tikhonov 13550aadb33SDmitri Tikhonov 13650aadb33SDmitri Tikhonovvoid 1375392f7a3SLiteSpeed Techlsquic_ev_log_window_update_frame_in (const lsquic_cid_t *cid, 1385392f7a3SLiteSpeed Tech lsquic_stream_id_t stream_id, uint64_t offset) 13950aadb33SDmitri Tikhonov{ 1405392f7a3SLiteSpeed Tech LCID("WINDOW_UPDATE frame in: stream %"PRIu64"; offset %"PRIu64, 14150aadb33SDmitri Tikhonov stream_id, offset); 14250aadb33SDmitri Tikhonov} 14350aadb33SDmitri Tikhonov 14450aadb33SDmitri Tikhonov 14550aadb33SDmitri Tikhonovvoid 1465392f7a3SLiteSpeed Techlsquic_ev_log_blocked_frame_in (const lsquic_cid_t *cid, 1475392f7a3SLiteSpeed Tech lsquic_stream_id_t stream_id) 14850aadb33SDmitri Tikhonov{ 1495392f7a3SLiteSpeed Tech LCID("BLOCKED frame in: stream %"PRIu64, stream_id); 15050aadb33SDmitri Tikhonov} 15150aadb33SDmitri Tikhonov 15250aadb33SDmitri Tikhonov 15350aadb33SDmitri Tikhonovvoid 1545392f7a3SLiteSpeed Techlsquic_ev_log_connection_close_frame_in (const lsquic_cid_t *cid, 1555392f7a3SLiteSpeed Tech uint64_t error_code, int reason_len, const char *reason) 15650aadb33SDmitri Tikhonov{ 1575392f7a3SLiteSpeed Tech LCID("CONNECTION_CLOSE frame in: error code %"PRIu64", reason: %.*s", 15850aadb33SDmitri Tikhonov error_code, reason_len, reason); 15950aadb33SDmitri Tikhonov} 16050aadb33SDmitri Tikhonov 16150aadb33SDmitri Tikhonov 16250aadb33SDmitri Tikhonovvoid 1635392f7a3SLiteSpeed Techlsquic_ev_log_goaway_frame_in (const lsquic_cid_t *cid, uint32_t error_code, 1645392f7a3SLiteSpeed Tech lsquic_stream_id_t stream_id, int reason_len, const char *reason) 16550aadb33SDmitri Tikhonov{ 1665392f7a3SLiteSpeed Tech LCID("GOAWAY frame in: error code %"PRIu32", stream %"PRIu64 16750aadb33SDmitri Tikhonov ", reason: %.*s", error_code, stream_id, reason_len, reason); 16850aadb33SDmitri Tikhonov} 16950aadb33SDmitri Tikhonov 17050aadb33SDmitri Tikhonov 17150aadb33SDmitri Tikhonovvoid 1725392f7a3SLiteSpeed Techlsquic_ev_log_rst_stream_frame_in (const lsquic_cid_t *cid, 1735392f7a3SLiteSpeed Tech lsquic_stream_id_t stream_id, uint64_t offset, uint64_t error_code) 17450aadb33SDmitri Tikhonov{ 1755392f7a3SLiteSpeed Tech LCID("RST_STREAM frame in: error code %"PRIu64", stream %"PRIu64 17650aadb33SDmitri Tikhonov ", offset: %"PRIu64, error_code, stream_id, offset); 17750aadb33SDmitri Tikhonov} 17850aadb33SDmitri Tikhonov 17950aadb33SDmitri Tikhonov 18050aadb33SDmitri Tikhonovvoid 1815392f7a3SLiteSpeed Techlsquic_ev_log_stop_sending_frame_in (const lsquic_cid_t *cid, 1825392f7a3SLiteSpeed Tech lsquic_stream_id_t stream_id, uint64_t error_code) 1835392f7a3SLiteSpeed Tech{ 1845392f7a3SLiteSpeed Tech LCID("STOP_SENDING frame in: error code %"PRIu64", stream %"PRIu64, 1855392f7a3SLiteSpeed Tech error_code, stream_id); 1865392f7a3SLiteSpeed Tech} 1875392f7a3SLiteSpeed Tech 1885392f7a3SLiteSpeed Tech 1895392f7a3SLiteSpeed Techvoid 1905392f7a3SLiteSpeed Techlsquic_ev_log_padding_frame_in (const lsquic_cid_t *cid, size_t len) 19150aadb33SDmitri Tikhonov{ 19250aadb33SDmitri Tikhonov LCID("PADDING frame in of %zd bytes", len); 19350aadb33SDmitri Tikhonov} 19450aadb33SDmitri Tikhonov 19550aadb33SDmitri Tikhonov 19650aadb33SDmitri Tikhonovvoid 1975392f7a3SLiteSpeed Techlsquic_ev_log_ping_frame_in (const lsquic_cid_t *cid) 19850aadb33SDmitri Tikhonov{ 19950aadb33SDmitri Tikhonov LCID("PING frame in"); 20050aadb33SDmitri Tikhonov} 20150aadb33SDmitri Tikhonov 20250aadb33SDmitri Tikhonov 20350aadb33SDmitri Tikhonovvoid 2045392f7a3SLiteSpeed Techlsquic_ev_log_packet_created (const lsquic_cid_t *cid, 20550aadb33SDmitri Tikhonov const struct lsquic_packet_out *packet_out) 20650aadb33SDmitri Tikhonov{ 20750aadb33SDmitri Tikhonov LCID("created packet %"PRIu64"; flags: version=%d, nonce=%d, conn_id=%d", 20850aadb33SDmitri Tikhonov packet_out->po_packno, 20950aadb33SDmitri Tikhonov !!(packet_out->po_flags & PO_VERSION), 21050aadb33SDmitri Tikhonov !!(packet_out->po_flags & PO_NONCE), 21150aadb33SDmitri Tikhonov !!(packet_out->po_flags & PO_CONN_ID)); 21250aadb33SDmitri Tikhonov} 21350aadb33SDmitri Tikhonov 21450aadb33SDmitri Tikhonov 21550aadb33SDmitri Tikhonovvoid 2165392f7a3SLiteSpeed Techlsquic_ev_log_packet_sent (const lsquic_cid_t *cid, 21750aadb33SDmitri Tikhonov const struct lsquic_packet_out *packet_out) 21850aadb33SDmitri Tikhonov{ 21950aadb33SDmitri Tikhonov char frames[lsquic_frame_types_str_sz]; 22050aadb33SDmitri Tikhonov if (lsquic_packet_out_verneg(packet_out)) 22150aadb33SDmitri Tikhonov LCID("sent version negotiation packet, size %hu", 22250aadb33SDmitri Tikhonov packet_out->po_data_sz); 2235392f7a3SLiteSpeed Tech else if (lsquic_packet_out_retry(packet_out)) 2245392f7a3SLiteSpeed Tech LCID("sent stateless retry packet, size %hu", packet_out->po_data_sz); 22550aadb33SDmitri Tikhonov else if (lsquic_packet_out_pubres(packet_out)) 22650aadb33SDmitri Tikhonov LCID("sent public reset packet, size %hu", packet_out->po_data_sz); 2275392f7a3SLiteSpeed Tech else if (packet_out->po_lflags & POL_GQUIC) 22850aadb33SDmitri Tikhonov LCID("sent packet %"PRIu64", size %hu, frame types: %s", 22950aadb33SDmitri Tikhonov packet_out->po_packno, packet_out->po_enc_data_sz, 23050aadb33SDmitri Tikhonov /* Frame types is a list of different frames types contained 23150aadb33SDmitri Tikhonov * in the packet, no more. Count and order of frames is not 23250aadb33SDmitri Tikhonov * printed. 23350aadb33SDmitri Tikhonov */ 23450aadb33SDmitri Tikhonov lsquic_frame_types_to_str(frames, sizeof(frames), 23550aadb33SDmitri Tikhonov packet_out->po_frame_types)); 23602b6086dSDmitri Tikhonov else if (packet_out->po_lflags & POL_LOG_QL_BITS) 23702b6086dSDmitri Tikhonov LCID("sent packet %"PRIu64", type %s, crypto: %s, size %hu, frame " 23802b6086dSDmitri Tikhonov "types: %s, ecn: %u, spin: %d; kp: %u, path: %hhu, flags: %u; " 23902b6086dSDmitri Tikhonov "Q: %u; L: %u", 24002b6086dSDmitri Tikhonov packet_out->po_packno, lsquic_hety2str[packet_out->po_header_type], 24102b6086dSDmitri Tikhonov lsquic_enclev2str[ lsquic_packet_out_enc_level(packet_out) ], 24202b6086dSDmitri Tikhonov packet_out->po_enc_data_sz, 24302b6086dSDmitri Tikhonov /* Frame types is a list of different frames types contained 24402b6086dSDmitri Tikhonov * in the packet, no more. Count and order of frames is not 24502b6086dSDmitri Tikhonov * printed. 24602b6086dSDmitri Tikhonov */ 24702b6086dSDmitri Tikhonov lsquic_frame_types_to_str(frames, sizeof(frames), 24802b6086dSDmitri Tikhonov packet_out->po_frame_types), 24902b6086dSDmitri Tikhonov lsquic_packet_out_ecn(packet_out), 25002b6086dSDmitri Tikhonov /* spin bit value is only valid for short packet headers */ 25102b6086dSDmitri Tikhonov lsquic_packet_out_spin_bit(packet_out), 25202b6086dSDmitri Tikhonov lsquic_packet_out_kp(packet_out), 25302b6086dSDmitri Tikhonov packet_out->po_path->np_path_id, 25402b6086dSDmitri Tikhonov (unsigned) packet_out->po_flags, 25502b6086dSDmitri Tikhonov lsquic_packet_out_square_bit(packet_out), 25602b6086dSDmitri Tikhonov lsquic_packet_out_loss_bit(packet_out)); 2579626cfc2SDmitri Tikhonov else 2589626cfc2SDmitri Tikhonov LCID("sent packet %"PRIu64", type %s, crypto: %s, size %hu, frame " 25984dbbb75SDmitri Tikhonov "types: %s, ecn: %u, spin: %d; kp: %u, path: %hhu, flags: %u", 2609626cfc2SDmitri Tikhonov packet_out->po_packno, lsquic_hety2str[packet_out->po_header_type], 2619626cfc2SDmitri Tikhonov lsquic_enclev2str[ lsquic_packet_out_enc_level(packet_out) ], 2629626cfc2SDmitri Tikhonov packet_out->po_enc_data_sz, 2639626cfc2SDmitri Tikhonov /* Frame types is a list of different frames types contained 2649626cfc2SDmitri Tikhonov * in the packet, no more. Count and order of frames is not 2659626cfc2SDmitri Tikhonov * printed. 2669626cfc2SDmitri Tikhonov */ 2679626cfc2SDmitri Tikhonov lsquic_frame_types_to_str(frames, sizeof(frames), 2685392f7a3SLiteSpeed Tech packet_out->po_frame_types), 2695392f7a3SLiteSpeed Tech lsquic_packet_out_ecn(packet_out), 2705392f7a3SLiteSpeed Tech /* spin bit value is only valid for short packet headers */ 2715392f7a3SLiteSpeed Tech lsquic_packet_out_spin_bit(packet_out), 2725392f7a3SLiteSpeed Tech lsquic_packet_out_kp(packet_out), 27384dbbb75SDmitri Tikhonov packet_out->po_path->np_path_id, 27484dbbb75SDmitri Tikhonov (unsigned) packet_out->po_flags); 27550aadb33SDmitri Tikhonov} 27650aadb33SDmitri Tikhonov 27750aadb33SDmitri Tikhonov 27850aadb33SDmitri Tikhonovvoid 2795392f7a3SLiteSpeed Techlsquic_ev_log_packet_not_sent (const lsquic_cid_t *cid, 28050aadb33SDmitri Tikhonov const struct lsquic_packet_out *packet_out) 28150aadb33SDmitri Tikhonov{ 28250aadb33SDmitri Tikhonov char frames[lsquic_frame_types_str_sz]; 28350aadb33SDmitri Tikhonov LCID("unsent packet %"PRIu64", size %hu, frame types: %s", 28450aadb33SDmitri Tikhonov packet_out->po_packno, packet_out->po_enc_data_sz, 28550aadb33SDmitri Tikhonov /* Frame types is a list of different frames types contained in 28650aadb33SDmitri Tikhonov * the packet, no more. Count and order of frames is not printed. 28750aadb33SDmitri Tikhonov */ 28850aadb33SDmitri Tikhonov lsquic_frame_types_to_str(frames, sizeof(frames), 28950aadb33SDmitri Tikhonov packet_out->po_frame_types)); 29050aadb33SDmitri Tikhonov} 29150aadb33SDmitri Tikhonov 29250aadb33SDmitri Tikhonov 29350aadb33SDmitri Tikhonovvoid 2945392f7a3SLiteSpeed Techlsquic_ev_log_http_headers_in (const lsquic_cid_t *cid, int is_server, 29550aadb33SDmitri Tikhonov const struct uncompressed_headers *uh) 29650aadb33SDmitri Tikhonov{ 2973b55e6aeSDmitri Tikhonov const struct http1x_headers *h1h; 29850aadb33SDmitri Tikhonov const char *cr, *p; 29950aadb33SDmitri Tikhonov 30050aadb33SDmitri Tikhonov if (uh->uh_flags & UH_PP) 3015392f7a3SLiteSpeed Tech LCID("read push promise; stream %"PRIu64", promised stream %"PRIu64, 30250aadb33SDmitri Tikhonov uh->uh_stream_id, uh->uh_oth_stream_id); 30350aadb33SDmitri Tikhonov else 3045392f7a3SLiteSpeed Tech LCID("read %s headers; stream: %"PRIu64", depends on stream: %"PRIu64 30550aadb33SDmitri Tikhonov ", weight: %hu, exclusive: %d, fin: %d", 30650aadb33SDmitri Tikhonov is_server ? "request" : "response", 30750aadb33SDmitri Tikhonov uh->uh_stream_id, uh->uh_oth_stream_id, uh->uh_weight, 30850aadb33SDmitri Tikhonov (int) uh->uh_exclusive, !!(uh->uh_flags & UH_FIN)); 30950aadb33SDmitri Tikhonov 3103b55e6aeSDmitri Tikhonov if (uh->uh_flags & UH_H1H) 31150aadb33SDmitri Tikhonov { 3123b55e6aeSDmitri Tikhonov h1h = uh->uh_hset; 3133b55e6aeSDmitri Tikhonov for (p = h1h->h1h_buf; p < h1h->h1h_buf + h1h->h1h_size; p = cr + 2) 3143b55e6aeSDmitri Tikhonov { 3153b55e6aeSDmitri Tikhonov cr = strchr(p, '\r'); 3163b55e6aeSDmitri Tikhonov if (cr && cr > p) 3173b55e6aeSDmitri Tikhonov LCID(" %.*s", (int) (cr - p), p); 3183b55e6aeSDmitri Tikhonov else 3193b55e6aeSDmitri Tikhonov break; 3203b55e6aeSDmitri Tikhonov } 32150aadb33SDmitri Tikhonov } 32250aadb33SDmitri Tikhonov} 32350aadb33SDmitri Tikhonov 32450aadb33SDmitri Tikhonov 32550aadb33SDmitri Tikhonovvoid 3265392f7a3SLiteSpeed Techlsquic_ev_log_action_stream_frame (const lsquic_cid_t *cid, 327c51ce338SDmitri Tikhonov const struct parse_funcs *pf, const unsigned char *buf, size_t bufsz, 328c51ce338SDmitri Tikhonov const char *what) 32950aadb33SDmitri Tikhonov{ 33050aadb33SDmitri Tikhonov struct stream_frame frame; 33150aadb33SDmitri Tikhonov int len; 33250aadb33SDmitri Tikhonov 33350aadb33SDmitri Tikhonov len = pf->pf_parse_stream_frame(buf, bufsz, &frame); 33450aadb33SDmitri Tikhonov if (len > 0) 3355392f7a3SLiteSpeed Tech LCID("%s STREAM frame: stream %"PRIu64", offset: %"PRIu64 336c51ce338SDmitri Tikhonov ", size: %"PRIu16", fin: %d", what, frame.stream_id, 33750aadb33SDmitri Tikhonov frame.data_frame.df_offset, frame.data_frame.df_size, 33850aadb33SDmitri Tikhonov frame.data_frame.df_fin); 33950aadb33SDmitri Tikhonov else 34050aadb33SDmitri Tikhonov LSQ_LOG2(LSQ_LOG_WARN, "cannot parse STREAM frame"); 34150aadb33SDmitri Tikhonov} 34250aadb33SDmitri Tikhonov 34350aadb33SDmitri Tikhonov 34450aadb33SDmitri Tikhonovvoid 3455392f7a3SLiteSpeed Techlsquic_ev_log_generated_crypto_frame (const lsquic_cid_t *cid, 3465392f7a3SLiteSpeed Tech const struct parse_funcs *pf, const unsigned char *buf, size_t bufsz) 3475392f7a3SLiteSpeed Tech{ 3485392f7a3SLiteSpeed Tech struct stream_frame frame; 3495392f7a3SLiteSpeed Tech int len; 3505392f7a3SLiteSpeed Tech 3515392f7a3SLiteSpeed Tech len = pf->pf_parse_crypto_frame(buf, bufsz, &frame); 3525392f7a3SLiteSpeed Tech if (len > 0) 3535392f7a3SLiteSpeed Tech LCID("generated CRYPTO frame: offset: %"PRIu64", size: %"PRIu16, 3545392f7a3SLiteSpeed Tech frame.data_frame.df_offset, frame.data_frame.df_size); 3555392f7a3SLiteSpeed Tech else 3565392f7a3SLiteSpeed Tech LSQ_LOG2(LSQ_LOG_WARN, "cannot parse CRYPTO frame"); 3575392f7a3SLiteSpeed Tech} 3585392f7a3SLiteSpeed Tech 3595392f7a3SLiteSpeed Tech 3605392f7a3SLiteSpeed Techvoid 3615392f7a3SLiteSpeed Techlsquic_ev_log_generated_ack_frame (const lsquic_cid_t *cid, 3625392f7a3SLiteSpeed Tech const struct parse_funcs *pf, const unsigned char *ack_buf, 3635392f7a3SLiteSpeed Tech size_t ack_buf_sz) 36450aadb33SDmitri Tikhonov{ 36550aadb33SDmitri Tikhonov struct ack_info acki; 36650aadb33SDmitri Tikhonov int len; 367de46bf2fSDmitri Tikhonov char buf[MAX_ACKI_STR_SZ]; 36850aadb33SDmitri Tikhonov 3695392f7a3SLiteSpeed Tech len = pf->pf_parse_ack_frame(ack_buf, ack_buf_sz, &acki, 3705392f7a3SLiteSpeed Tech TP_DEF_ACK_DELAY_EXP); 37150aadb33SDmitri Tikhonov if (len < 0) 37250aadb33SDmitri Tikhonov { 37350aadb33SDmitri Tikhonov LSQ_LOG2(LSQ_LOG_WARN, "cannot parse ACK frame"); 37450aadb33SDmitri Tikhonov return; 37550aadb33SDmitri Tikhonov } 37650aadb33SDmitri Tikhonov 377de46bf2fSDmitri Tikhonov lsquic_acki2str(&acki, buf, sizeof(buf)); 378de46bf2fSDmitri Tikhonov LCID("generated ACK frame: %s", buf); 37950aadb33SDmitri Tikhonov} 38050aadb33SDmitri Tikhonov 38150aadb33SDmitri Tikhonov 38250aadb33SDmitri Tikhonovvoid 3835392f7a3SLiteSpeed Techlsquic_ev_log_generated_new_token_frame (const lsquic_cid_t *cid, 3845392f7a3SLiteSpeed Tech const struct parse_funcs *pf, const unsigned char *frame_buf, 3855392f7a3SLiteSpeed Tech size_t frame_buf_sz) 3865392f7a3SLiteSpeed Tech{ 3875392f7a3SLiteSpeed Tech const unsigned char *token; 3885392f7a3SLiteSpeed Tech size_t sz; 3895392f7a3SLiteSpeed Tech char *buf; 3905392f7a3SLiteSpeed Tech int len; 3915392f7a3SLiteSpeed Tech 3925392f7a3SLiteSpeed Tech len = pf->pf_parse_new_token_frame(frame_buf, frame_buf_sz, &token, &sz); 3935392f7a3SLiteSpeed Tech if (len < 0) 3945392f7a3SLiteSpeed Tech { 3955392f7a3SLiteSpeed Tech LSQ_LOG2(LSQ_LOG_WARN, "cannot parse NEW_TOKEN frame"); 3965392f7a3SLiteSpeed Tech return; 3975392f7a3SLiteSpeed Tech } 3985392f7a3SLiteSpeed Tech 3995392f7a3SLiteSpeed Tech buf = malloc(sz * 2 + 1); 4005392f7a3SLiteSpeed Tech if (buf) 4015392f7a3SLiteSpeed Tech { 4025392f7a3SLiteSpeed Tech lsquic_hexstr(token, sz, buf, sz * 2 + 1); 4035392f7a3SLiteSpeed Tech LCID("generated NEW_TOKEN frame: %s", buf); 4045392f7a3SLiteSpeed Tech free(buf); 4055392f7a3SLiteSpeed Tech } 4065392f7a3SLiteSpeed Tech} 4075392f7a3SLiteSpeed Tech 4085392f7a3SLiteSpeed Tech 4095392f7a3SLiteSpeed Techvoid 4105392f7a3SLiteSpeed Techlsquic_ev_log_generated_path_chal_frame (const lsquic_cid_t *cid, 4115392f7a3SLiteSpeed Tech const struct parse_funcs *pf, const unsigned char *frame_buf, 4125392f7a3SLiteSpeed Tech size_t frame_buf_sz) 4135392f7a3SLiteSpeed Tech{ 4145392f7a3SLiteSpeed Tech uint64_t chal; 4155392f7a3SLiteSpeed Tech int len; 4165392f7a3SLiteSpeed Tech char hexbuf[sizeof(chal) * 2 + 1]; 4175392f7a3SLiteSpeed Tech 4185392f7a3SLiteSpeed Tech len = pf->pf_parse_path_chal_frame(frame_buf, frame_buf_sz, &chal); 4195392f7a3SLiteSpeed Tech if (len > 0) 4205392f7a3SLiteSpeed Tech LCID("generated PATH_CHALLENGE(%s) frame", 4215392f7a3SLiteSpeed Tech HEXSTR((unsigned char *) &chal, sizeof(chal), hexbuf)); 4225392f7a3SLiteSpeed Tech else 4235392f7a3SLiteSpeed Tech LSQ_LOG2(LSQ_LOG_WARN, "cannot parse PATH_CHALLENGE frame"); 4245392f7a3SLiteSpeed Tech} 4255392f7a3SLiteSpeed Tech 4265392f7a3SLiteSpeed Tech 4275392f7a3SLiteSpeed Techvoid 4285392f7a3SLiteSpeed Techlsquic_ev_log_generated_path_resp_frame (const lsquic_cid_t *cid, 4295392f7a3SLiteSpeed Tech const struct parse_funcs *pf, const unsigned char *frame_buf, 4305392f7a3SLiteSpeed Tech size_t frame_buf_sz) 4315392f7a3SLiteSpeed Tech{ 4325392f7a3SLiteSpeed Tech uint64_t resp; 4335392f7a3SLiteSpeed Tech int len; 4345392f7a3SLiteSpeed Tech char hexbuf[sizeof(resp) * 2 + 1]; 4355392f7a3SLiteSpeed Tech 4365392f7a3SLiteSpeed Tech len = pf->pf_parse_path_resp_frame(frame_buf, frame_buf_sz, &resp); 4375392f7a3SLiteSpeed Tech if (len > 0) 4385392f7a3SLiteSpeed Tech LCID("generated PATH_RESPONSE(%s) frame", 4395392f7a3SLiteSpeed Tech HEXSTR((unsigned char *) &resp, sizeof(resp), hexbuf)); 4405392f7a3SLiteSpeed Tech else 4415392f7a3SLiteSpeed Tech LSQ_LOG2(LSQ_LOG_WARN, "cannot parse PATH_RESPONSE frame"); 4425392f7a3SLiteSpeed Tech} 4435392f7a3SLiteSpeed Tech 4445392f7a3SLiteSpeed Tech 4455392f7a3SLiteSpeed Techvoid 4465392f7a3SLiteSpeed Techlsquic_ev_log_generated_new_connection_id_frame (const lsquic_cid_t *cid, 4475392f7a3SLiteSpeed Tech const struct parse_funcs *pf, const unsigned char *frame_buf, 4485392f7a3SLiteSpeed Tech size_t frame_buf_sz) 4495392f7a3SLiteSpeed Tech{ 4505392f7a3SLiteSpeed Tech const unsigned char *token; 4515392f7a3SLiteSpeed Tech lsquic_cid_t new_cid; 4525392f7a3SLiteSpeed Tech uint64_t seqno, retire_prior_to; 4535392f7a3SLiteSpeed Tech int len; 4545392f7a3SLiteSpeed Tech char token_buf[IQUIC_SRESET_TOKEN_SZ * 2 + 1]; 4555392f7a3SLiteSpeed Tech char cid_buf[MAX_CID_LEN * 2 + 1]; 4565392f7a3SLiteSpeed Tech 4575392f7a3SLiteSpeed Tech len = pf->pf_parse_new_conn_id(frame_buf, frame_buf_sz, &seqno, 4585392f7a3SLiteSpeed Tech &retire_prior_to, &new_cid, &token); 4595392f7a3SLiteSpeed Tech if (len < 0) 4605392f7a3SLiteSpeed Tech { 4615392f7a3SLiteSpeed Tech LSQ_LOG2(LSQ_LOG_WARN, "cannot parse NEW_CONNECTION_ID frame"); 4625392f7a3SLiteSpeed Tech return; 4635392f7a3SLiteSpeed Tech } 4645392f7a3SLiteSpeed Tech 4655392f7a3SLiteSpeed Tech lsquic_hexstr(new_cid.idbuf, new_cid.len, cid_buf, sizeof(cid_buf)); 4665392f7a3SLiteSpeed Tech lsquic_hexstr(token, IQUIC_SRESET_TOKEN_SZ, token_buf, sizeof(token_buf)); 4675392f7a3SLiteSpeed Tech LCID("generated NEW_CONNECTION_ID frame: seqno: %"PRIu64"; retire prior " 4685392f7a3SLiteSpeed Tech "to: %"PRIu64"; cid: %s; token: %s", seqno, retire_prior_to, 4695392f7a3SLiteSpeed Tech cid_buf, token_buf); 4705392f7a3SLiteSpeed Tech} 4715392f7a3SLiteSpeed Tech 4725392f7a3SLiteSpeed Tech 4735392f7a3SLiteSpeed Techvoid 4745392f7a3SLiteSpeed Techlsquic_ev_log_generated_stop_waiting_frame (const lsquic_cid_t *cid, 47550aadb33SDmitri Tikhonov lsquic_packno_t lunack) 47650aadb33SDmitri Tikhonov{ 47750aadb33SDmitri Tikhonov LCID("generated STOP_WAITING frame; least unacked: %"PRIu64, lunack); 47850aadb33SDmitri Tikhonov} 47950aadb33SDmitri Tikhonov 48050aadb33SDmitri Tikhonov 48150aadb33SDmitri Tikhonovvoid 4825392f7a3SLiteSpeed Techlsquic_ev_log_generated_stop_sending_frame (const lsquic_cid_t *cid, 4835392f7a3SLiteSpeed Tech lsquic_stream_id_t stream_id, uint16_t error_code) 4845392f7a3SLiteSpeed Tech{ 4855392f7a3SLiteSpeed Tech LCID("generated STOP_SENDING frame; stream ID: %"PRIu64"; error code: " 4865392f7a3SLiteSpeed Tech "%"PRIu16, stream_id, error_code); 4875392f7a3SLiteSpeed Tech} 4885392f7a3SLiteSpeed Tech 4895392f7a3SLiteSpeed Tech 4905392f7a3SLiteSpeed Techvoid 4915392f7a3SLiteSpeed Techlsquic_ev_log_generated_http_headers (const lsquic_cid_t *cid, 4925392f7a3SLiteSpeed Tech lsquic_stream_id_t stream_id, 49350aadb33SDmitri Tikhonov int is_server, const struct http_prio_frame *prio_frame, 49450aadb33SDmitri Tikhonov const struct lsquic_http_headers *headers) 49550aadb33SDmitri Tikhonov{ 4965392f7a3SLiteSpeed Tech lsquic_stream_id_t dep_stream_id; 49750aadb33SDmitri Tikhonov int exclusive, i; 49850aadb33SDmitri Tikhonov unsigned short weight; 49950aadb33SDmitri Tikhonov 50050aadb33SDmitri Tikhonov if (is_server) 5015392f7a3SLiteSpeed Tech LCID("generated HTTP response HEADERS for stream %"PRIu64, stream_id); 50250aadb33SDmitri Tikhonov else 50350aadb33SDmitri Tikhonov { 50450aadb33SDmitri Tikhonov memcpy(&dep_stream_id, prio_frame->hpf_stream_id, 4); 50550aadb33SDmitri Tikhonov dep_stream_id = htonl(dep_stream_id); 50650aadb33SDmitri Tikhonov exclusive = dep_stream_id >> 31; 50750aadb33SDmitri Tikhonov dep_stream_id &= ~(1 << 31); 50850aadb33SDmitri Tikhonov weight = prio_frame->hpf_weight + 1; 5095392f7a3SLiteSpeed Tech LCID("generated HTTP request HEADERS for stream %"PRIu64 5105392f7a3SLiteSpeed Tech ", dep stream: %"PRIu64", weight: %hu, exclusive: %d", stream_id, 51150aadb33SDmitri Tikhonov dep_stream_id, weight, exclusive); 51250aadb33SDmitri Tikhonov } 51350aadb33SDmitri Tikhonov 51450aadb33SDmitri Tikhonov for (i = 0; i < headers->count; ++i) 51555613f44SDmitri Tikhonov if (headers->headers[i].buf) 51655613f44SDmitri Tikhonov LCID(" %.*s: %.*s", 51755613f44SDmitri Tikhonov (int) headers->headers[i].name_len, 51855613f44SDmitri Tikhonov lsxpack_header_get_name(&headers->headers[i]), 51955613f44SDmitri Tikhonov (int) headers->headers[i].val_len, 52055613f44SDmitri Tikhonov lsxpack_header_get_value(&headers->headers[i])); 52150aadb33SDmitri Tikhonov} 52250aadb33SDmitri Tikhonov 52350aadb33SDmitri Tikhonov 52450aadb33SDmitri Tikhonovvoid 5255392f7a3SLiteSpeed Techlsquic_ev_log_generated_http_push_promise (const lsquic_cid_t *cid, 5265392f7a3SLiteSpeed Tech lsquic_stream_id_t stream_id, lsquic_stream_id_t promised_stream_id, 52755613f44SDmitri Tikhonov const struct lsquic_http_headers *headers) 52850aadb33SDmitri Tikhonov{ 52950aadb33SDmitri Tikhonov int i; 53050aadb33SDmitri Tikhonov 5315392f7a3SLiteSpeed Tech LCID("generated HTTP PUSH_PROMISE for stream %"PRIu64"; promised stream %" 5325392f7a3SLiteSpeed Tech PRIu64, stream_id, promised_stream_id); 53350aadb33SDmitri Tikhonov 53450aadb33SDmitri Tikhonov for (i = 0; i < headers->count; ++i) 53555613f44SDmitri Tikhonov if (headers->headers[i].buf) 53650aadb33SDmitri Tikhonov LCID(" %.*s: %.*s", 53755613f44SDmitri Tikhonov (int) headers->headers[i].name_len, 53855613f44SDmitri Tikhonov lsxpack_header_get_name(&headers->headers[i]), 53955613f44SDmitri Tikhonov (int) headers->headers[i].val_len, 54055613f44SDmitri Tikhonov lsxpack_header_get_value(&headers->headers[i])); 54150aadb33SDmitri Tikhonov} 54255cd0b38SDmitri Tikhonov 54355cd0b38SDmitri Tikhonovvoid 5445392f7a3SLiteSpeed Techlsquic_ev_log_create_connection (const lsquic_cid_t *cid, 54555cd0b38SDmitri Tikhonov const struct sockaddr *local_sa, 54655cd0b38SDmitri Tikhonov const struct sockaddr *peer_sa) 54755cd0b38SDmitri Tikhonov{ 54855cd0b38SDmitri Tikhonov LCID("connection created"); 54955cd0b38SDmitri Tikhonov} 55055cd0b38SDmitri Tikhonov 55155cd0b38SDmitri Tikhonov 55255cd0b38SDmitri Tikhonovvoid 5535392f7a3SLiteSpeed Techlsquic_ev_log_hsk_completed (const lsquic_cid_t *cid) 55455cd0b38SDmitri Tikhonov{ 55555cd0b38SDmitri Tikhonov LCID("handshake completed"); 55655cd0b38SDmitri Tikhonov} 55755cd0b38SDmitri Tikhonov 55855cd0b38SDmitri Tikhonov 55955cd0b38SDmitri Tikhonovvoid 5607483dee0SDmitri Tikhonovlsquic_ev_log_sess_resume (const lsquic_cid_t *cid) 56155cd0b38SDmitri Tikhonov{ 5627483dee0SDmitri Tikhonov LCID("sess_resume successful"); 56355cd0b38SDmitri Tikhonov} 56455cd0b38SDmitri Tikhonov 56555cd0b38SDmitri Tikhonov 56655cd0b38SDmitri Tikhonovvoid 5675392f7a3SLiteSpeed Techlsquic_ev_log_check_certs (const lsquic_cid_t *cid, const lsquic_str_t **certs, 56855cd0b38SDmitri Tikhonov size_t count) 56955cd0b38SDmitri Tikhonov{ 57055cd0b38SDmitri Tikhonov LCID("check certs"); 57155cd0b38SDmitri Tikhonov} 57255cd0b38SDmitri Tikhonov 57355cd0b38SDmitri Tikhonov 57455cd0b38SDmitri Tikhonovvoid 575b55a5117SDmitri Tikhonovlsquic_ev_log_cert_chain (const lsquic_cid_t *cid, struct stack_st_X509 *chain) 576b55a5117SDmitri Tikhonov{ 577b55a5117SDmitri Tikhonov X509_NAME *name; 578b55a5117SDmitri Tikhonov X509 *cert; 579b55a5117SDmitri Tikhonov unsigned i; 580b55a5117SDmitri Tikhonov char buf[0x100]; 581b55a5117SDmitri Tikhonov 582b55a5117SDmitri Tikhonov for (i = 0; i < sk_X509_num(chain); ++i) 583b55a5117SDmitri Tikhonov { 584b55a5117SDmitri Tikhonov cert = sk_X509_value(chain, i); 585b55a5117SDmitri Tikhonov name = X509_get_subject_name(cert); 586b55a5117SDmitri Tikhonov LCID("cert #%u: name: %s", i, 587b55a5117SDmitri Tikhonov X509_NAME_oneline(name, buf, sizeof(buf))); 588b55a5117SDmitri Tikhonov } 589b55a5117SDmitri Tikhonov} 590b55a5117SDmitri Tikhonov 591b55a5117SDmitri Tikhonov 592b55a5117SDmitri Tikhonovvoid 5935392f7a3SLiteSpeed Techlsquic_ev_log_version_negotiation (const lsquic_cid_t *cid, 59455cd0b38SDmitri Tikhonov const char *action, const char *ver) 59555cd0b38SDmitri Tikhonov{ 59655cd0b38SDmitri Tikhonov LCID("version negotiation: %s version %s", action, ver); 59755cd0b38SDmitri Tikhonov} 598