lsquic_qlog.c revision 7483dee0 
1/* Copyright (c) 2017 - 2020 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#ifdef WIN32
9#include <Ws2tcpip.h>
10#else
11#include <sys/types.h>
12#include <sys/socket.h>
13#include <netinet/in.h>
14#include <arpa/inet.h>
15#endif
16
17#include <openssl/ssl.h>
18#include <openssl/x509.h>
19
20#include "lsquic.h"
21#include "lsquic_types.h"
22#include "lsquic_int_types.h"
23#include "lsquic_packet_common.h"
24#include "lsquic_packet_in.h"
25#include "lsquic_packet_out.h"
26#include "lsquic_util.h"
27#include "lsquic_qlog.h"
28
29#define LSQUIC_LOGGER_MODULE LSQLM_QLOG
30#include "lsquic_logger.h"
31
32#define LSQUIC_LOG_CONN_ID cid
33#define LCID(...) LSQ_LOG2(LSQ_LOG_DEBUG, __VA_ARGS__)
34
35#define MAX_IP_LEN INET6_ADDRSTRLEN
36#define QLOG_PACKET_RAW_SZ 64
37
38
39void
40lsquic_qlog_create_connection (const lsquic_cid_t* cid,
41                                const struct sockaddr *local_sa,
42                                const struct sockaddr *peer_sa)
43{
44    uint32_t ip_version, srcport, dstport;
45    struct sockaddr_in *local4, *peer4;
46    struct sockaddr_in6 *local6, *peer6;
47    char srcip[MAX_IP_LEN], dstip[MAX_IP_LEN];
48
49    if (!local_sa || !peer_sa)
50        return;
51
52    if (local_sa->sa_family == AF_INET)
53    {
54        ip_version = 4;
55        local4 = (struct sockaddr_in *)local_sa;
56        peer4 = (struct sockaddr_in *)peer_sa;
57        srcport = ntohs(local4->sin_port);
58        dstport = ntohs(peer4->sin_port);
59        inet_ntop(local4->sin_family, &local4->sin_addr, srcip, MAX_IP_LEN);
60        inet_ntop(peer4->sin_family, &peer4->sin_addr, dstip, MAX_IP_LEN);
61    }
62    else if (local_sa->sa_family == AF_INET6)
63    {
64        ip_version = 6;
65        local6 = (struct sockaddr_in6 *)local_sa;
66        peer6 = (struct sockaddr_in6 *)peer_sa;
67        srcport = ntohs(local6->sin6_port);
68        dstport = ntohs(peer6->sin6_port);
69        inet_ntop(local6->sin6_family, &local6->sin6_addr, srcip, MAX_IP_LEN);
70        inet_ntop(peer6->sin6_family, &peer6->sin6_addr, dstip, MAX_IP_LEN);
71    }
72    else
73        return;
74
75    LCID("[%" PRIu64 ",\"CONNECTIVITY\",\"NEW_CONNECTION\",\"LINE\","
76            "{"
77                "\"ip_version\":\"%u\","
78                "\"srcip\":\"%s\","
79                "\"dstip\":\"%s\","
80                "\"srcport\":\"%u\","
81                "\"dstport\":\"%u\""
82            "}]",
83            lsquic_time_now(), ip_version, srcip, dstip, srcport, dstport);
84}
85
86
87#define QLOG_FRAME_DICT_PREFIX_COMMA ",{\"frame_type\":\""
88#define QLOG_FRAME_DICT_PREFIX "{\"frame_type\":\""
89#define QLOG_FRAME_DICT_SUFFIX "\"}"
90#define QLOG_FRAME_LIST_PREFIX ",\"frames\":["
91#define QLOG_FRAME_LIST_SUFFIX "]"
92#define QLOG_FRAME_LIST_MAX \
93    sizeof(QLOG_FRAME_LIST_PREFIX) + \
94    sizeof(QLOG_FRAME_LIST_SUFFIX) + \
95    lsquic_frame_types_str_sz + \
96    (N_QUIC_FRAMES * \
97    (sizeof(QLOG_FRAME_DICT_PREFIX_COMMA) + \
98     sizeof(QLOG_FRAME_DICT_SUFFIX)))
99
100void
101lsquic_qlog_packet_rx (const lsquic_cid_t* cid,
102                        const struct lsquic_packet_in *packet_in,
103                        const unsigned char *packet_in_data,
104                        size_t packet_in_size)
105{
106    int i, first, ret;
107    unsigned cur;
108    size_t raw_bytes_written;
109    char data[QLOG_PACKET_RAW_SZ];
110    char frame_list[QLOG_FRAME_LIST_MAX + 1];
111
112    if (!packet_in || !packet_in_data)
113        return;
114
115    if (packet_in->pi_frame_types)
116    {
117        memcpy(frame_list, QLOG_FRAME_LIST_PREFIX,
118                                            sizeof(QLOG_FRAME_LIST_PREFIX));
119        cur = sizeof(QLOG_FRAME_LIST_PREFIX) - 1;
120        for (i = 0, first = 0; i < N_QUIC_FRAMES; i++)
121            if (packet_in->pi_frame_types & (1 << i))
122            {
123                ret = snprintf(frame_list + cur,
124                                QLOG_FRAME_LIST_MAX - cur,
125                                /* prefix + FRAME_NAME + suffix */
126                                "%s%s%s",
127                                /* skip comma in prefix if first frame */
128                                (first++ ?
129                                    QLOG_FRAME_DICT_PREFIX_COMMA :
130                                    QLOG_FRAME_DICT_PREFIX),
131                                QUIC_FRAME_NAME(i),
132                                QLOG_FRAME_DICT_SUFFIX);
133                if (ret < 0 || (unsigned)ret > QLOG_FRAME_LIST_MAX - cur)
134                    break;
135                cur += ret;
136            }
137        if (cur + sizeof(QLOG_FRAME_LIST_SUFFIX) <= QLOG_FRAME_LIST_MAX)
138            memcpy(frame_list + cur, QLOG_FRAME_LIST_SUFFIX,
139                                        sizeof(QLOG_FRAME_LIST_SUFFIX));
140    }
141    else
142        frame_list[0] = '\0';
143
144    raw_bytes_written = lsquic_hex_encode(packet_in_data, packet_in_size,
145                                                    data, QLOG_PACKET_RAW_SZ);
146
147    LCID("[%" PRIu64 ",\"TRANSPORT\",\"PACKET_RX\",\"LINE\","
148            "{"
149                "\"raw\":\"%s%s\","
150                "\"header\":{"
151                    "\"type\":\"%s\","
152                    "\"payload_length\":\"%d\","
153                    "\"packet_number\":\"%" PRIu64 "\""
154                "}%s"
155            "}]",
156            packet_in->pi_received,
157            data, (raw_bytes_written < packet_in_size) ? "..." : "",
158            lsquic_hety2str[packet_in->pi_header_type],
159            packet_in->pi_data_sz,
160            packet_in->pi_packno,
161            frame_list);
162}
163
164
165void
166lsquic_qlog_hsk_completed (const lsquic_cid_t* cid)
167{
168    LCID("[%" PRIu64 ",\"CONNECTIVITY\",\"HANDSHAKE\",\"PACKET_RX\","
169            "{\"status\":\"complete\"}]", lsquic_time_now());
170}
171
172
173void
174lsquic_qlog_sess_resume (const lsquic_cid_t* cid)
175{
176    LCID("[%" PRIu64 ",\"RECOVERY\",\"RTT_UPDATE\",\"PACKET_RX\","
177            "{\"zero_rtt\":\"successful\"}]", lsquic_time_now());
178}
179
180
181void
182lsquic_qlog_check_certs (const lsquic_cid_t* cid, const lsquic_str_t **certs,
183                                                                size_t count)
184{
185    size_t i;
186    size_t buf_sz = 0;
187    char *buf = NULL;
188    char *new_buf;
189
190    for (i = 0; i < count; i++)
191    {
192        if (buf_sz < (lsquic_str_len(certs[i]) * 2) + 1)
193        {
194            buf_sz = (lsquic_str_len(certs[i]) * 2) + 1;
195            new_buf = realloc(buf, buf_sz);
196            if (!new_buf)
197                break;
198            buf = new_buf;
199        }
200        lsquic_hex_encode(lsquic_str_cstr(certs[i]), lsquic_str_len(certs[i]),
201                                                                buf, buf_sz);
202        LCID("[%" PRIu64 ",\"SECURITY\",\"CHECK_CERT\",\"CERTLOG\","
203                "{\"certificate\":\"%s\"}]", lsquic_time_now(), buf);
204    }
205    if (buf)
206        free(buf);
207}
208
209
210void
211lsquic_qlog_cert_chain (const lsquic_cid_t* cid, struct stack_st_X509 *chain)
212{
213    X509 *cert;
214    unsigned i;
215    unsigned char *buf;
216    char *hexbuf, *newbuf;
217    size_t hexbuf_sz;
218    int len;
219    lsquic_time_t now;
220
221    now = lsquic_time_now();
222    hexbuf = NULL;
223    hexbuf_sz = 0;
224    for (i = 0; i < sk_X509_num(chain); ++i)
225    {
226        cert = sk_X509_value(chain, i);
227        buf = NULL;
228        len = i2d_X509(cert, &buf);
229        if (len <= 0)
230            break;
231        if ((size_t) len * 2 + 1 > hexbuf_sz)
232        {
233            hexbuf_sz = len * 2 + 1;
234            newbuf = realloc(hexbuf, hexbuf_sz);
235            if (!newbuf)
236                break;
237            hexbuf = newbuf;
238        }
239        lsquic_hexstr(buf, (size_t) len, hexbuf, hexbuf_sz);
240        LCID("[%" PRIu64 ",\"SECURITY\",\"CHECK_CERT\",\"CERTLOG\","
241                "{\"certificate\":\"%s\"}]", now, hexbuf);
242        OPENSSL_free(buf);
243    }
244
245    if (hexbuf)
246        free(hexbuf);
247}
248
249
250void
251lsquic_qlog_version_negotiation (const lsquic_cid_t* cid,
252                                        const char *action, const char *ver)
253{
254    char *trig;
255
256    if (!action || !ver)
257        return;
258    if (strcmp(action, "proposed") == 0)
259        trig = "LINE";
260    else if (strcmp(action, "supports") == 0 || strcmp(action, "agreed") == 0)
261        trig = "PACKET_RX";
262    else
263        return;
264    LCID("[%" PRIu64 ",\"CONNECTIVITY\",\"VERNEG\",\"%s\","
265            "{\"%s_version\":\"%s\"}]", lsquic_time_now(), trig, action, ver);
266}
267