lsquic_qlog.c revision 9b4d33c7
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>
855cd0b38SDmitri Tikhonov#include <netinet/in.h>
955cd0b38SDmitri Tikhonov#include <arpa/inet.h>
1055cd0b38SDmitri Tikhonov
1155cd0b38SDmitri Tikhonov#include "lsquic.h"
1255cd0b38SDmitri Tikhonov#include "lsquic_types.h"
1355cd0b38SDmitri Tikhonov#include "lsquic_int_types.h"
1455cd0b38SDmitri Tikhonov#include "lsquic_packet_common.h"
1555cd0b38SDmitri Tikhonov#include "lsquic_packet_in.h"
1655cd0b38SDmitri Tikhonov#include "lsquic_packet_out.h"
1755cd0b38SDmitri Tikhonov#include "lsquic_util.h"
1855cd0b38SDmitri Tikhonov#include "lsquic_qlog.h"
1955cd0b38SDmitri Tikhonov
2055cd0b38SDmitri Tikhonov#define LSQUIC_LOGGER_MODULE LSQLM_QLOG
2155cd0b38SDmitri Tikhonov#include "lsquic_logger.h"
2255cd0b38SDmitri Tikhonov
2355cd0b38SDmitri Tikhonov#define LSQUIC_LOG_CONN_ID cid
2455cd0b38SDmitri Tikhonov#define LCID(...) LSQ_LOG2(LSQ_LOG_DEBUG, __VA_ARGS__)
2555cd0b38SDmitri Tikhonov
2655cd0b38SDmitri Tikhonov#define MAX_IP_LEN INET6_ADDRSTRLEN
2755cd0b38SDmitri Tikhonov#define QLOG_PACKET_RAW_SZ 64
2855cd0b38SDmitri Tikhonov
2955cd0b38SDmitri Tikhonov
3055cd0b38SDmitri Tikhonovvoid
3155cd0b38SDmitri Tikhonovlsquic_qlog_create_connection (lsquic_cid_t cid,
3255cd0b38SDmitri Tikhonov                                const struct sockaddr *local_sa,
3355cd0b38SDmitri Tikhonov                                const struct sockaddr *peer_sa)
3455cd0b38SDmitri Tikhonov{
3555cd0b38SDmitri Tikhonov    uint32_t ip_version, srcport, dstport;
3655cd0b38SDmitri Tikhonov    struct sockaddr_in *local4, *peer4;
3755cd0b38SDmitri Tikhonov    struct sockaddr_in6 *local6, *peer6;
3855cd0b38SDmitri Tikhonov    char srcip[MAX_IP_LEN], dstip[MAX_IP_LEN];
3955cd0b38SDmitri Tikhonov
4055cd0b38SDmitri Tikhonov    if (!local_sa || !peer_sa)
4155cd0b38SDmitri Tikhonov        return;
4255cd0b38SDmitri Tikhonov
4355cd0b38SDmitri Tikhonov    if (local_sa->sa_family == AF_INET)
4455cd0b38SDmitri Tikhonov    {
4555cd0b38SDmitri Tikhonov        ip_version = 4;
4655cd0b38SDmitri Tikhonov        local4 = (struct sockaddr_in *)local_sa;
4755cd0b38SDmitri Tikhonov        peer4 = (struct sockaddr_in *)peer_sa;
4855cd0b38SDmitri Tikhonov        srcport = ntohs(local4->sin_port);
4955cd0b38SDmitri Tikhonov        dstport = ntohs(peer4->sin_port);
5055cd0b38SDmitri Tikhonov        inet_ntop(local4->sin_family, &local4->sin_addr, srcip, MAX_IP_LEN);
5155cd0b38SDmitri Tikhonov        inet_ntop(peer4->sin_family, &peer4->sin_addr, dstip, MAX_IP_LEN);
5255cd0b38SDmitri Tikhonov    }
5355cd0b38SDmitri Tikhonov    else if (local_sa->sa_family == AF_INET6)
5455cd0b38SDmitri Tikhonov    {
5555cd0b38SDmitri Tikhonov        ip_version = 6;
5655cd0b38SDmitri Tikhonov        local6 = (struct sockaddr_in6 *)local_sa;
5755cd0b38SDmitri Tikhonov        peer6 = (struct sockaddr_in6 *)peer_sa;
5855cd0b38SDmitri Tikhonov        srcport = ntohs(local6->sin6_port);
5955cd0b38SDmitri Tikhonov        dstport = ntohs(peer6->sin6_port);
6055cd0b38SDmitri Tikhonov        inet_ntop(local6->sin6_family, &local6->sin6_addr, srcip, MAX_IP_LEN);
6155cd0b38SDmitri Tikhonov        inet_ntop(peer6->sin6_family, &peer6->sin6_addr, dstip, MAX_IP_LEN);
6255cd0b38SDmitri Tikhonov    }
6355cd0b38SDmitri Tikhonov    else
6455cd0b38SDmitri Tikhonov        return;
6555cd0b38SDmitri Tikhonov
6655cd0b38SDmitri Tikhonov    LCID("[%" PRIu64 ",\"CONNECTIVITY\",\"NEW_CONNECTION\",\"LINE\","
6755cd0b38SDmitri Tikhonov            "{"
6855cd0b38SDmitri Tikhonov                "\"ip_version\":\"%u\","
6955cd0b38SDmitri Tikhonov                "\"srcip\":\"%s\","
7055cd0b38SDmitri Tikhonov                "\"dstip\":\"%s\","
7155cd0b38SDmitri Tikhonov                "\"srcport\":\"%u\","
7255cd0b38SDmitri Tikhonov                "\"dstport\":\"%u\""
7355cd0b38SDmitri Tikhonov            "}]",
7455cd0b38SDmitri Tikhonov            lsquic_time_now(), ip_version, srcip, dstip, srcport, dstport);
7555cd0b38SDmitri Tikhonov}
7655cd0b38SDmitri Tikhonov
779b4d33c7SDmitri Tikhonov#define QLOG_FRAME_DICT_PREFIX_COMMA ",{\"frame_type\":\""
789b4d33c7SDmitri Tikhonov#define QLOG_FRAME_DICT_PREFIX "{\"frame_type\":\""
7955cd0b38SDmitri Tikhonov#define QLOG_FRAME_DICT_SUFFIX "\"}"
8055cd0b38SDmitri Tikhonov#define QLOG_FRAME_LIST_PREFIX ",\"frames\":["
8155cd0b38SDmitri Tikhonov#define QLOG_FRAME_LIST_SUFFIX "]"
8255cd0b38SDmitri Tikhonov#define QLOG_FRAME_LIST_MAX \
8355cd0b38SDmitri Tikhonov    sizeof(QLOG_FRAME_LIST_PREFIX) + \
8455cd0b38SDmitri Tikhonov    sizeof(QLOG_FRAME_LIST_SUFFIX) + \
8555cd0b38SDmitri Tikhonov    lsquic_frame_types_str_sz + \
8655cd0b38SDmitri Tikhonov    (N_QUIC_FRAMES * \
879b4d33c7SDmitri Tikhonov    (sizeof(QLOG_FRAME_DICT_PREFIX_COMMA) + \
8855cd0b38SDmitri Tikhonov     sizeof(QLOG_FRAME_DICT_SUFFIX)))
8955cd0b38SDmitri Tikhonov
9055cd0b38SDmitri Tikhonovvoid
9155cd0b38SDmitri Tikhonovlsquic_qlog_packet_rx (lsquic_cid_t cid,
9255cd0b38SDmitri Tikhonov                        const struct lsquic_packet_in *packet_in,
9355cd0b38SDmitri Tikhonov                        const unsigned char *packet_in_data,
9455cd0b38SDmitri Tikhonov                        size_t packet_in_size)
9555cd0b38SDmitri Tikhonov{
9655cd0b38SDmitri Tikhonov    int i, cur = 0, first = 0, ret = 0;
9755cd0b38SDmitri Tikhonov    size_t raw_bytes_written;
9855cd0b38SDmitri Tikhonov    char data[QLOG_PACKET_RAW_SZ];
9955cd0b38SDmitri Tikhonov    char frame_list[QLOG_FRAME_LIST_MAX + 1];
10055cd0b38SDmitri Tikhonov
10155cd0b38SDmitri Tikhonov    if (!packet_in || !packet_in_data)
10255cd0b38SDmitri Tikhonov        return;
10355cd0b38SDmitri Tikhonov
10455cd0b38SDmitri Tikhonov    frame_list[cur] = '\0';
10555cd0b38SDmitri Tikhonov    if (packet_in->pi_frame_types)
10655cd0b38SDmitri Tikhonov    {
10755cd0b38SDmitri Tikhonov        cur = sprintf(frame_list, "%s", QLOG_FRAME_LIST_PREFIX);
10855cd0b38SDmitri Tikhonov        for (i = 0; i < N_QUIC_FRAMES; i++)
10955cd0b38SDmitri Tikhonov            if (packet_in->pi_frame_types & (1 << i))
11055cd0b38SDmitri Tikhonov            {
11155cd0b38SDmitri Tikhonov                ret = snprintf(frame_list + cur,
11255cd0b38SDmitri Tikhonov                                QLOG_FRAME_LIST_MAX - cur,
11355cd0b38SDmitri Tikhonov                                /* prefix + FRAME_NAME + suffix */
11455cd0b38SDmitri Tikhonov                                "%s%s%s",
11555cd0b38SDmitri Tikhonov                                /* skip comma in prefix if first frame */
1169b4d33c7SDmitri Tikhonov                                (first++ ?
1179b4d33c7SDmitri Tikhonov                                    QLOG_FRAME_DICT_PREFIX_COMMA :
1189b4d33c7SDmitri Tikhonov                                    QLOG_FRAME_DICT_PREFIX),
11955cd0b38SDmitri Tikhonov                                QUIC_FRAME_NAME(i),
12055cd0b38SDmitri Tikhonov                                QLOG_FRAME_DICT_SUFFIX);
12155cd0b38SDmitri Tikhonov                if ((unsigned)ret > QLOG_FRAME_LIST_MAX - cur)
12255cd0b38SDmitri Tikhonov                    break;
12355cd0b38SDmitri Tikhonov                cur += ret;
12455cd0b38SDmitri Tikhonov            }
12555cd0b38SDmitri Tikhonov        if ((unsigned)cur <= QLOG_FRAME_LIST_MAX)
12655cd0b38SDmitri Tikhonov            sprintf(frame_list + cur, "%s", QLOG_FRAME_LIST_SUFFIX);
12755cd0b38SDmitri Tikhonov    }
12855cd0b38SDmitri Tikhonov
12955cd0b38SDmitri Tikhonov    raw_bytes_written = lsquic_hex_encode(packet_in_data, packet_in_size,
13055cd0b38SDmitri Tikhonov                                                    data, QLOG_PACKET_RAW_SZ);
13155cd0b38SDmitri Tikhonov
13255cd0b38SDmitri Tikhonov    LCID("[%" PRIu64 ",\"TRANSPORT\",\"PACKET_RX\",\"LINE\","
13355cd0b38SDmitri Tikhonov            "{"
13455cd0b38SDmitri Tikhonov                "\"raw\":\"%s%s\","
13555cd0b38SDmitri Tikhonov                "\"header\":{"
13655cd0b38SDmitri Tikhonov                    "\"type\":\"%s\","
13755cd0b38SDmitri Tikhonov                    "\"payload_length\":\"%d\","
1389b4d33c7SDmitri Tikhonov                    "\"packet_number\":\"%" PRIu64 "\""
13955cd0b38SDmitri Tikhonov                "}%s"
14055cd0b38SDmitri Tikhonov            "}]",
14155cd0b38SDmitri Tikhonov            packet_in->pi_received,
14255cd0b38SDmitri Tikhonov            data, (raw_bytes_written < packet_in_size) ? "..." : "",
14355cd0b38SDmitri Tikhonov            lsquic_hety2str[packet_in->pi_header_type],
14455cd0b38SDmitri Tikhonov            packet_in->pi_data_sz,
14555cd0b38SDmitri Tikhonov            packet_in->pi_packno,
14655cd0b38SDmitri Tikhonov            frame_list);
14755cd0b38SDmitri Tikhonov}
14855cd0b38SDmitri Tikhonov
14955cd0b38SDmitri Tikhonov
15055cd0b38SDmitri Tikhonovvoid
15155cd0b38SDmitri Tikhonovlsquic_qlog_hsk_completed (lsquic_cid_t cid)
15255cd0b38SDmitri Tikhonov{
15355cd0b38SDmitri Tikhonov    LCID("[%" PRIu64 ",\"CONNECTIVITY\",\"HANDSHAKE\",\"PACKET_RX\","
15455cd0b38SDmitri Tikhonov            "{\"status\":\"complete\"}]", lsquic_time_now());
15555cd0b38SDmitri Tikhonov}
15655cd0b38SDmitri Tikhonov
15755cd0b38SDmitri Tikhonov
15855cd0b38SDmitri Tikhonovvoid
15955cd0b38SDmitri Tikhonovlsquic_qlog_zero_rtt (lsquic_cid_t cid)
16055cd0b38SDmitri Tikhonov{
16155cd0b38SDmitri Tikhonov    LCID("[%" PRIu64 ",\"RECOVERY\",\"RTT_UPDATE\",\"PACKET_RX\","
16255cd0b38SDmitri Tikhonov            "{\"zero_rtt\":\"successful\"}]", lsquic_time_now());
16355cd0b38SDmitri Tikhonov}
16455cd0b38SDmitri Tikhonov
16555cd0b38SDmitri Tikhonov
16655cd0b38SDmitri Tikhonovvoid
16755cd0b38SDmitri Tikhonovlsquic_qlog_check_certs (lsquic_cid_t cid, const lsquic_str_t **certs,
16855cd0b38SDmitri Tikhonov                                                                size_t count)
16955cd0b38SDmitri Tikhonov{
17055cd0b38SDmitri Tikhonov    size_t i;
17155cd0b38SDmitri Tikhonov    size_t buf_sz = 0;
17255cd0b38SDmitri Tikhonov    char *buf = NULL;
17355cd0b38SDmitri Tikhonov    char *new_buf;
17455cd0b38SDmitri Tikhonov
17555cd0b38SDmitri Tikhonov    for (i = 0; i < count; i++)
17655cd0b38SDmitri Tikhonov    {
17755cd0b38SDmitri Tikhonov        if (buf_sz < (lsquic_str_len(certs[i]) * 2) + 1)
17855cd0b38SDmitri Tikhonov        {
17955cd0b38SDmitri Tikhonov            buf_sz = (lsquic_str_len(certs[i]) * 2) + 1;
18055cd0b38SDmitri Tikhonov            new_buf = realloc(buf, buf_sz);
18155cd0b38SDmitri Tikhonov            if (!new_buf)
18255cd0b38SDmitri Tikhonov                break;
18355cd0b38SDmitri Tikhonov            buf = new_buf;
18455cd0b38SDmitri Tikhonov        }
18555cd0b38SDmitri Tikhonov        lsquic_hex_encode(lsquic_str_cstr(certs[i]), lsquic_str_len(certs[i]),
18655cd0b38SDmitri Tikhonov                                                                buf, buf_sz);
18755cd0b38SDmitri Tikhonov        LCID("[%" PRIu64 ",\"SECURITY\",\"CHECK_CERT\",\"CERTLOG\","
18855cd0b38SDmitri Tikhonov                "{\"certificate\":\"%s\"}]", lsquic_time_now(), buf);
18955cd0b38SDmitri Tikhonov    }
19055cd0b38SDmitri Tikhonov    if (buf)
19155cd0b38SDmitri Tikhonov        free(buf);
19255cd0b38SDmitri Tikhonov}
19355cd0b38SDmitri Tikhonov
19455cd0b38SDmitri Tikhonov
19555cd0b38SDmitri Tikhonovvoid
19655cd0b38SDmitri Tikhonovlsquic_qlog_version_negotiation (lsquic_cid_t cid,
19755cd0b38SDmitri Tikhonov                                        const char *action, const char *ver)
19855cd0b38SDmitri Tikhonov{
19955cd0b38SDmitri Tikhonov    char *trig;
20055cd0b38SDmitri Tikhonov
20155cd0b38SDmitri Tikhonov    if (!action || !ver)
20255cd0b38SDmitri Tikhonov        return;
20355cd0b38SDmitri Tikhonov    if (strcmp(action, "proposed") == 0)
20455cd0b38SDmitri Tikhonov        trig = "LINE";
20555cd0b38SDmitri Tikhonov    else if (strcmp(action, "agreed") == 0)
20655cd0b38SDmitri Tikhonov        trig = "PACKET_RX";
20755cd0b38SDmitri Tikhonov    else
20855cd0b38SDmitri Tikhonov        return;
20955cd0b38SDmitri Tikhonov    LCID("[%" PRIu64 ",\"CONNECTIVITY\",\"VERNEG\",\"%s\","
21055cd0b38SDmitri Tikhonov            "{\"%s_version\":\"%s\"}]", lsquic_time_now(), trig, action, ver);
21155cd0b38SDmitri Tikhonov}
212