lsquic_qlog.c revision 7cf121d7
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 3755cd0b38SDmitri Tikhonovlsquic_qlog_create_connection (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 9755cd0b38SDmitri Tikhonovlsquic_qlog_packet_rx (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{ 10255cd0b38SDmitri Tikhonov int i, cur = 0, first = 0, ret = 0; 10355cd0b38SDmitri Tikhonov size_t raw_bytes_written; 10455cd0b38SDmitri Tikhonov char data[QLOG_PACKET_RAW_SZ]; 10555cd0b38SDmitri Tikhonov char frame_list[QLOG_FRAME_LIST_MAX + 1]; 10655cd0b38SDmitri Tikhonov 10755cd0b38SDmitri Tikhonov if (!packet_in || !packet_in_data) 10855cd0b38SDmitri Tikhonov return; 10955cd0b38SDmitri Tikhonov 11055cd0b38SDmitri Tikhonov frame_list[cur] = '\0'; 11155cd0b38SDmitri Tikhonov if (packet_in->pi_frame_types) 11255cd0b38SDmitri Tikhonov { 11355cd0b38SDmitri Tikhonov cur = sprintf(frame_list, "%s", QLOG_FRAME_LIST_PREFIX); 11455cd0b38SDmitri Tikhonov for (i = 0; i < N_QUIC_FRAMES; i++) 11555cd0b38SDmitri Tikhonov if (packet_in->pi_frame_types & (1 << i)) 11655cd0b38SDmitri Tikhonov { 11755cd0b38SDmitri Tikhonov ret = snprintf(frame_list + cur, 11855cd0b38SDmitri Tikhonov QLOG_FRAME_LIST_MAX - cur, 11955cd0b38SDmitri Tikhonov /* prefix + FRAME_NAME + suffix */ 12055cd0b38SDmitri Tikhonov "%s%s%s", 12155cd0b38SDmitri Tikhonov /* skip comma in prefix if first frame */ 1229b4d33c7SDmitri Tikhonov (first++ ? 1239b4d33c7SDmitri Tikhonov QLOG_FRAME_DICT_PREFIX_COMMA : 1249b4d33c7SDmitri Tikhonov QLOG_FRAME_DICT_PREFIX), 12555cd0b38SDmitri Tikhonov QUIC_FRAME_NAME(i), 12655cd0b38SDmitri Tikhonov QLOG_FRAME_DICT_SUFFIX); 12755cd0b38SDmitri Tikhonov if ((unsigned)ret > QLOG_FRAME_LIST_MAX - cur) 12855cd0b38SDmitri Tikhonov break; 12955cd0b38SDmitri Tikhonov cur += ret; 13055cd0b38SDmitri Tikhonov } 13155cd0b38SDmitri Tikhonov if ((unsigned)cur <= QLOG_FRAME_LIST_MAX) 13255cd0b38SDmitri Tikhonov sprintf(frame_list + cur, "%s", QLOG_FRAME_LIST_SUFFIX); 13355cd0b38SDmitri Tikhonov } 13455cd0b38SDmitri Tikhonov 13555cd0b38SDmitri Tikhonov raw_bytes_written = lsquic_hex_encode(packet_in_data, packet_in_size, 13655cd0b38SDmitri Tikhonov data, QLOG_PACKET_RAW_SZ); 13755cd0b38SDmitri Tikhonov 13855cd0b38SDmitri Tikhonov LCID("[%" PRIu64 ",\"TRANSPORT\",\"PACKET_RX\",\"LINE\"," 13955cd0b38SDmitri Tikhonov "{" 14055cd0b38SDmitri Tikhonov "\"raw\":\"%s%s\"," 14155cd0b38SDmitri Tikhonov "\"header\":{" 14255cd0b38SDmitri Tikhonov "\"type\":\"%s\"," 14355cd0b38SDmitri Tikhonov "\"payload_length\":\"%d\"," 1449b4d33c7SDmitri Tikhonov "\"packet_number\":\"%" PRIu64 "\"" 14555cd0b38SDmitri Tikhonov "}%s" 14655cd0b38SDmitri Tikhonov "}]", 14755cd0b38SDmitri Tikhonov packet_in->pi_received, 14855cd0b38SDmitri Tikhonov data, (raw_bytes_written < packet_in_size) ? "..." : "", 14955cd0b38SDmitri Tikhonov lsquic_hety2str[packet_in->pi_header_type], 15055cd0b38SDmitri Tikhonov packet_in->pi_data_sz, 15155cd0b38SDmitri Tikhonov packet_in->pi_packno, 15255cd0b38SDmitri Tikhonov frame_list); 15355cd0b38SDmitri Tikhonov} 15455cd0b38SDmitri Tikhonov 15555cd0b38SDmitri Tikhonov 15655cd0b38SDmitri Tikhonovvoid 15755cd0b38SDmitri Tikhonovlsquic_qlog_hsk_completed (lsquic_cid_t cid) 15855cd0b38SDmitri Tikhonov{ 15955cd0b38SDmitri Tikhonov LCID("[%" PRIu64 ",\"CONNECTIVITY\",\"HANDSHAKE\",\"PACKET_RX\"," 16055cd0b38SDmitri Tikhonov "{\"status\":\"complete\"}]", lsquic_time_now()); 16155cd0b38SDmitri Tikhonov} 16255cd0b38SDmitri Tikhonov 16355cd0b38SDmitri Tikhonov 16455cd0b38SDmitri Tikhonovvoid 16555cd0b38SDmitri Tikhonovlsquic_qlog_zero_rtt (lsquic_cid_t cid) 16655cd0b38SDmitri Tikhonov{ 16755cd0b38SDmitri Tikhonov LCID("[%" PRIu64 ",\"RECOVERY\",\"RTT_UPDATE\",\"PACKET_RX\"," 16855cd0b38SDmitri Tikhonov "{\"zero_rtt\":\"successful\"}]", lsquic_time_now()); 16955cd0b38SDmitri Tikhonov} 17055cd0b38SDmitri Tikhonov 17155cd0b38SDmitri Tikhonov 17255cd0b38SDmitri Tikhonovvoid 17355cd0b38SDmitri Tikhonovlsquic_qlog_check_certs (lsquic_cid_t cid, const lsquic_str_t **certs, 17455cd0b38SDmitri Tikhonov size_t count) 17555cd0b38SDmitri Tikhonov{ 17655cd0b38SDmitri Tikhonov size_t i; 17755cd0b38SDmitri Tikhonov size_t buf_sz = 0; 17855cd0b38SDmitri Tikhonov char *buf = NULL; 17955cd0b38SDmitri Tikhonov char *new_buf; 18055cd0b38SDmitri Tikhonov 18155cd0b38SDmitri Tikhonov for (i = 0; i < count; i++) 18255cd0b38SDmitri Tikhonov { 18355cd0b38SDmitri Tikhonov if (buf_sz < (lsquic_str_len(certs[i]) * 2) + 1) 18455cd0b38SDmitri Tikhonov { 18555cd0b38SDmitri Tikhonov buf_sz = (lsquic_str_len(certs[i]) * 2) + 1; 18655cd0b38SDmitri Tikhonov new_buf = realloc(buf, buf_sz); 18755cd0b38SDmitri Tikhonov if (!new_buf) 18855cd0b38SDmitri Tikhonov break; 18955cd0b38SDmitri Tikhonov buf = new_buf; 19055cd0b38SDmitri Tikhonov } 19155cd0b38SDmitri Tikhonov lsquic_hex_encode(lsquic_str_cstr(certs[i]), lsquic_str_len(certs[i]), 19255cd0b38SDmitri Tikhonov buf, buf_sz); 19355cd0b38SDmitri Tikhonov LCID("[%" PRIu64 ",\"SECURITY\",\"CHECK_CERT\",\"CERTLOG\"," 19455cd0b38SDmitri Tikhonov "{\"certificate\":\"%s\"}]", lsquic_time_now(), buf); 19555cd0b38SDmitri Tikhonov } 19655cd0b38SDmitri Tikhonov if (buf) 19755cd0b38SDmitri Tikhonov free(buf); 19855cd0b38SDmitri Tikhonov} 19955cd0b38SDmitri Tikhonov 20055cd0b38SDmitri Tikhonov 20155cd0b38SDmitri Tikhonovvoid 20255cd0b38SDmitri Tikhonovlsquic_qlog_version_negotiation (lsquic_cid_t cid, 20355cd0b38SDmitri Tikhonov const char *action, const char *ver) 20455cd0b38SDmitri Tikhonov{ 20555cd0b38SDmitri Tikhonov char *trig; 20655cd0b38SDmitri Tikhonov 20755cd0b38SDmitri Tikhonov if (!action || !ver) 20855cd0b38SDmitri Tikhonov return; 20955cd0b38SDmitri Tikhonov if (strcmp(action, "proposed") == 0) 21055cd0b38SDmitri Tikhonov trig = "LINE"; 21155cd0b38SDmitri Tikhonov else if (strcmp(action, "agreed") == 0) 21255cd0b38SDmitri Tikhonov trig = "PACKET_RX"; 21355cd0b38SDmitri Tikhonov else 21455cd0b38SDmitri Tikhonov return; 21555cd0b38SDmitri Tikhonov LCID("[%" PRIu64 ",\"CONNECTIVITY\",\"VERNEG\",\"%s\"," 21655cd0b38SDmitri Tikhonov "{\"%s_version\":\"%s\"}]", lsquic_time_now(), trig, action, ver); 21755cd0b38SDmitri Tikhonov} 218