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