lsquic_ev_log.c revision 50aadb33
150aadb33SDmitri Tikhonov/* Copyright (c) 2017 LiteSpeed Technologies Inc. See LICENSE. */ 250aadb33SDmitri Tikhonov#include <arpa/inet.h> 350aadb33SDmitri Tikhonov#include <errno.h> 450aadb33SDmitri Tikhonov#include <inttypes.h> 550aadb33SDmitri Tikhonov#include <stdlib.h> 650aadb33SDmitri Tikhonov#include <string.h> 750aadb33SDmitri Tikhonov 850aadb33SDmitri Tikhonov#include "lsquic.h" 950aadb33SDmitri Tikhonov#include "lsquic_types.h" 1050aadb33SDmitri Tikhonov#include "lsquic_int_types.h" 1150aadb33SDmitri Tikhonov#include "lsquic_packet_common.h" 1250aadb33SDmitri Tikhonov#include "lsquic_packet_in.h" 1350aadb33SDmitri Tikhonov#include "lsquic_packet_out.h" 1450aadb33SDmitri Tikhonov#include "lsquic_parse.h" 1550aadb33SDmitri Tikhonov#include "lsquic_frame_common.h" 1650aadb33SDmitri Tikhonov#include "lsquic_frame_reader.h" 1750aadb33SDmitri Tikhonov#include "lsquic_ev_log.h" 1850aadb33SDmitri Tikhonov 1950aadb33SDmitri Tikhonov#define LSQUIC_LOGGER_MODULE LSQLM_EVENT 2050aadb33SDmitri Tikhonov#include "lsquic_logger.h" 2150aadb33SDmitri Tikhonov 2250aadb33SDmitri Tikhonov 2350aadb33SDmitri Tikhonov/* ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ */ 2450aadb33SDmitri Tikhonov/* |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| */ 2550aadb33SDmitri Tikhonov/* Messages that do not include connection ID go above this point */ 2650aadb33SDmitri Tikhonov 2750aadb33SDmitri Tikhonov#define LSQUIC_LOG_CONN_ID cid 2850aadb33SDmitri Tikhonov#define LCID(a...) LSQ_LOG2(LSQ_LOG_DEBUG, a) /* LCID: log with CID */ 2950aadb33SDmitri Tikhonov 3050aadb33SDmitri Tikhonov/* Messages that are to include connection ID go below this point */ 3150aadb33SDmitri Tikhonov/* |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| */ 3250aadb33SDmitri Tikhonov/* VVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVV */ 3350aadb33SDmitri Tikhonov 3450aadb33SDmitri Tikhonovvoid 3550aadb33SDmitri Tikhonovlsquic_ev_log_packet_in (lsquic_cid_t cid, const lsquic_packet_in_t *packet_in) 3650aadb33SDmitri Tikhonov{ 3750aadb33SDmitri Tikhonov LCID("packet in: %"PRIu64, packet_in->pi_packno); 3850aadb33SDmitri Tikhonov} 3950aadb33SDmitri Tikhonov 4050aadb33SDmitri Tikhonov 4150aadb33SDmitri Tikhonovvoid 4250aadb33SDmitri Tikhonovlsquic_ev_log_ack_frame_in (lsquic_cid_t cid, const struct ack_info *acki) 4350aadb33SDmitri Tikhonov{ 4450aadb33SDmitri Tikhonov size_t sz; 4550aadb33SDmitri Tikhonov char *buf; 4650aadb33SDmitri Tikhonov 4750aadb33SDmitri Tikhonov if ((buf = acki2str(acki, &sz))) 4850aadb33SDmitri Tikhonov { 4950aadb33SDmitri Tikhonov LCID("ACK frame in: %.*s", (int) sz, buf); 5050aadb33SDmitri Tikhonov free(buf); 5150aadb33SDmitri Tikhonov } 5250aadb33SDmitri Tikhonov} 5350aadb33SDmitri Tikhonov 5450aadb33SDmitri Tikhonov 5550aadb33SDmitri Tikhonovvoid 5650aadb33SDmitri Tikhonovlsquic_ev_log_stream_frame_in (lsquic_cid_t cid, 5750aadb33SDmitri Tikhonov const struct stream_frame *frame) 5850aadb33SDmitri Tikhonov{ 5950aadb33SDmitri Tikhonov LCID("STREAM frame in: stream %u; offset %"PRIu64"; size %"PRIu16 6050aadb33SDmitri Tikhonov "; fin: %d", frame->stream_id, frame->data_frame.df_offset, 6150aadb33SDmitri Tikhonov frame->data_frame.df_size, (int) frame->data_frame.df_fin); 6250aadb33SDmitri Tikhonov} 6350aadb33SDmitri Tikhonov 6450aadb33SDmitri Tikhonov 6550aadb33SDmitri Tikhonovvoid 6650aadb33SDmitri Tikhonovlsquic_ev_log_stop_waiting_frame_in (lsquic_cid_t cid, lsquic_packno_t least) 6750aadb33SDmitri Tikhonov{ 6850aadb33SDmitri Tikhonov LCID("STOP_WAITING frame in: least unacked packno %"PRIu64, least); 6950aadb33SDmitri Tikhonov} 7050aadb33SDmitri Tikhonov 7150aadb33SDmitri Tikhonov 7250aadb33SDmitri Tikhonovvoid 7350aadb33SDmitri Tikhonovlsquic_ev_log_window_update_frame_in (lsquic_cid_t cid, uint32_t stream_id, 7450aadb33SDmitri Tikhonov uint64_t offset) 7550aadb33SDmitri Tikhonov{ 7650aadb33SDmitri Tikhonov LCID("WINDOW_UPDATE frame in: stream %"PRIu32"; offset %"PRIu64, 7750aadb33SDmitri Tikhonov stream_id, offset); 7850aadb33SDmitri Tikhonov} 7950aadb33SDmitri Tikhonov 8050aadb33SDmitri Tikhonov 8150aadb33SDmitri Tikhonovvoid 8250aadb33SDmitri Tikhonovlsquic_ev_log_blocked_frame_in (lsquic_cid_t cid, uint32_t stream_id) 8350aadb33SDmitri Tikhonov{ 8450aadb33SDmitri Tikhonov LCID("BLOCKED frame in: stream %"PRIu32, stream_id); 8550aadb33SDmitri Tikhonov} 8650aadb33SDmitri Tikhonov 8750aadb33SDmitri Tikhonov 8850aadb33SDmitri Tikhonovvoid 8950aadb33SDmitri Tikhonovlsquic_ev_log_connection_close_frame_in (lsquic_cid_t cid, 9050aadb33SDmitri Tikhonov uint32_t error_code, int reason_len, const char *reason) 9150aadb33SDmitri Tikhonov{ 9250aadb33SDmitri Tikhonov LCID("CONNECTION_CLOSE frame in: error code %"PRIu32", reason: %.*s", 9350aadb33SDmitri Tikhonov error_code, reason_len, reason); 9450aadb33SDmitri Tikhonov} 9550aadb33SDmitri Tikhonov 9650aadb33SDmitri Tikhonov 9750aadb33SDmitri Tikhonovvoid 9850aadb33SDmitri Tikhonovlsquic_ev_log_goaway_frame_in (lsquic_cid_t cid, uint32_t error_code, 9950aadb33SDmitri Tikhonov uint32_t stream_id, int reason_len, const char *reason) 10050aadb33SDmitri Tikhonov{ 10150aadb33SDmitri Tikhonov LCID("GOAWAY frame in: error code %"PRIu32", stream %"PRIu32 10250aadb33SDmitri Tikhonov ", reason: %.*s", error_code, stream_id, reason_len, reason); 10350aadb33SDmitri Tikhonov} 10450aadb33SDmitri Tikhonov 10550aadb33SDmitri Tikhonov 10650aadb33SDmitri Tikhonovvoid 10750aadb33SDmitri Tikhonovlsquic_ev_log_rst_stream_frame_in (lsquic_cid_t cid, uint32_t stream_id, 10850aadb33SDmitri Tikhonov uint64_t offset, uint32_t error_code) 10950aadb33SDmitri Tikhonov{ 11050aadb33SDmitri Tikhonov LCID("RST_FRAME frame in: error code %"PRIu32", stream %"PRIu32 11150aadb33SDmitri Tikhonov ", offset: %"PRIu64, error_code, stream_id, offset); 11250aadb33SDmitri Tikhonov} 11350aadb33SDmitri Tikhonov 11450aadb33SDmitri Tikhonov 11550aadb33SDmitri Tikhonovvoid 11650aadb33SDmitri Tikhonovlsquic_ev_log_padding_frame_in (lsquic_cid_t cid, size_t len) 11750aadb33SDmitri Tikhonov{ 11850aadb33SDmitri Tikhonov LCID("PADDING frame in of %zd bytes", len); 11950aadb33SDmitri Tikhonov} 12050aadb33SDmitri Tikhonov 12150aadb33SDmitri Tikhonov 12250aadb33SDmitri Tikhonovvoid 12350aadb33SDmitri Tikhonovlsquic_ev_log_ping_frame_in (lsquic_cid_t cid) 12450aadb33SDmitri Tikhonov{ 12550aadb33SDmitri Tikhonov LCID("PING frame in"); 12650aadb33SDmitri Tikhonov} 12750aadb33SDmitri Tikhonov 12850aadb33SDmitri Tikhonov 12950aadb33SDmitri Tikhonovvoid 13050aadb33SDmitri Tikhonovlsquic_ev_log_packet_created (lsquic_cid_t cid, 13150aadb33SDmitri Tikhonov const struct lsquic_packet_out *packet_out) 13250aadb33SDmitri Tikhonov{ 13350aadb33SDmitri Tikhonov LCID("created packet %"PRIu64"; flags: version=%d, nonce=%d, conn_id=%d", 13450aadb33SDmitri Tikhonov packet_out->po_packno, 13550aadb33SDmitri Tikhonov !!(packet_out->po_flags & PO_VERSION), 13650aadb33SDmitri Tikhonov !!(packet_out->po_flags & PO_NONCE), 13750aadb33SDmitri Tikhonov !!(packet_out->po_flags & PO_CONN_ID)); 13850aadb33SDmitri Tikhonov} 13950aadb33SDmitri Tikhonov 14050aadb33SDmitri Tikhonov 14150aadb33SDmitri Tikhonovvoid 14250aadb33SDmitri Tikhonovlsquic_ev_log_packet_sent (lsquic_cid_t cid, 14350aadb33SDmitri Tikhonov const struct lsquic_packet_out *packet_out) 14450aadb33SDmitri Tikhonov{ 14550aadb33SDmitri Tikhonov char frames[lsquic_frame_types_str_sz]; 14650aadb33SDmitri Tikhonov if (lsquic_packet_out_verneg(packet_out)) 14750aadb33SDmitri Tikhonov LCID("sent version negotiation packet, size %hu", 14850aadb33SDmitri Tikhonov packet_out->po_data_sz); 14950aadb33SDmitri Tikhonov else if (lsquic_packet_out_pubres(packet_out)) 15050aadb33SDmitri Tikhonov LCID("sent public reset packet, size %hu", packet_out->po_data_sz); 15150aadb33SDmitri Tikhonov else 15250aadb33SDmitri Tikhonov LCID("sent packet %"PRIu64", size %hu, frame types: %s", 15350aadb33SDmitri Tikhonov packet_out->po_packno, packet_out->po_enc_data_sz, 15450aadb33SDmitri Tikhonov /* Frame types is a list of different frames types contained 15550aadb33SDmitri Tikhonov * in the packet, no more. Count and order of frames is not 15650aadb33SDmitri Tikhonov * printed. 15750aadb33SDmitri Tikhonov */ 15850aadb33SDmitri Tikhonov lsquic_frame_types_to_str(frames, sizeof(frames), 15950aadb33SDmitri Tikhonov packet_out->po_frame_types)); 16050aadb33SDmitri Tikhonov} 16150aadb33SDmitri Tikhonov 16250aadb33SDmitri Tikhonov 16350aadb33SDmitri Tikhonovvoid 16450aadb33SDmitri Tikhonovlsquic_ev_log_packet_not_sent (lsquic_cid_t cid, 16550aadb33SDmitri Tikhonov const struct lsquic_packet_out *packet_out) 16650aadb33SDmitri Tikhonov{ 16750aadb33SDmitri Tikhonov char frames[lsquic_frame_types_str_sz]; 16850aadb33SDmitri Tikhonov LCID("unsent packet %"PRIu64", size %hu, frame types: %s", 16950aadb33SDmitri Tikhonov packet_out->po_packno, packet_out->po_enc_data_sz, 17050aadb33SDmitri Tikhonov /* Frame types is a list of different frames types contained in 17150aadb33SDmitri Tikhonov * the packet, no more. Count and order of frames is not printed. 17250aadb33SDmitri Tikhonov */ 17350aadb33SDmitri Tikhonov lsquic_frame_types_to_str(frames, sizeof(frames), 17450aadb33SDmitri Tikhonov packet_out->po_frame_types)); 17550aadb33SDmitri Tikhonov} 17650aadb33SDmitri Tikhonov 17750aadb33SDmitri Tikhonov 17850aadb33SDmitri Tikhonovvoid 17950aadb33SDmitri Tikhonovlsquic_ev_log_http_headers_in (lsquic_cid_t cid, int is_server, 18050aadb33SDmitri Tikhonov const struct uncompressed_headers *uh) 18150aadb33SDmitri Tikhonov{ 18250aadb33SDmitri Tikhonov const char *cr, *p; 18350aadb33SDmitri Tikhonov 18450aadb33SDmitri Tikhonov if (uh->uh_flags & UH_PP) 18550aadb33SDmitri Tikhonov LCID("read push promise; stream %"PRIu32", promised stream %"PRIu32, 18650aadb33SDmitri Tikhonov uh->uh_stream_id, uh->uh_oth_stream_id); 18750aadb33SDmitri Tikhonov else 18850aadb33SDmitri Tikhonov LCID("read %s headers; stream: %"PRIu32", depends on stream: %"PRIu32 18950aadb33SDmitri Tikhonov ", weight: %hu, exclusive: %d, fin: %d", 19050aadb33SDmitri Tikhonov is_server ? "request" : "response", 19150aadb33SDmitri Tikhonov uh->uh_stream_id, uh->uh_oth_stream_id, uh->uh_weight, 19250aadb33SDmitri Tikhonov (int) uh->uh_exclusive, !!(uh->uh_flags & UH_FIN)); 19350aadb33SDmitri Tikhonov 19450aadb33SDmitri Tikhonov for (p = uh->uh_headers; p < uh->uh_headers + uh->uh_size; p = cr + 2) 19550aadb33SDmitri Tikhonov { 19650aadb33SDmitri Tikhonov cr = strchr(p, '\r'); 19750aadb33SDmitri Tikhonov if (cr && cr > p) 19850aadb33SDmitri Tikhonov LCID(" %.*s", (int) (cr - p), p); 19950aadb33SDmitri Tikhonov else 20050aadb33SDmitri Tikhonov break; 20150aadb33SDmitri Tikhonov } 20250aadb33SDmitri Tikhonov} 20350aadb33SDmitri Tikhonov 20450aadb33SDmitri Tikhonov 20550aadb33SDmitri Tikhonovvoid 20650aadb33SDmitri Tikhonovlsquic_ev_log_generated_stream_frame (lsquic_cid_t cid, 20750aadb33SDmitri Tikhonov const struct parse_funcs *pf, const unsigned char *buf, size_t bufsz) 20850aadb33SDmitri Tikhonov{ 20950aadb33SDmitri Tikhonov struct stream_frame frame; 21050aadb33SDmitri Tikhonov int len; 21150aadb33SDmitri Tikhonov 21250aadb33SDmitri Tikhonov len = pf->pf_parse_stream_frame(buf, bufsz, &frame); 21350aadb33SDmitri Tikhonov if (len > 0) 21450aadb33SDmitri Tikhonov LCID("generated STREAM frame: stream %"PRIu32", offset: %"PRIu64 21550aadb33SDmitri Tikhonov ", size: %"PRIu16", fin: %d", frame.stream_id, 21650aadb33SDmitri Tikhonov frame.data_frame.df_offset, frame.data_frame.df_size, 21750aadb33SDmitri Tikhonov frame.data_frame.df_fin); 21850aadb33SDmitri Tikhonov else 21950aadb33SDmitri Tikhonov LSQ_LOG2(LSQ_LOG_WARN, "cannot parse STREAM frame"); 22050aadb33SDmitri Tikhonov} 22150aadb33SDmitri Tikhonov 22250aadb33SDmitri Tikhonov 22350aadb33SDmitri Tikhonovvoid 22450aadb33SDmitri Tikhonovlsquic_ev_log_generated_ack_frame (lsquic_cid_t cid, const struct parse_funcs *pf, 22550aadb33SDmitri Tikhonov const unsigned char *ack_buf, size_t ack_buf_sz) 22650aadb33SDmitri Tikhonov{ 22750aadb33SDmitri Tikhonov struct ack_info acki; 22850aadb33SDmitri Tikhonov size_t sz; 22950aadb33SDmitri Tikhonov char *buf; 23050aadb33SDmitri Tikhonov int len; 23150aadb33SDmitri Tikhonov 23250aadb33SDmitri Tikhonov len = pf->pf_parse_ack_frame(ack_buf, ack_buf_sz, &acki); 23350aadb33SDmitri Tikhonov if (len < 0) 23450aadb33SDmitri Tikhonov { 23550aadb33SDmitri Tikhonov LSQ_LOG2(LSQ_LOG_WARN, "cannot parse ACK frame"); 23650aadb33SDmitri Tikhonov return; 23750aadb33SDmitri Tikhonov } 23850aadb33SDmitri Tikhonov 23950aadb33SDmitri Tikhonov if ((buf = acki2str(&acki, &sz))) 24050aadb33SDmitri Tikhonov { 24150aadb33SDmitri Tikhonov LCID("generated ACK frame: %.*s", (int) sz, buf); 24250aadb33SDmitri Tikhonov free(buf); 24350aadb33SDmitri Tikhonov } 24450aadb33SDmitri Tikhonov} 24550aadb33SDmitri Tikhonov 24650aadb33SDmitri Tikhonov 24750aadb33SDmitri Tikhonovvoid 24850aadb33SDmitri Tikhonovlsquic_ev_log_generated_stop_waiting_frame (lsquic_cid_t cid, 24950aadb33SDmitri Tikhonov lsquic_packno_t lunack) 25050aadb33SDmitri Tikhonov{ 25150aadb33SDmitri Tikhonov LCID("generated STOP_WAITING frame; least unacked: %"PRIu64, lunack); 25250aadb33SDmitri Tikhonov} 25350aadb33SDmitri Tikhonov 25450aadb33SDmitri Tikhonov 25550aadb33SDmitri Tikhonovvoid 25650aadb33SDmitri Tikhonovlsquic_ev_log_generated_http_headers (lsquic_cid_t cid, uint32_t stream_id, 25750aadb33SDmitri Tikhonov int is_server, const struct http_prio_frame *prio_frame, 25850aadb33SDmitri Tikhonov const struct lsquic_http_headers *headers) 25950aadb33SDmitri Tikhonov{ 26050aadb33SDmitri Tikhonov uint32_t dep_stream_id; 26150aadb33SDmitri Tikhonov int exclusive, i; 26250aadb33SDmitri Tikhonov unsigned short weight; 26350aadb33SDmitri Tikhonov 26450aadb33SDmitri Tikhonov if (is_server) 26550aadb33SDmitri Tikhonov LCID("generated HTTP response HEADERS for stream %"PRIu32, stream_id); 26650aadb33SDmitri Tikhonov else 26750aadb33SDmitri Tikhonov { 26850aadb33SDmitri Tikhonov memcpy(&dep_stream_id, prio_frame->hpf_stream_id, 4); 26950aadb33SDmitri Tikhonov dep_stream_id = htonl(dep_stream_id); 27050aadb33SDmitri Tikhonov exclusive = dep_stream_id >> 31; 27150aadb33SDmitri Tikhonov dep_stream_id &= ~(1 << 31); 27250aadb33SDmitri Tikhonov weight = prio_frame->hpf_weight + 1; 27350aadb33SDmitri Tikhonov LCID("generated HTTP request HEADERS for stream %"PRIu32 27450aadb33SDmitri Tikhonov ", dep stream: %"PRIu32", weight: %hu, exclusive: %d", stream_id, 27550aadb33SDmitri Tikhonov dep_stream_id, weight, exclusive); 27650aadb33SDmitri Tikhonov } 27750aadb33SDmitri Tikhonov 27850aadb33SDmitri Tikhonov for (i = 0; i < headers->count; ++i) 27950aadb33SDmitri Tikhonov LCID(" %.*s: %.*s", 28050aadb33SDmitri Tikhonov (int) headers->headers[i].name.iov_len, 28150aadb33SDmitri Tikhonov (char *) headers->headers[i].name.iov_base, 28250aadb33SDmitri Tikhonov (int) headers->headers[i].value.iov_len, 28350aadb33SDmitri Tikhonov (char *) headers->headers[i].value.iov_base); 28450aadb33SDmitri Tikhonov} 28550aadb33SDmitri Tikhonov 28650aadb33SDmitri Tikhonov 28750aadb33SDmitri Tikhonovvoid 28850aadb33SDmitri Tikhonovlsquic_ev_log_generated_http_push_promise (lsquic_cid_t cid, 28950aadb33SDmitri Tikhonov uint32_t stream_id, uint32_t promised_stream_id, 29050aadb33SDmitri Tikhonov const struct lsquic_http_headers *headers, 29150aadb33SDmitri Tikhonov const struct lsquic_http_headers *extra_headers) 29250aadb33SDmitri Tikhonov{ 29350aadb33SDmitri Tikhonov int i; 29450aadb33SDmitri Tikhonov 29550aadb33SDmitri Tikhonov LCID("generated HTTP PUSH_PROMISE for stream %"PRIu32"; promised stream %" 29650aadb33SDmitri Tikhonov PRIu32, stream_id, promised_stream_id); 29750aadb33SDmitri Tikhonov 29850aadb33SDmitri Tikhonov for (i = 0; i < headers->count; ++i) 29950aadb33SDmitri Tikhonov LCID(" %.*s: %.*s", 30050aadb33SDmitri Tikhonov (int) headers->headers[i].name.iov_len, 30150aadb33SDmitri Tikhonov (char *) headers->headers[i].name.iov_base, 30250aadb33SDmitri Tikhonov (int) headers->headers[i].value.iov_len, 30350aadb33SDmitri Tikhonov (char *) headers->headers[i].value.iov_base); 30450aadb33SDmitri Tikhonov 30550aadb33SDmitri Tikhonov if (extra_headers) 30650aadb33SDmitri Tikhonov for (i = 0; i < extra_headers->count; ++i) 30750aadb33SDmitri Tikhonov LCID(" %.*s: %.*s", 30850aadb33SDmitri Tikhonov (int) extra_headers->headers[i].name.iov_len, 30950aadb33SDmitri Tikhonov (char *) extra_headers->headers[i].name.iov_base, 31050aadb33SDmitri Tikhonov (int) extra_headers->headers[i].value.iov_len, 31150aadb33SDmitri Tikhonov (char *) extra_headers->headers[i].value.iov_base); 31250aadb33SDmitri Tikhonov} 31350aadb33SDmitri Tikhonov 31450aadb33SDmitri Tikhonov 315