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