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