lsquic_qlog.c revision 7483dee0
17d09751dSDmitri Tikhonov/* Copyright (c) 2017 - 2020 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 17b55a5117SDmitri Tikhonov#include <openssl/ssl.h> 18b55a5117SDmitri Tikhonov#include <openssl/x509.h> 19b55a5117SDmitri Tikhonov 2055cd0b38SDmitri Tikhonov#include "lsquic.h" 2155cd0b38SDmitri Tikhonov#include "lsquic_types.h" 2255cd0b38SDmitri Tikhonov#include "lsquic_int_types.h" 2355cd0b38SDmitri Tikhonov#include "lsquic_packet_common.h" 2455cd0b38SDmitri Tikhonov#include "lsquic_packet_in.h" 2555cd0b38SDmitri Tikhonov#include "lsquic_packet_out.h" 2655cd0b38SDmitri Tikhonov#include "lsquic_util.h" 2755cd0b38SDmitri Tikhonov#include "lsquic_qlog.h" 2855cd0b38SDmitri Tikhonov 2955cd0b38SDmitri Tikhonov#define LSQUIC_LOGGER_MODULE LSQLM_QLOG 3055cd0b38SDmitri Tikhonov#include "lsquic_logger.h" 3155cd0b38SDmitri Tikhonov 3255cd0b38SDmitri Tikhonov#define LSQUIC_LOG_CONN_ID cid 3355cd0b38SDmitri Tikhonov#define LCID(...) LSQ_LOG2(LSQ_LOG_DEBUG, __VA_ARGS__) 3455cd0b38SDmitri Tikhonov 3555cd0b38SDmitri Tikhonov#define MAX_IP_LEN INET6_ADDRSTRLEN 3655cd0b38SDmitri Tikhonov#define QLOG_PACKET_RAW_SZ 64 3755cd0b38SDmitri Tikhonov 3855cd0b38SDmitri Tikhonov 3955cd0b38SDmitri Tikhonovvoid 405392f7a3SLiteSpeed Techlsquic_qlog_create_connection (const lsquic_cid_t* cid, 4155cd0b38SDmitri Tikhonov const struct sockaddr *local_sa, 4255cd0b38SDmitri Tikhonov const struct sockaddr *peer_sa) 4355cd0b38SDmitri Tikhonov{ 4455cd0b38SDmitri Tikhonov uint32_t ip_version, srcport, dstport; 4555cd0b38SDmitri Tikhonov struct sockaddr_in *local4, *peer4; 4655cd0b38SDmitri Tikhonov struct sockaddr_in6 *local6, *peer6; 4755cd0b38SDmitri Tikhonov char srcip[MAX_IP_LEN], dstip[MAX_IP_LEN]; 4855cd0b38SDmitri Tikhonov 4955cd0b38SDmitri Tikhonov if (!local_sa || !peer_sa) 5055cd0b38SDmitri Tikhonov return; 5155cd0b38SDmitri Tikhonov 5255cd0b38SDmitri Tikhonov if (local_sa->sa_family == AF_INET) 5355cd0b38SDmitri Tikhonov { 5455cd0b38SDmitri Tikhonov ip_version = 4; 5555cd0b38SDmitri Tikhonov local4 = (struct sockaddr_in *)local_sa; 5655cd0b38SDmitri Tikhonov peer4 = (struct sockaddr_in *)peer_sa; 5755cd0b38SDmitri Tikhonov srcport = ntohs(local4->sin_port); 5855cd0b38SDmitri Tikhonov dstport = ntohs(peer4->sin_port); 5955cd0b38SDmitri Tikhonov inet_ntop(local4->sin_family, &local4->sin_addr, srcip, MAX_IP_LEN); 6055cd0b38SDmitri Tikhonov inet_ntop(peer4->sin_family, &peer4->sin_addr, dstip, MAX_IP_LEN); 6155cd0b38SDmitri Tikhonov } 6255cd0b38SDmitri Tikhonov else if (local_sa->sa_family == AF_INET6) 6355cd0b38SDmitri Tikhonov { 6455cd0b38SDmitri Tikhonov ip_version = 6; 6555cd0b38SDmitri Tikhonov local6 = (struct sockaddr_in6 *)local_sa; 6655cd0b38SDmitri Tikhonov peer6 = (struct sockaddr_in6 *)peer_sa; 6755cd0b38SDmitri Tikhonov srcport = ntohs(local6->sin6_port); 6855cd0b38SDmitri Tikhonov dstport = ntohs(peer6->sin6_port); 6955cd0b38SDmitri Tikhonov inet_ntop(local6->sin6_family, &local6->sin6_addr, srcip, MAX_IP_LEN); 7055cd0b38SDmitri Tikhonov inet_ntop(peer6->sin6_family, &peer6->sin6_addr, dstip, MAX_IP_LEN); 7155cd0b38SDmitri Tikhonov } 7255cd0b38SDmitri Tikhonov else 7355cd0b38SDmitri Tikhonov return; 7455cd0b38SDmitri Tikhonov 7555cd0b38SDmitri Tikhonov LCID("[%" PRIu64 ",\"CONNECTIVITY\",\"NEW_CONNECTION\",\"LINE\"," 7655cd0b38SDmitri Tikhonov "{" 7755cd0b38SDmitri Tikhonov "\"ip_version\":\"%u\"," 7855cd0b38SDmitri Tikhonov "\"srcip\":\"%s\"," 7955cd0b38SDmitri Tikhonov "\"dstip\":\"%s\"," 8055cd0b38SDmitri Tikhonov "\"srcport\":\"%u\"," 8155cd0b38SDmitri Tikhonov "\"dstport\":\"%u\"" 8255cd0b38SDmitri Tikhonov "}]", 8355cd0b38SDmitri Tikhonov lsquic_time_now(), ip_version, srcip, dstip, srcport, dstport); 8455cd0b38SDmitri Tikhonov} 8555cd0b38SDmitri Tikhonov 867483dee0SDmitri Tikhonov 879b4d33c7SDmitri Tikhonov#define QLOG_FRAME_DICT_PREFIX_COMMA ",{\"frame_type\":\"" 889b4d33c7SDmitri Tikhonov#define QLOG_FRAME_DICT_PREFIX "{\"frame_type\":\"" 8955cd0b38SDmitri Tikhonov#define QLOG_FRAME_DICT_SUFFIX "\"}" 9055cd0b38SDmitri Tikhonov#define QLOG_FRAME_LIST_PREFIX ",\"frames\":[" 9155cd0b38SDmitri Tikhonov#define QLOG_FRAME_LIST_SUFFIX "]" 9255cd0b38SDmitri Tikhonov#define QLOG_FRAME_LIST_MAX \ 9355cd0b38SDmitri Tikhonov sizeof(QLOG_FRAME_LIST_PREFIX) + \ 9455cd0b38SDmitri Tikhonov sizeof(QLOG_FRAME_LIST_SUFFIX) + \ 9555cd0b38SDmitri Tikhonov lsquic_frame_types_str_sz + \ 9655cd0b38SDmitri Tikhonov (N_QUIC_FRAMES * \ 979b4d33c7SDmitri Tikhonov (sizeof(QLOG_FRAME_DICT_PREFIX_COMMA) + \ 9855cd0b38SDmitri Tikhonov sizeof(QLOG_FRAME_DICT_SUFFIX))) 9955cd0b38SDmitri Tikhonov 10055cd0b38SDmitri Tikhonovvoid 1015392f7a3SLiteSpeed Techlsquic_qlog_packet_rx (const lsquic_cid_t* cid, 10255cd0b38SDmitri Tikhonov const struct lsquic_packet_in *packet_in, 10355cd0b38SDmitri Tikhonov const unsigned char *packet_in_data, 10455cd0b38SDmitri Tikhonov size_t packet_in_size) 10555cd0b38SDmitri Tikhonov{ 106a0e1aeeeSDmitri Tikhonov int i, first, ret; 107a0e1aeeeSDmitri Tikhonov unsigned cur; 10855cd0b38SDmitri Tikhonov size_t raw_bytes_written; 10955cd0b38SDmitri Tikhonov char data[QLOG_PACKET_RAW_SZ]; 11055cd0b38SDmitri Tikhonov char frame_list[QLOG_FRAME_LIST_MAX + 1]; 11155cd0b38SDmitri Tikhonov 11255cd0b38SDmitri Tikhonov if (!packet_in || !packet_in_data) 11355cd0b38SDmitri Tikhonov return; 11455cd0b38SDmitri Tikhonov 11555cd0b38SDmitri Tikhonov if (packet_in->pi_frame_types) 11655cd0b38SDmitri Tikhonov { 117a0e1aeeeSDmitri Tikhonov memcpy(frame_list, QLOG_FRAME_LIST_PREFIX, 118a0e1aeeeSDmitri Tikhonov sizeof(QLOG_FRAME_LIST_PREFIX)); 119a0e1aeeeSDmitri Tikhonov cur = sizeof(QLOG_FRAME_LIST_PREFIX) - 1; 120a0e1aeeeSDmitri Tikhonov for (i = 0, first = 0; i < N_QUIC_FRAMES; i++) 12155cd0b38SDmitri Tikhonov if (packet_in->pi_frame_types & (1 << i)) 12255cd0b38SDmitri Tikhonov { 12355cd0b38SDmitri Tikhonov ret = snprintf(frame_list + cur, 12455cd0b38SDmitri Tikhonov QLOG_FRAME_LIST_MAX - cur, 12555cd0b38SDmitri Tikhonov /* prefix + FRAME_NAME + suffix */ 12655cd0b38SDmitri Tikhonov "%s%s%s", 12755cd0b38SDmitri Tikhonov /* skip comma in prefix if first frame */ 1289b4d33c7SDmitri Tikhonov (first++ ? 1299b4d33c7SDmitri Tikhonov QLOG_FRAME_DICT_PREFIX_COMMA : 1309b4d33c7SDmitri Tikhonov QLOG_FRAME_DICT_PREFIX), 13155cd0b38SDmitri Tikhonov QUIC_FRAME_NAME(i), 13255cd0b38SDmitri Tikhonov QLOG_FRAME_DICT_SUFFIX); 133a0e1aeeeSDmitri Tikhonov if (ret < 0 || (unsigned)ret > QLOG_FRAME_LIST_MAX - cur) 13455cd0b38SDmitri Tikhonov break; 13555cd0b38SDmitri Tikhonov cur += ret; 13655cd0b38SDmitri Tikhonov } 137a0e1aeeeSDmitri Tikhonov if (cur + sizeof(QLOG_FRAME_LIST_SUFFIX) <= QLOG_FRAME_LIST_MAX) 138a0e1aeeeSDmitri Tikhonov memcpy(frame_list + cur, QLOG_FRAME_LIST_SUFFIX, 139a0e1aeeeSDmitri Tikhonov sizeof(QLOG_FRAME_LIST_SUFFIX)); 14055cd0b38SDmitri Tikhonov } 141a0e1aeeeSDmitri Tikhonov else 142a0e1aeeeSDmitri Tikhonov frame_list[0] = '\0'; 14355cd0b38SDmitri Tikhonov 14455cd0b38SDmitri Tikhonov raw_bytes_written = lsquic_hex_encode(packet_in_data, packet_in_size, 14555cd0b38SDmitri Tikhonov data, QLOG_PACKET_RAW_SZ); 14655cd0b38SDmitri Tikhonov 14755cd0b38SDmitri Tikhonov LCID("[%" PRIu64 ",\"TRANSPORT\",\"PACKET_RX\",\"LINE\"," 14855cd0b38SDmitri Tikhonov "{" 14955cd0b38SDmitri Tikhonov "\"raw\":\"%s%s\"," 15055cd0b38SDmitri Tikhonov "\"header\":{" 15155cd0b38SDmitri Tikhonov "\"type\":\"%s\"," 15255cd0b38SDmitri Tikhonov "\"payload_length\":\"%d\"," 1539b4d33c7SDmitri Tikhonov "\"packet_number\":\"%" PRIu64 "\"" 15455cd0b38SDmitri Tikhonov "}%s" 15555cd0b38SDmitri Tikhonov "}]", 15655cd0b38SDmitri Tikhonov packet_in->pi_received, 15755cd0b38SDmitri Tikhonov data, (raw_bytes_written < packet_in_size) ? "..." : "", 15855cd0b38SDmitri Tikhonov lsquic_hety2str[packet_in->pi_header_type], 15955cd0b38SDmitri Tikhonov packet_in->pi_data_sz, 16055cd0b38SDmitri Tikhonov packet_in->pi_packno, 16155cd0b38SDmitri Tikhonov frame_list); 16255cd0b38SDmitri Tikhonov} 16355cd0b38SDmitri Tikhonov 16455cd0b38SDmitri Tikhonov 16555cd0b38SDmitri Tikhonovvoid 1665392f7a3SLiteSpeed Techlsquic_qlog_hsk_completed (const lsquic_cid_t* cid) 16755cd0b38SDmitri Tikhonov{ 16855cd0b38SDmitri Tikhonov LCID("[%" PRIu64 ",\"CONNECTIVITY\",\"HANDSHAKE\",\"PACKET_RX\"," 16955cd0b38SDmitri Tikhonov "{\"status\":\"complete\"}]", lsquic_time_now()); 17055cd0b38SDmitri Tikhonov} 17155cd0b38SDmitri Tikhonov 17255cd0b38SDmitri Tikhonov 17355cd0b38SDmitri Tikhonovvoid 1747483dee0SDmitri Tikhonovlsquic_qlog_sess_resume (const lsquic_cid_t* cid) 17555cd0b38SDmitri Tikhonov{ 17655cd0b38SDmitri Tikhonov LCID("[%" PRIu64 ",\"RECOVERY\",\"RTT_UPDATE\",\"PACKET_RX\"," 17755cd0b38SDmitri Tikhonov "{\"zero_rtt\":\"successful\"}]", lsquic_time_now()); 17855cd0b38SDmitri Tikhonov} 17955cd0b38SDmitri Tikhonov 18055cd0b38SDmitri Tikhonov 18155cd0b38SDmitri Tikhonovvoid 1825392f7a3SLiteSpeed Techlsquic_qlog_check_certs (const lsquic_cid_t* cid, const lsquic_str_t **certs, 18355cd0b38SDmitri Tikhonov size_t count) 18455cd0b38SDmitri Tikhonov{ 18555cd0b38SDmitri Tikhonov size_t i; 18655cd0b38SDmitri Tikhonov size_t buf_sz = 0; 18755cd0b38SDmitri Tikhonov char *buf = NULL; 18855cd0b38SDmitri Tikhonov char *new_buf; 18955cd0b38SDmitri Tikhonov 19055cd0b38SDmitri Tikhonov for (i = 0; i < count; i++) 19155cd0b38SDmitri Tikhonov { 19255cd0b38SDmitri Tikhonov if (buf_sz < (lsquic_str_len(certs[i]) * 2) + 1) 19355cd0b38SDmitri Tikhonov { 19455cd0b38SDmitri Tikhonov buf_sz = (lsquic_str_len(certs[i]) * 2) + 1; 19555cd0b38SDmitri Tikhonov new_buf = realloc(buf, buf_sz); 19655cd0b38SDmitri Tikhonov if (!new_buf) 19755cd0b38SDmitri Tikhonov break; 19855cd0b38SDmitri Tikhonov buf = new_buf; 19955cd0b38SDmitri Tikhonov } 20055cd0b38SDmitri Tikhonov lsquic_hex_encode(lsquic_str_cstr(certs[i]), lsquic_str_len(certs[i]), 20155cd0b38SDmitri Tikhonov buf, buf_sz); 20255cd0b38SDmitri Tikhonov LCID("[%" PRIu64 ",\"SECURITY\",\"CHECK_CERT\",\"CERTLOG\"," 20355cd0b38SDmitri Tikhonov "{\"certificate\":\"%s\"}]", lsquic_time_now(), buf); 20455cd0b38SDmitri Tikhonov } 20555cd0b38SDmitri Tikhonov if (buf) 20655cd0b38SDmitri Tikhonov free(buf); 20755cd0b38SDmitri Tikhonov} 20855cd0b38SDmitri Tikhonov 20955cd0b38SDmitri Tikhonov 21055cd0b38SDmitri Tikhonovvoid 211b55a5117SDmitri Tikhonovlsquic_qlog_cert_chain (const lsquic_cid_t* cid, struct stack_st_X509 *chain) 212b55a5117SDmitri Tikhonov{ 213b55a5117SDmitri Tikhonov X509 *cert; 214b55a5117SDmitri Tikhonov unsigned i; 215b55a5117SDmitri Tikhonov unsigned char *buf; 216b55a5117SDmitri Tikhonov char *hexbuf, *newbuf; 217b55a5117SDmitri Tikhonov size_t hexbuf_sz; 218b55a5117SDmitri Tikhonov int len; 219b55a5117SDmitri Tikhonov lsquic_time_t now; 220b55a5117SDmitri Tikhonov 221b55a5117SDmitri Tikhonov now = lsquic_time_now(); 222b55a5117SDmitri Tikhonov hexbuf = NULL; 223b55a5117SDmitri Tikhonov hexbuf_sz = 0; 224b55a5117SDmitri Tikhonov for (i = 0; i < sk_X509_num(chain); ++i) 225b55a5117SDmitri Tikhonov { 226b55a5117SDmitri Tikhonov cert = sk_X509_value(chain, i); 227b55a5117SDmitri Tikhonov buf = NULL; 228b55a5117SDmitri Tikhonov len = i2d_X509(cert, &buf); 229b55a5117SDmitri Tikhonov if (len <= 0) 230b55a5117SDmitri Tikhonov break; 231b55a5117SDmitri Tikhonov if ((size_t) len * 2 + 1 > hexbuf_sz) 232b55a5117SDmitri Tikhonov { 233b55a5117SDmitri Tikhonov hexbuf_sz = len * 2 + 1; 234b55a5117SDmitri Tikhonov newbuf = realloc(hexbuf, hexbuf_sz); 235b55a5117SDmitri Tikhonov if (!newbuf) 236b55a5117SDmitri Tikhonov break; 237b55a5117SDmitri Tikhonov hexbuf = newbuf; 238b55a5117SDmitri Tikhonov } 239b55a5117SDmitri Tikhonov lsquic_hexstr(buf, (size_t) len, hexbuf, hexbuf_sz); 240b55a5117SDmitri Tikhonov LCID("[%" PRIu64 ",\"SECURITY\",\"CHECK_CERT\",\"CERTLOG\"," 241b55a5117SDmitri Tikhonov "{\"certificate\":\"%s\"}]", now, hexbuf); 242b55a5117SDmitri Tikhonov OPENSSL_free(buf); 243b55a5117SDmitri Tikhonov } 244b55a5117SDmitri Tikhonov 245b55a5117SDmitri Tikhonov if (hexbuf) 246b55a5117SDmitri Tikhonov free(hexbuf); 247b55a5117SDmitri Tikhonov} 248b55a5117SDmitri Tikhonov 249b55a5117SDmitri Tikhonov 250b55a5117SDmitri Tikhonovvoid 2515392f7a3SLiteSpeed Techlsquic_qlog_version_negotiation (const lsquic_cid_t* cid, 25255cd0b38SDmitri Tikhonov const char *action, const char *ver) 25355cd0b38SDmitri Tikhonov{ 25455cd0b38SDmitri Tikhonov char *trig; 25555cd0b38SDmitri Tikhonov 25655cd0b38SDmitri Tikhonov if (!action || !ver) 25755cd0b38SDmitri Tikhonov return; 25855cd0b38SDmitri Tikhonov if (strcmp(action, "proposed") == 0) 25955cd0b38SDmitri Tikhonov trig = "LINE"; 2605392f7a3SLiteSpeed Tech else if (strcmp(action, "supports") == 0 || strcmp(action, "agreed") == 0) 26155cd0b38SDmitri Tikhonov trig = "PACKET_RX"; 26255cd0b38SDmitri Tikhonov else 26355cd0b38SDmitri Tikhonov return; 26455cd0b38SDmitri Tikhonov LCID("[%" PRIu64 ",\"CONNECTIVITY\",\"VERNEG\",\"%s\"," 26555cd0b38SDmitri Tikhonov "{\"%s_version\":\"%s\"}]", lsquic_time_now(), trig, action, ver); 26655cd0b38SDmitri Tikhonov} 267