lsquic_ev_log.c revision 3b55e6ae 
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_headers.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 struct http1x_headers *h1h;
212    const char *cr, *p;
213
214    if (uh->uh_flags & UH_PP)
215        LCID("read push promise; stream %"PRIu32", promised stream %"PRIu32,
216            uh->uh_stream_id, uh->uh_oth_stream_id);
217    else
218        LCID("read %s headers; stream: %"PRIu32", depends on stream: %"PRIu32
219            ", weight: %hu, exclusive: %d, fin: %d",
220            is_server ? "request" : "response",
221            uh->uh_stream_id, uh->uh_oth_stream_id, uh->uh_weight,
222            (int) uh->uh_exclusive, !!(uh->uh_flags & UH_FIN));
223
224    if (uh->uh_flags & UH_H1H)
225    {
226        h1h = uh->uh_hset;
227        for (p = h1h->h1h_buf; p < h1h->h1h_buf + h1h->h1h_size; p = cr + 2)
228        {
229            cr = strchr(p, '\r');
230            if (cr && cr > p)
231                LCID("  %.*s", (int) (cr - p), p);
232            else
233                break;
234        }
235    }
236}
237
238
239void
240lsquic_ev_log_action_stream_frame (lsquic_cid_t cid,
241    const struct parse_funcs *pf, const unsigned char *buf, size_t bufsz,
242    const char *what)
243{
244    struct stream_frame frame;
245    int len;
246
247    len = pf->pf_parse_stream_frame(buf, bufsz, &frame);
248    if (len > 0)
249        LCID("%s STREAM frame: stream %"PRIu32", offset: %"PRIu64
250            ", size: %"PRIu16", fin: %d", what, frame.stream_id,
251            frame.data_frame.df_offset, frame.data_frame.df_size,
252            frame.data_frame.df_fin);
253    else
254        LSQ_LOG2(LSQ_LOG_WARN, "cannot parse STREAM frame");
255}
256
257
258void
259lsquic_ev_log_generated_ack_frame (lsquic_cid_t cid, const struct parse_funcs *pf,
260                                   const unsigned char *ack_buf, size_t ack_buf_sz)
261{
262    struct ack_info acki;
263    size_t sz;
264    char *buf;
265    int len;
266
267    len = pf->pf_parse_ack_frame(ack_buf, ack_buf_sz, &acki);
268    if (len < 0)
269    {
270        LSQ_LOG2(LSQ_LOG_WARN, "cannot parse ACK frame");
271        return;
272    }
273
274    if ((buf = acki2str(&acki, &sz)))
275    {
276        LCID("generated ACK frame: %.*s", (int) sz, buf);
277        free(buf);
278    }
279}
280
281
282void
283lsquic_ev_log_generated_stop_waiting_frame (lsquic_cid_t cid,
284                                            lsquic_packno_t lunack)
285{
286    LCID("generated STOP_WAITING frame; least unacked: %"PRIu64, lunack);
287}
288
289
290void
291lsquic_ev_log_generated_http_headers (lsquic_cid_t cid, uint32_t stream_id,
292                    int is_server, const struct http_prio_frame *prio_frame,
293                    const struct lsquic_http_headers *headers)
294{
295    uint32_t dep_stream_id;
296    int exclusive, i;
297    unsigned short weight;
298
299    if (is_server)
300        LCID("generated HTTP response HEADERS for stream %"PRIu32, stream_id);
301    else
302    {
303        memcpy(&dep_stream_id, prio_frame->hpf_stream_id, 4);
304        dep_stream_id = htonl(dep_stream_id);
305        exclusive = dep_stream_id >> 31;
306        dep_stream_id &= ~(1 << 31);
307        weight = prio_frame->hpf_weight + 1;
308        LCID("generated HTTP request HEADERS for stream %"PRIu32
309            ", dep stream: %"PRIu32", weight: %hu, exclusive: %d", stream_id,
310            dep_stream_id, weight, exclusive);
311    }
312
313    for (i = 0; i < headers->count; ++i)
314        LCID("  %.*s: %.*s",
315            (int)    headers->headers[i].name.iov_len,
316            (char *) headers->headers[i].name.iov_base,
317            (int)    headers->headers[i].value.iov_len,
318            (char *) headers->headers[i].value.iov_base);
319}
320
321
322void
323lsquic_ev_log_generated_http_push_promise (lsquic_cid_t cid,
324                            uint32_t stream_id, uint32_t promised_stream_id,
325                            const struct lsquic_http_headers *headers,
326                            const struct lsquic_http_headers *extra_headers)
327{
328    int i;
329
330    LCID("generated HTTP PUSH_PROMISE for stream %"PRIu32"; promised stream %"
331        PRIu32, stream_id, promised_stream_id);
332
333    for (i = 0; i < headers->count; ++i)
334        LCID("  %.*s: %.*s",
335            (int)    headers->headers[i].name.iov_len,
336            (char *) headers->headers[i].name.iov_base,
337            (int)    headers->headers[i].value.iov_len,
338            (char *) headers->headers[i].value.iov_base);
339
340    if (extra_headers)
341        for (i = 0; i < extra_headers->count; ++i)
342            LCID("  %.*s: %.*s",
343                (int)    extra_headers->headers[i].name.iov_len,
344                (char *) extra_headers->headers[i].name.iov_base,
345                (int)    extra_headers->headers[i].value.iov_len,
346                (char *) extra_headers->headers[i].value.iov_base);
347}
348