lsquic_ev_log.c revision 9626cfc2 
1/* Copyright (c) 2017 - 2018 LiteSpeed Technologies Inc.  See LICENSE. */
2#ifndef WIN32
3#include <arpa/inet.h>
4#else
5#include <vc_compat.h>
6#endif
7#include <errno.h>
8#include <inttypes.h>
9#include <stdlib.h>
10#include <string.h>
11#include <sys/queue.h>
12
13#include "lsquic.h"
14#include "lsquic_types.h"
15#include "lsquic_int_types.h"
16#include "lsquic_packet_common.h"
17#include "lsquic_packet_in.h"
18#include "lsquic_packet_out.h"
19#include "lsquic_parse.h"
20#include "lsquic_frame_common.h"
21#include "lsquic_frame_reader.h"
22#include "lsquic_str.h"
23#include "lsquic_handshake.h"
24#include "lsquic_ev_log.h"
25
26#define LSQUIC_LOGGER_MODULE LSQLM_EVENT
27#include "lsquic_logger.h"
28
29
30/*  ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^  */
31/*  ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||  */
32/* Messages that do not include connection ID go above this point */
33
34#define LSQUIC_LOG_CONN_ID cid
35#define LCID(...) LSQ_LOG2(LSQ_LOG_DEBUG, __VA_ARGS__)   /* LCID: log with CID */
36
37/* Messages that are to include connection ID go below this point */
38/*  ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||  */
39/*  VVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVV  */
40
41void
42lsquic_ev_log_packet_in (lsquic_cid_t cid, const lsquic_packet_in_t *packet_in)
43{
44    switch (packet_in->pi_flags & (
45                                                PI_GQUIC))
46    {
47    case PI_GQUIC:
48        LCID("packet in: %"PRIu64, packet_in->pi_packno);
49        break;
50    default:
51        LCID("packet in: %"PRIu64", type: %s",
52            packet_in->pi_packno, lsquic_hety2str[packet_in->pi_header_type]);
53        break;
54    }
55}
56
57
58void
59lsquic_ev_log_ack_frame_in (lsquic_cid_t cid, const struct ack_info *acki)
60{
61    size_t sz;
62    char *buf;
63
64    if ((buf = acki2str(acki, &sz)))
65    {
66        LCID("ACK frame in: %.*s", (int) sz, buf);
67        free(buf);
68    }
69}
70
71
72void
73lsquic_ev_log_stream_frame_in (lsquic_cid_t cid,
74                                        const struct stream_frame *frame)
75{
76    LCID("STREAM frame in: stream %u; offset %"PRIu64"; size %"PRIu16
77        "; fin: %d", frame->stream_id, frame->data_frame.df_offset,
78        frame->data_frame.df_size, (int) frame->data_frame.df_fin);
79}
80
81
82void
83lsquic_ev_log_stop_waiting_frame_in (lsquic_cid_t cid, lsquic_packno_t least)
84{
85    LCID("STOP_WAITING frame in: least unacked packno %"PRIu64, least);
86}
87
88
89void
90lsquic_ev_log_window_update_frame_in (lsquic_cid_t cid, uint32_t stream_id,
91                                                            uint64_t offset)
92{
93    LCID("WINDOW_UPDATE frame in: stream %"PRIu32"; offset %"PRIu64,
94        stream_id, offset);
95}
96
97
98void
99lsquic_ev_log_blocked_frame_in (lsquic_cid_t cid, uint32_t stream_id)
100{
101    LCID("BLOCKED frame in: stream %"PRIu32, stream_id);
102}
103
104
105void
106lsquic_ev_log_connection_close_frame_in (lsquic_cid_t cid,
107                    uint32_t error_code, int reason_len, const char *reason)
108{
109    LCID("CONNECTION_CLOSE frame in: error code %"PRIu32", reason: %.*s",
110        error_code, reason_len, reason);
111}
112
113
114void
115lsquic_ev_log_goaway_frame_in (lsquic_cid_t cid, uint32_t error_code,
116                    uint32_t stream_id, int reason_len, const char *reason)
117{
118    LCID("GOAWAY frame in: error code %"PRIu32", stream %"PRIu32
119        ", reason: %.*s", error_code, stream_id, reason_len, reason);
120}
121
122
123void
124lsquic_ev_log_rst_stream_frame_in (lsquic_cid_t cid, uint32_t stream_id,
125                                        uint64_t offset, uint32_t error_code)
126{
127    LCID("RST_FRAME frame in: error code %"PRIu32", stream %"PRIu32
128        ", offset: %"PRIu64, error_code, stream_id, offset);
129}
130
131
132void
133lsquic_ev_log_padding_frame_in (lsquic_cid_t cid, size_t len)
134{
135    LCID("PADDING frame in of %zd bytes", len);
136}
137
138
139void
140lsquic_ev_log_ping_frame_in (lsquic_cid_t cid)
141{
142    LCID("PING frame in");
143}
144
145
146void
147lsquic_ev_log_packet_created (lsquic_cid_t cid,
148                                const struct lsquic_packet_out *packet_out)
149{
150    LCID("created packet %"PRIu64"; flags: version=%d, nonce=%d, conn_id=%d",
151        packet_out->po_packno,
152        !!(packet_out->po_flags & PO_VERSION),
153        !!(packet_out->po_flags & PO_NONCE),
154        !!(packet_out->po_flags & PO_CONN_ID));
155}
156
157
158void
159lsquic_ev_log_packet_sent (lsquic_cid_t cid,
160                                const struct lsquic_packet_out *packet_out)
161{
162    char frames[lsquic_frame_types_str_sz];
163    if (lsquic_packet_out_verneg(packet_out))
164        LCID("sent version negotiation packet, size %hu",
165                                                    packet_out->po_data_sz);
166    else if (lsquic_packet_out_pubres(packet_out))
167        LCID("sent public reset packet, size %hu", packet_out->po_data_sz);
168    else if (packet_out->po_flags & PO_GQUIC)
169        LCID("sent packet %"PRIu64", size %hu, frame types: %s",
170            packet_out->po_packno, packet_out->po_enc_data_sz,
171                /* Frame types is a list of different frames types contained
172                 * in the packet, no more.  Count and order of frames is not
173                 * printed.
174                 */
175                lsquic_frame_types_to_str(frames, sizeof(frames),
176                                                packet_out->po_frame_types));
177    else
178        LCID("sent packet %"PRIu64", type %s, crypto: %s, size %hu, frame "
179            "types: %s",
180            packet_out->po_packno, lsquic_hety2str[packet_out->po_header_type],
181            lsquic_enclev2str[ lsquic_packet_out_enc_level(packet_out) ],
182            packet_out->po_enc_data_sz,
183                /* Frame types is a list of different frames types contained
184                 * in the packet, no more.  Count and order of frames is not
185                 * printed.
186                 */
187                lsquic_frame_types_to_str(frames, sizeof(frames),
188                                                packet_out->po_frame_types));
189}
190
191
192void
193lsquic_ev_log_packet_not_sent (lsquic_cid_t cid,
194                                const struct lsquic_packet_out *packet_out)
195{
196    char frames[lsquic_frame_types_str_sz];
197    LCID("unsent packet %"PRIu64", size %hu, frame types: %s",
198        packet_out->po_packno, packet_out->po_enc_data_sz,
199            /* Frame types is a list of different frames types contained in
200             * the packet, no more.  Count and order of frames is not printed.
201             */
202            lsquic_frame_types_to_str(frames, sizeof(frames),
203                                                packet_out->po_frame_types));
204}
205
206
207void
208lsquic_ev_log_http_headers_in (lsquic_cid_t cid, int is_server,
209                                        const struct uncompressed_headers *uh)
210{
211    const char *cr, *p;
212
213    if (uh->uh_flags & UH_PP)
214        LCID("read push promise; stream %"PRIu32", promised stream %"PRIu32,
215            uh->uh_stream_id, uh->uh_oth_stream_id);
216    else
217        LCID("read %s headers; stream: %"PRIu32", depends on stream: %"PRIu32
218            ", weight: %hu, exclusive: %d, fin: %d",
219            is_server ? "request" : "response",
220            uh->uh_stream_id, uh->uh_oth_stream_id, uh->uh_weight,
221            (int) uh->uh_exclusive, !!(uh->uh_flags & UH_FIN));
222
223    for (p = uh->uh_headers; p < uh->uh_headers + uh->uh_size; p = cr + 2)
224    {
225        cr = strchr(p, '\r');
226        if (cr && cr > p)
227            LCID("  %.*s", (int) (cr - p), p);
228        else
229            break;
230    }
231}
232
233
234void
235lsquic_ev_log_action_stream_frame (lsquic_cid_t cid,
236    const struct parse_funcs *pf, const unsigned char *buf, size_t bufsz,
237    const char *what)
238{
239    struct stream_frame frame;
240    int len;
241
242    len = pf->pf_parse_stream_frame(buf, bufsz, &frame);
243    if (len > 0)
244        LCID("%s STREAM frame: stream %"PRIu32", offset: %"PRIu64
245            ", size: %"PRIu16", fin: %d", what, frame.stream_id,
246            frame.data_frame.df_offset, frame.data_frame.df_size,
247            frame.data_frame.df_fin);
248    else
249        LSQ_LOG2(LSQ_LOG_WARN, "cannot parse STREAM frame");
250}
251
252
253void
254lsquic_ev_log_generated_ack_frame (lsquic_cid_t cid, const struct parse_funcs *pf,
255                                   const unsigned char *ack_buf, size_t ack_buf_sz)
256{
257    struct ack_info acki;
258    size_t sz;
259    char *buf;
260    int len;
261
262    len = pf->pf_parse_ack_frame(ack_buf, ack_buf_sz, &acki);
263    if (len < 0)
264    {
265        LSQ_LOG2(LSQ_LOG_WARN, "cannot parse ACK frame");
266        return;
267    }
268
269    if ((buf = acki2str(&acki, &sz)))
270    {
271        LCID("generated ACK frame: %.*s", (int) sz, buf);
272        free(buf);
273    }
274}
275
276
277void
278lsquic_ev_log_generated_stop_waiting_frame (lsquic_cid_t cid,
279                                            lsquic_packno_t lunack)
280{
281    LCID("generated STOP_WAITING frame; least unacked: %"PRIu64, lunack);
282}
283
284
285void
286lsquic_ev_log_generated_http_headers (lsquic_cid_t cid, uint32_t stream_id,
287                    int is_server, const struct http_prio_frame *prio_frame,
288                    const struct lsquic_http_headers *headers)
289{
290    uint32_t dep_stream_id;
291    int exclusive, i;
292    unsigned short weight;
293
294    if (is_server)
295        LCID("generated HTTP response HEADERS for stream %"PRIu32, stream_id);
296    else
297    {
298        memcpy(&dep_stream_id, prio_frame->hpf_stream_id, 4);
299        dep_stream_id = htonl(dep_stream_id);
300        exclusive = dep_stream_id >> 31;
301        dep_stream_id &= ~(1 << 31);
302        weight = prio_frame->hpf_weight + 1;
303        LCID("generated HTTP request HEADERS for stream %"PRIu32
304            ", dep stream: %"PRIu32", weight: %hu, exclusive: %d", stream_id,
305            dep_stream_id, weight, exclusive);
306    }
307
308    for (i = 0; i < headers->count; ++i)
309        LCID("  %.*s: %.*s",
310            (int)    headers->headers[i].name.iov_len,
311            (char *) headers->headers[i].name.iov_base,
312            (int)    headers->headers[i].value.iov_len,
313            (char *) headers->headers[i].value.iov_base);
314}
315
316
317void
318lsquic_ev_log_generated_http_push_promise (lsquic_cid_t cid,
319                            uint32_t stream_id, uint32_t promised_stream_id,
320                            const struct lsquic_http_headers *headers,
321                            const struct lsquic_http_headers *extra_headers)
322{
323    int i;
324
325    LCID("generated HTTP PUSH_PROMISE for stream %"PRIu32"; promised stream %"
326        PRIu32, stream_id, promised_stream_id);
327
328    for (i = 0; i < headers->count; ++i)
329        LCID("  %.*s: %.*s",
330            (int)    headers->headers[i].name.iov_len,
331            (char *) headers->headers[i].name.iov_base,
332            (int)    headers->headers[i].value.iov_len,
333            (char *) headers->headers[i].value.iov_base);
334
335    if (extra_headers)
336        for (i = 0; i < extra_headers->count; ++i)
337            LCID("  %.*s: %.*s",
338                (int)    extra_headers->headers[i].name.iov_len,
339                (char *) extra_headers->headers[i].name.iov_base,
340                (int)    extra_headers->headers[i].value.iov_len,
341                (char *) extra_headers->headers[i].value.iov_base);
342}
343