lsquic_qlog.c revision a0e1aeee
155cd0b38SDmitri Tikhonov/* Copyright (c) 2017 - 2019 LiteSpeed Technologies Inc. See LICENSE. */ 255cd0b38SDmitri Tikhonov#include <stdlib.h> 355cd0b38SDmitri Tikhonov#include <stdio.h> 455cd0b38SDmitri Tikhonov#include <errno.h> 555cd0b38SDmitri Tikhonov#include <inttypes.h> 655cd0b38SDmitri Tikhonov#include <string.h> 755cd0b38SDmitri Tikhonov#include <sys/queue.h> 87cf121d7SStephen Petrides#ifdef WIN32 97cf121d7SStephen Petrides#include <Ws2tcpip.h> 107cf121d7SStephen Petrides#else 117cf121d7SStephen Petrides#include <sys/types.h> 127cf121d7SStephen Petrides#include <sys/socket.h> 137cf121d7SStephen Petrides#include <netinet/in.h> 1455cd0b38SDmitri Tikhonov#include <arpa/inet.h> 157cf121d7SStephen Petrides#endif 1655cd0b38SDmitri Tikhonov 1755cd0b38SDmitri Tikhonov#include "lsquic.h" 1855cd0b38SDmitri Tikhonov#include "lsquic_types.h" 1955cd0b38SDmitri Tikhonov#include "lsquic_int_types.h" 2055cd0b38SDmitri Tikhonov#include "lsquic_packet_common.h" 2155cd0b38SDmitri Tikhonov#include "lsquic_packet_in.h" 2255cd0b38SDmitri Tikhonov#include "lsquic_packet_out.h" 2355cd0b38SDmitri Tikhonov#include "lsquic_util.h" 2455cd0b38SDmitri Tikhonov#include "lsquic_qlog.h" 2555cd0b38SDmitri Tikhonov 2655cd0b38SDmitri Tikhonov#define LSQUIC_LOGGER_MODULE LSQLM_QLOG 2755cd0b38SDmitri Tikhonov#include "lsquic_logger.h" 2855cd0b38SDmitri Tikhonov 2955cd0b38SDmitri Tikhonov#define LSQUIC_LOG_CONN_ID cid 3055cd0b38SDmitri Tikhonov#define LCID(...) LSQ_LOG2(LSQ_LOG_DEBUG, __VA_ARGS__) 3155cd0b38SDmitri Tikhonov 3255cd0b38SDmitri Tikhonov#define MAX_IP_LEN INET6_ADDRSTRLEN 3355cd0b38SDmitri Tikhonov#define QLOG_PACKET_RAW_SZ 64 3455cd0b38SDmitri Tikhonov 3555cd0b38SDmitri Tikhonov 3655cd0b38SDmitri Tikhonovvoid 375392f7a3SLiteSpeed Techlsquic_qlog_create_connection (const lsquic_cid_t* cid, 3855cd0b38SDmitri Tikhonov const struct sockaddr *local_sa, 3955cd0b38SDmitri Tikhonov const struct sockaddr *peer_sa) 4055cd0b38SDmitri Tikhonov{ 4155cd0b38SDmitri Tikhonov uint32_t ip_version, srcport, dstport; 4255cd0b38SDmitri Tikhonov struct sockaddr_in *local4, *peer4; 4355cd0b38SDmitri Tikhonov struct sockaddr_in6 *local6, *peer6; 4455cd0b38SDmitri Tikhonov char srcip[MAX_IP_LEN], dstip[MAX_IP_LEN]; 4555cd0b38SDmitri Tikhonov 4655cd0b38SDmitri Tikhonov if (!local_sa || !peer_sa) 4755cd0b38SDmitri Tikhonov return; 4855cd0b38SDmitri Tikhonov 4955cd0b38SDmitri Tikhonov if (local_sa->sa_family == AF_INET) 5055cd0b38SDmitri Tikhonov { 5155cd0b38SDmitri Tikhonov ip_version = 4; 5255cd0b38SDmitri Tikhonov local4 = (struct sockaddr_in *)local_sa; 5355cd0b38SDmitri Tikhonov peer4 = (struct sockaddr_in *)peer_sa; 5455cd0b38SDmitri Tikhonov srcport = ntohs(local4->sin_port); 5555cd0b38SDmitri Tikhonov dstport = ntohs(peer4->sin_port); 5655cd0b38SDmitri Tikhonov inet_ntop(local4->sin_family, &local4->sin_addr, srcip, MAX_IP_LEN); 5755cd0b38SDmitri Tikhonov inet_ntop(peer4->sin_family, &peer4->sin_addr, dstip, MAX_IP_LEN); 5855cd0b38SDmitri Tikhonov } 5955cd0b38SDmitri Tikhonov else if (local_sa->sa_family == AF_INET6) 6055cd0b38SDmitri Tikhonov { 6155cd0b38SDmitri Tikhonov ip_version = 6; 6255cd0b38SDmitri Tikhonov local6 = (struct sockaddr_in6 *)local_sa; 6355cd0b38SDmitri Tikhonov peer6 = (struct sockaddr_in6 *)peer_sa; 6455cd0b38SDmitri Tikhonov srcport = ntohs(local6->sin6_port); 6555cd0b38SDmitri Tikhonov dstport = ntohs(peer6->sin6_port); 6655cd0b38SDmitri Tikhonov inet_ntop(local6->sin6_family, &local6->sin6_addr, srcip, MAX_IP_LEN); 6755cd0b38SDmitri Tikhonov inet_ntop(peer6->sin6_family, &peer6->sin6_addr, dstip, MAX_IP_LEN); 6855cd0b38SDmitri Tikhonov } 6955cd0b38SDmitri Tikhonov else 7055cd0b38SDmitri Tikhonov return; 7155cd0b38SDmitri Tikhonov 7255cd0b38SDmitri Tikhonov LCID("[%" PRIu64 ",\"CONNECTIVITY\",\"NEW_CONNECTION\",\"LINE\"," 7355cd0b38SDmitri Tikhonov "{" 7455cd0b38SDmitri Tikhonov "\"ip_version\":\"%u\"," 7555cd0b38SDmitri Tikhonov "\"srcip\":\"%s\"," 7655cd0b38SDmitri Tikhonov "\"dstip\":\"%s\"," 7755cd0b38SDmitri Tikhonov "\"srcport\":\"%u\"," 7855cd0b38SDmitri Tikhonov "\"dstport\":\"%u\"" 7955cd0b38SDmitri Tikhonov "}]", 8055cd0b38SDmitri Tikhonov lsquic_time_now(), ip_version, srcip, dstip, srcport, dstport); 8155cd0b38SDmitri Tikhonov} 8255cd0b38SDmitri Tikhonov 839b4d33c7SDmitri Tikhonov#define QLOG_FRAME_DICT_PREFIX_COMMA ",{\"frame_type\":\"" 849b4d33c7SDmitri Tikhonov#define QLOG_FRAME_DICT_PREFIX "{\"frame_type\":\"" 8555cd0b38SDmitri Tikhonov#define QLOG_FRAME_DICT_SUFFIX "\"}" 8655cd0b38SDmitri Tikhonov#define QLOG_FRAME_LIST_PREFIX ",\"frames\":[" 8755cd0b38SDmitri Tikhonov#define QLOG_FRAME_LIST_SUFFIX "]" 8855cd0b38SDmitri Tikhonov#define QLOG_FRAME_LIST_MAX \ 8955cd0b38SDmitri Tikhonov sizeof(QLOG_FRAME_LIST_PREFIX) + \ 9055cd0b38SDmitri Tikhonov sizeof(QLOG_FRAME_LIST_SUFFIX) + \ 9155cd0b38SDmitri Tikhonov lsquic_frame_types_str_sz + \ 9255cd0b38SDmitri Tikhonov (N_QUIC_FRAMES * \ 939b4d33c7SDmitri Tikhonov (sizeof(QLOG_FRAME_DICT_PREFIX_COMMA) + \ 9455cd0b38SDmitri Tikhonov sizeof(QLOG_FRAME_DICT_SUFFIX))) 9555cd0b38SDmitri Tikhonov 9655cd0b38SDmitri Tikhonovvoid 975392f7a3SLiteSpeed Techlsquic_qlog_packet_rx (const lsquic_cid_t* cid, 9855cd0b38SDmitri Tikhonov const struct lsquic_packet_in *packet_in, 9955cd0b38SDmitri Tikhonov const unsigned char *packet_in_data, 10055cd0b38SDmitri Tikhonov size_t packet_in_size) 10155cd0b38SDmitri Tikhonov{ 102a0e1aeeeSDmitri Tikhonov int i, first, ret; 103a0e1aeeeSDmitri Tikhonov unsigned cur; 10455cd0b38SDmitri Tikhonov size_t raw_bytes_written; 10555cd0b38SDmitri Tikhonov char data[QLOG_PACKET_RAW_SZ]; 10655cd0b38SDmitri Tikhonov char frame_list[QLOG_FRAME_LIST_MAX + 1]; 10755cd0b38SDmitri Tikhonov 10855cd0b38SDmitri Tikhonov if (!packet_in || !packet_in_data) 10955cd0b38SDmitri Tikhonov return; 11055cd0b38SDmitri Tikhonov 11155cd0b38SDmitri Tikhonov if (packet_in->pi_frame_types) 11255cd0b38SDmitri Tikhonov { 113a0e1aeeeSDmitri Tikhonov memcpy(frame_list, QLOG_FRAME_LIST_PREFIX, 114a0e1aeeeSDmitri Tikhonov sizeof(QLOG_FRAME_LIST_PREFIX)); 115a0e1aeeeSDmitri Tikhonov cur = sizeof(QLOG_FRAME_LIST_PREFIX) - 1; 116a0e1aeeeSDmitri Tikhonov for (i = 0, first = 0; i < N_QUIC_FRAMES; i++) 11755cd0b38SDmitri Tikhonov if (packet_in->pi_frame_types & (1 << i)) 11855cd0b38SDmitri Tikhonov { 11955cd0b38SDmitri Tikhonov ret = snprintf(frame_list + cur, 12055cd0b38SDmitri Tikhonov QLOG_FRAME_LIST_MAX - cur, 12155cd0b38SDmitri Tikhonov /* prefix + FRAME_NAME + suffix */ 12255cd0b38SDmitri Tikhonov "%s%s%s", 12355cd0b38SDmitri Tikhonov /* skip comma in prefix if first frame */ 1249b4d33c7SDmitri Tikhonov (first++ ? 1259b4d33c7SDmitri Tikhonov QLOG_FRAME_DICT_PREFIX_COMMA : 1269b4d33c7SDmitri Tikhonov QLOG_FRAME_DICT_PREFIX), 12755cd0b38SDmitri Tikhonov QUIC_FRAME_NAME(i), 12855cd0b38SDmitri Tikhonov QLOG_FRAME_DICT_SUFFIX); 129a0e1aeeeSDmitri Tikhonov if (ret < 0 || (unsigned)ret > QLOG_FRAME_LIST_MAX - cur) 13055cd0b38SDmitri Tikhonov break; 13155cd0b38SDmitri Tikhonov cur += ret; 13255cd0b38SDmitri Tikhonov } 133a0e1aeeeSDmitri Tikhonov if (cur + sizeof(QLOG_FRAME_LIST_SUFFIX) <= QLOG_FRAME_LIST_MAX) 134a0e1aeeeSDmitri Tikhonov memcpy(frame_list + cur, QLOG_FRAME_LIST_SUFFIX, 135a0e1aeeeSDmitri Tikhonov sizeof(QLOG_FRAME_LIST_SUFFIX)); 13655cd0b38SDmitri Tikhonov } 137a0e1aeeeSDmitri Tikhonov else 138a0e1aeeeSDmitri Tikhonov frame_list[0] = '\0'; 13955cd0b38SDmitri Tikhonov 14055cd0b38SDmitri Tikhonov raw_bytes_written = lsquic_hex_encode(packet_in_data, packet_in_size, 14155cd0b38SDmitri Tikhonov data, QLOG_PACKET_RAW_SZ); 14255cd0b38SDmitri Tikhonov 14355cd0b38SDmitri Tikhonov LCID("[%" PRIu64 ",\"TRANSPORT\",\"PACKET_RX\",\"LINE\"," 14455cd0b38SDmitri Tikhonov "{" 14555cd0b38SDmitri Tikhonov "\"raw\":\"%s%s\"," 14655cd0b38SDmitri Tikhonov "\"header\":{" 14755cd0b38SDmitri Tikhonov "\"type\":\"%s\"," 14855cd0b38SDmitri Tikhonov "\"payload_length\":\"%d\"," 1499b4d33c7SDmitri Tikhonov "\"packet_number\":\"%" PRIu64 "\"" 15055cd0b38SDmitri Tikhonov "}%s" 15155cd0b38SDmitri Tikhonov "}]", 15255cd0b38SDmitri Tikhonov packet_in->pi_received, 15355cd0b38SDmitri Tikhonov data, (raw_bytes_written < packet_in_size) ? "..." : "", 15455cd0b38SDmitri Tikhonov lsquic_hety2str[packet_in->pi_header_type], 15555cd0b38SDmitri Tikhonov packet_in->pi_data_sz, 15655cd0b38SDmitri Tikhonov packet_in->pi_packno, 15755cd0b38SDmitri Tikhonov frame_list); 15855cd0b38SDmitri Tikhonov} 15955cd0b38SDmitri Tikhonov 16055cd0b38SDmitri Tikhonov 16155cd0b38SDmitri Tikhonovvoid 1625392f7a3SLiteSpeed Techlsquic_qlog_hsk_completed (const lsquic_cid_t* cid) 16355cd0b38SDmitri Tikhonov{ 16455cd0b38SDmitri Tikhonov LCID("[%" PRIu64 ",\"CONNECTIVITY\",\"HANDSHAKE\",\"PACKET_RX\"," 16555cd0b38SDmitri Tikhonov "{\"status\":\"complete\"}]", lsquic_time_now()); 16655cd0b38SDmitri Tikhonov} 16755cd0b38SDmitri Tikhonov 16855cd0b38SDmitri Tikhonov 16955cd0b38SDmitri Tikhonovvoid 1705392f7a3SLiteSpeed Techlsquic_qlog_zero_rtt (const lsquic_cid_t* cid) 17155cd0b38SDmitri Tikhonov{ 17255cd0b38SDmitri Tikhonov LCID("[%" PRIu64 ",\"RECOVERY\",\"RTT_UPDATE\",\"PACKET_RX\"," 17355cd0b38SDmitri Tikhonov "{\"zero_rtt\":\"successful\"}]", lsquic_time_now()); 17455cd0b38SDmitri Tikhonov} 17555cd0b38SDmitri Tikhonov 17655cd0b38SDmitri Tikhonov 17755cd0b38SDmitri Tikhonovvoid 1785392f7a3SLiteSpeed Techlsquic_qlog_check_certs (const lsquic_cid_t* cid, const lsquic_str_t **certs, 17955cd0b38SDmitri Tikhonov size_t count) 18055cd0b38SDmitri Tikhonov{ 18155cd0b38SDmitri Tikhonov size_t i; 18255cd0b38SDmitri Tikhonov size_t buf_sz = 0; 18355cd0b38SDmitri Tikhonov char *buf = NULL; 18455cd0b38SDmitri Tikhonov char *new_buf; 18555cd0b38SDmitri Tikhonov 18655cd0b38SDmitri Tikhonov for (i = 0; i < count; i++) 18755cd0b38SDmitri Tikhonov { 18855cd0b38SDmitri Tikhonov if (buf_sz < (lsquic_str_len(certs[i]) * 2) + 1) 18955cd0b38SDmitri Tikhonov { 19055cd0b38SDmitri Tikhonov buf_sz = (lsquic_str_len(certs[i]) * 2) + 1; 19155cd0b38SDmitri Tikhonov new_buf = realloc(buf, buf_sz); 19255cd0b38SDmitri Tikhonov if (!new_buf) 19355cd0b38SDmitri Tikhonov break; 19455cd0b38SDmitri Tikhonov buf = new_buf; 19555cd0b38SDmitri Tikhonov } 19655cd0b38SDmitri Tikhonov lsquic_hex_encode(lsquic_str_cstr(certs[i]), lsquic_str_len(certs[i]), 19755cd0b38SDmitri Tikhonov buf, buf_sz); 19855cd0b38SDmitri Tikhonov LCID("[%" PRIu64 ",\"SECURITY\",\"CHECK_CERT\",\"CERTLOG\"," 19955cd0b38SDmitri Tikhonov "{\"certificate\":\"%s\"}]", lsquic_time_now(), buf); 20055cd0b38SDmitri Tikhonov } 20155cd0b38SDmitri Tikhonov if (buf) 20255cd0b38SDmitri Tikhonov free(buf); 20355cd0b38SDmitri Tikhonov} 20455cd0b38SDmitri Tikhonov 20555cd0b38SDmitri Tikhonov 20655cd0b38SDmitri Tikhonovvoid 2075392f7a3SLiteSpeed Techlsquic_qlog_version_negotiation (const lsquic_cid_t* cid, 20855cd0b38SDmitri Tikhonov const char *action, const char *ver) 20955cd0b38SDmitri Tikhonov{ 21055cd0b38SDmitri Tikhonov char *trig; 21155cd0b38SDmitri Tikhonov 21255cd0b38SDmitri Tikhonov if (!action || !ver) 21355cd0b38SDmitri Tikhonov return; 21455cd0b38SDmitri Tikhonov if (strcmp(action, "proposed") == 0) 21555cd0b38SDmitri Tikhonov trig = "LINE"; 2165392f7a3SLiteSpeed Tech else if (strcmp(action, "supports") == 0 || strcmp(action, "agreed") == 0) 21755cd0b38SDmitri Tikhonov trig = "PACKET_RX"; 21855cd0b38SDmitri Tikhonov else 21955cd0b38SDmitri Tikhonov return; 22055cd0b38SDmitri Tikhonov LCID("[%" PRIu64 ",\"CONNECTIVITY\",\"VERNEG\",\"%s\"," 22155cd0b38SDmitri Tikhonov "{\"%s_version\":\"%s\"}]", lsquic_time_now(), trig, action, ver); 22255cd0b38SDmitri Tikhonov} 223