lsquic_qlog.c revision 7d09751d 
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 "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 (const 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 (const 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, first, ret;
103    unsigned cur;
104    size_t raw_bytes_written;
105    char data[QLOG_PACKET_RAW_SZ];
106    char frame_list[QLOG_FRAME_LIST_MAX + 1];
107
108    if (!packet_in || !packet_in_data)
109        return;
110
111    if (packet_in->pi_frame_types)
112    {
113        memcpy(frame_list, QLOG_FRAME_LIST_PREFIX,
114                                            sizeof(QLOG_FRAME_LIST_PREFIX));
115        cur = sizeof(QLOG_FRAME_LIST_PREFIX) - 1;
116        for (i = 0, first = 0; i < N_QUIC_FRAMES; i++)
117            if (packet_in->pi_frame_types & (1 << i))
118            {
119                ret = snprintf(frame_list + cur,
120                                QLOG_FRAME_LIST_MAX - cur,
121                                /* prefix + FRAME_NAME + suffix */
122                                "%s%s%s",
123                                /* skip comma in prefix if first frame */
124                                (first++ ?
125                                    QLOG_FRAME_DICT_PREFIX_COMMA :
126                                    QLOG_FRAME_DICT_PREFIX),
127                                QUIC_FRAME_NAME(i),
128                                QLOG_FRAME_DICT_SUFFIX);
129                if (ret < 0 || (unsigned)ret > QLOG_FRAME_LIST_MAX - cur)
130                    break;
131                cur += ret;
132            }
133        if (cur + sizeof(QLOG_FRAME_LIST_SUFFIX) <= QLOG_FRAME_LIST_MAX)
134            memcpy(frame_list + cur, QLOG_FRAME_LIST_SUFFIX,
135                                        sizeof(QLOG_FRAME_LIST_SUFFIX));
136    }
137    else
138        frame_list[0] = '\0';
139
140    raw_bytes_written = lsquic_hex_encode(packet_in_data, packet_in_size,
141                                                    data, QLOG_PACKET_RAW_SZ);
142
143    LCID("[%" PRIu64 ",\"TRANSPORT\",\"PACKET_RX\",\"LINE\","
144            "{"
145                "\"raw\":\"%s%s\","
146                "\"header\":{"
147                    "\"type\":\"%s\","
148                    "\"payload_length\":\"%d\","
149                    "\"packet_number\":\"%" PRIu64 "\""
150                "}%s"
151            "}]",
152            packet_in->pi_received,
153            data, (raw_bytes_written < packet_in_size) ? "..." : "",
154            lsquic_hety2str[packet_in->pi_header_type],
155            packet_in->pi_data_sz,
156            packet_in->pi_packno,
157            frame_list);
158}
159
160
161void
162lsquic_qlog_hsk_completed (const lsquic_cid_t* cid)
163{
164    LCID("[%" PRIu64 ",\"CONNECTIVITY\",\"HANDSHAKE\",\"PACKET_RX\","
165            "{\"status\":\"complete\"}]", lsquic_time_now());
166}
167
168
169void
170lsquic_qlog_zero_rtt (const lsquic_cid_t* cid)
171{
172    LCID("[%" PRIu64 ",\"RECOVERY\",\"RTT_UPDATE\",\"PACKET_RX\","
173            "{\"zero_rtt\":\"successful\"}]", lsquic_time_now());
174}
175
176
177void
178lsquic_qlog_check_certs (const lsquic_cid_t* cid, const lsquic_str_t **certs,
179                                                                size_t count)
180{
181    size_t i;
182    size_t buf_sz = 0;
183    char *buf = NULL;
184    char *new_buf;
185
186    for (i = 0; i < count; i++)
187    {
188        if (buf_sz < (lsquic_str_len(certs[i]) * 2) + 1)
189        {
190            buf_sz = (lsquic_str_len(certs[i]) * 2) + 1;
191            new_buf = realloc(buf, buf_sz);
192            if (!new_buf)
193                break;
194            buf = new_buf;
195        }
196        lsquic_hex_encode(lsquic_str_cstr(certs[i]), lsquic_str_len(certs[i]),
197                                                                buf, buf_sz);
198        LCID("[%" PRIu64 ",\"SECURITY\",\"CHECK_CERT\",\"CERTLOG\","
199                "{\"certificate\":\"%s\"}]", lsquic_time_now(), buf);
200    }
201    if (buf)
202        free(buf);
203}
204
205
206void
207lsquic_qlog_version_negotiation (const lsquic_cid_t* cid,
208                                        const char *action, const char *ver)
209{
210    char *trig;
211
212    if (!action || !ver)
213        return;
214    if (strcmp(action, "proposed") == 0)
215        trig = "LINE";
216    else if (strcmp(action, "supports") == 0 || strcmp(action, "agreed") == 0)
217        trig = "PACKET_RX";
218    else
219        return;
220    LCID("[%" PRIu64 ",\"CONNECTIVITY\",\"VERNEG\",\"%s\","
221            "{\"%s_version\":\"%s\"}]", lsquic_time_now(), trig, action, ver);
222}
223