lsquic_qlog.c revision 9b4d33c7 
1/* Copyright (c) 2017 - 2019 LiteSpeed Technologies Inc.  See LICENSE. */
2#include <stdlib.h>
3#include <stdio.h>
4#include <errno.h>
5#include <inttypes.h>
6#include <string.h>
7#include <sys/queue.h>
8#include <netinet/in.h>
9#include <arpa/inet.h>
10
11#include "lsquic.h"
12#include "lsquic_types.h"
13#include "lsquic_int_types.h"
14#include "lsquic_packet_common.h"
15#include "lsquic_packet_in.h"
16#include "lsquic_packet_out.h"
17#include "lsquic_util.h"
18#include "lsquic_qlog.h"
19
20#define LSQUIC_LOGGER_MODULE LSQLM_QLOG
21#include "lsquic_logger.h"
22
23#define LSQUIC_LOG_CONN_ID cid
24#define LCID(...) LSQ_LOG2(LSQ_LOG_DEBUG, __VA_ARGS__)
25
26#define MAX_IP_LEN INET6_ADDRSTRLEN
27#define QLOG_PACKET_RAW_SZ 64
28
29
30void
31lsquic_qlog_create_connection (lsquic_cid_t cid,
32                                const struct sockaddr *local_sa,
33                                const struct sockaddr *peer_sa)
34{
35    uint32_t ip_version, srcport, dstport;
36    struct sockaddr_in *local4, *peer4;
37    struct sockaddr_in6 *local6, *peer6;
38    char srcip[MAX_IP_LEN], dstip[MAX_IP_LEN];
39
40    if (!local_sa || !peer_sa)
41        return;
42
43    if (local_sa->sa_family == AF_INET)
44    {
45        ip_version = 4;
46        local4 = (struct sockaddr_in *)local_sa;
47        peer4 = (struct sockaddr_in *)peer_sa;
48        srcport = ntohs(local4->sin_port);
49        dstport = ntohs(peer4->sin_port);
50        inet_ntop(local4->sin_family, &local4->sin_addr, srcip, MAX_IP_LEN);
51        inet_ntop(peer4->sin_family, &peer4->sin_addr, dstip, MAX_IP_LEN);
52    }
53    else if (local_sa->sa_family == AF_INET6)
54    {
55        ip_version = 6;
56        local6 = (struct sockaddr_in6 *)local_sa;
57        peer6 = (struct sockaddr_in6 *)peer_sa;
58        srcport = ntohs(local6->sin6_port);
59        dstport = ntohs(peer6->sin6_port);
60        inet_ntop(local6->sin6_family, &local6->sin6_addr, srcip, MAX_IP_LEN);
61        inet_ntop(peer6->sin6_family, &peer6->sin6_addr, dstip, MAX_IP_LEN);
62    }
63    else
64        return;
65
66    LCID("[%" PRIu64 ",\"CONNECTIVITY\",\"NEW_CONNECTION\",\"LINE\","
67            "{"
68                "\"ip_version\":\"%u\","
69                "\"srcip\":\"%s\","
70                "\"dstip\":\"%s\","
71                "\"srcport\":\"%u\","
72                "\"dstport\":\"%u\""
73            "}]",
74            lsquic_time_now(), ip_version, srcip, dstip, srcport, dstport);
75}
76
77#define QLOG_FRAME_DICT_PREFIX_COMMA ",{\"frame_type\":\""
78#define QLOG_FRAME_DICT_PREFIX "{\"frame_type\":\""
79#define QLOG_FRAME_DICT_SUFFIX "\"}"
80#define QLOG_FRAME_LIST_PREFIX ",\"frames\":["
81#define QLOG_FRAME_LIST_SUFFIX "]"
82#define QLOG_FRAME_LIST_MAX \
83    sizeof(QLOG_FRAME_LIST_PREFIX) + \
84    sizeof(QLOG_FRAME_LIST_SUFFIX) + \
85    lsquic_frame_types_str_sz + \
86    (N_QUIC_FRAMES * \
87    (sizeof(QLOG_FRAME_DICT_PREFIX_COMMA) + \
88     sizeof(QLOG_FRAME_DICT_SUFFIX)))
89
90void
91lsquic_qlog_packet_rx (lsquic_cid_t cid,
92                        const struct lsquic_packet_in *packet_in,
93                        const unsigned char *packet_in_data,
94                        size_t packet_in_size)
95{
96    int i, cur = 0, first = 0, ret = 0;
97    size_t raw_bytes_written;
98    char data[QLOG_PACKET_RAW_SZ];
99    char frame_list[QLOG_FRAME_LIST_MAX + 1];
100
101    if (!packet_in || !packet_in_data)
102        return;
103
104    frame_list[cur] = '\0';
105    if (packet_in->pi_frame_types)
106    {
107        cur = sprintf(frame_list, "%s", QLOG_FRAME_LIST_PREFIX);
108        for (i = 0; i < N_QUIC_FRAMES; i++)
109            if (packet_in->pi_frame_types & (1 << i))
110            {
111                ret = snprintf(frame_list + cur,
112                                QLOG_FRAME_LIST_MAX - cur,
113                                /* prefix + FRAME_NAME + suffix */
114                                "%s%s%s",
115                                /* skip comma in prefix if first frame */
116                                (first++ ?
117                                    QLOG_FRAME_DICT_PREFIX_COMMA :
118                                    QLOG_FRAME_DICT_PREFIX),
119                                QUIC_FRAME_NAME(i),
120                                QLOG_FRAME_DICT_SUFFIX);
121                if ((unsigned)ret > QLOG_FRAME_LIST_MAX - cur)
122                    break;
123                cur += ret;
124            }
125        if ((unsigned)cur <= QLOG_FRAME_LIST_MAX)
126            sprintf(frame_list + cur, "%s", QLOG_FRAME_LIST_SUFFIX);
127    }
128
129    raw_bytes_written = lsquic_hex_encode(packet_in_data, packet_in_size,
130                                                    data, QLOG_PACKET_RAW_SZ);
131
132    LCID("[%" PRIu64 ",\"TRANSPORT\",\"PACKET_RX\",\"LINE\","
133            "{"
134                "\"raw\":\"%s%s\","
135                "\"header\":{"
136                    "\"type\":\"%s\","
137                    "\"payload_length\":\"%d\","
138                    "\"packet_number\":\"%" PRIu64 "\""
139                "}%s"
140            "}]",
141            packet_in->pi_received,
142            data, (raw_bytes_written < packet_in_size) ? "..." : "",
143            lsquic_hety2str[packet_in->pi_header_type],
144            packet_in->pi_data_sz,
145            packet_in->pi_packno,
146            frame_list);
147}
148
149
150void
151lsquic_qlog_hsk_completed (lsquic_cid_t cid)
152{
153    LCID("[%" PRIu64 ",\"CONNECTIVITY\",\"HANDSHAKE\",\"PACKET_RX\","
154            "{\"status\":\"complete\"}]", lsquic_time_now());
155}
156
157
158void
159lsquic_qlog_zero_rtt (lsquic_cid_t cid)
160{
161    LCID("[%" PRIu64 ",\"RECOVERY\",\"RTT_UPDATE\",\"PACKET_RX\","
162            "{\"zero_rtt\":\"successful\"}]", lsquic_time_now());
163}
164
165
166void
167lsquic_qlog_check_certs (lsquic_cid_t cid, const lsquic_str_t **certs,
168                                                                size_t count)
169{
170    size_t i;
171    size_t buf_sz = 0;
172    char *buf = NULL;
173    char *new_buf;
174
175    for (i = 0; i < count; i++)
176    {
177        if (buf_sz < (lsquic_str_len(certs[i]) * 2) + 1)
178        {
179            buf_sz = (lsquic_str_len(certs[i]) * 2) + 1;
180            new_buf = realloc(buf, buf_sz);
181            if (!new_buf)
182                break;
183            buf = new_buf;
184        }
185        lsquic_hex_encode(lsquic_str_cstr(certs[i]), lsquic_str_len(certs[i]),
186                                                                buf, buf_sz);
187        LCID("[%" PRIu64 ",\"SECURITY\",\"CHECK_CERT\",\"CERTLOG\","
188                "{\"certificate\":\"%s\"}]", lsquic_time_now(), buf);
189    }
190    if (buf)
191        free(buf);
192}
193
194
195void
196lsquic_qlog_version_negotiation (lsquic_cid_t cid,
197                                        const char *action, const char *ver)
198{
199    char *trig;
200
201    if (!action || !ver)
202        return;
203    if (strcmp(action, "proposed") == 0)
204        trig = "LINE";
205    else if (strcmp(action, "agreed") == 0)
206        trig = "PACKET_RX";
207    else
208        return;
209    LCID("[%" PRIu64 ",\"CONNECTIVITY\",\"VERNEG\",\"%s\","
210            "{\"%s_version\":\"%s\"}]", lsquic_time_now(), trig, action, ver);
211}
212