lsquic_ev_log.c revision 5392f7a3 
1/* Copyright (c) 2017 - 2019 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_gquic.h"
18#include "lsquic_packet_in.h"
19#include "lsquic_packet_out.h"
20#include "lsquic_parse.h"
21#include "lsquic_frame_common.h"
22#include "lsquic_headers.h"
23#include "lsquic_str.h"
24#include "lsquic_frame_reader.h"
25#include "lsquic_enc_sess.h"
26#include "lsquic_ev_log.h"
27#include "lsquic_sizes.h"
28#include "lsquic_trans_params.h"
29#include "lsquic_util.h"
30#include "lsquic_hash.h"
31#include "lsquic_conn.h"
32
33#define LSQUIC_LOGGER_MODULE LSQLM_EVENT
34#include "lsquic_logger.h"
35
36
37/*  ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^  */
38/*  ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||  */
39/* Messages that do not include connection ID go above this point */
40
41#define LSQUIC_LOG_CONN_ID cid
42#define LCID(...) LSQ_LOG2(LSQ_LOG_DEBUG, __VA_ARGS__)   /* LCID: log with CID */
43
44/* Messages that are to include connection ID go below this point */
45/*  ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||  */
46/*  VVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVV  */
47
48void
49lsquic_ev_log_packet_in (const lsquic_cid_t *cid,
50                                        const lsquic_packet_in_t *packet_in)
51{
52    switch (packet_in->pi_flags & (
53                                   PI_FROM_MINI|
54                                                PI_GQUIC))
55    {
56    case PI_FROM_MINI|PI_GQUIC:
57        LCID("packet in: %"PRIu64" (from mini)", packet_in->pi_packno);
58        break;
59    case PI_FROM_MINI:
60        LCID("packet in: %"PRIu64" (from mini), type: %s, ecn: %u",
61            packet_in->pi_packno, lsquic_hety2str[packet_in->pi_header_type],
62            lsquic_packet_in_ecn(packet_in));
63        break;
64    case PI_GQUIC:
65        LCID("packet in: %"PRIu64", size: %u", packet_in->pi_packno,
66            (unsigned) (packet_in->pi_data_sz + GQUIC_PACKET_HASH_SZ));
67        break;
68    default:
69        LCID("packet in: %"PRIu64", type: %s, size: %u; ecn: %u, spin: %d; "
70            "path: %hhu",
71            packet_in->pi_packno, lsquic_hety2str[packet_in->pi_header_type],
72            (unsigned) (packet_in->pi_data_sz + IQUIC_TAG_LEN),
73            lsquic_packet_in_ecn(packet_in),
74            /* spin bit value is only valid for short packet headers */
75            lsquic_packet_in_spin_bit(packet_in), packet_in->pi_path_id);
76        break;
77    }
78}
79
80
81void
82lsquic_ev_log_ack_frame_in (const lsquic_cid_t *cid,
83                                        const struct ack_info *acki)
84{
85    size_t sz;
86    char *buf;
87
88    if ((buf = acki2str(acki, &sz)))
89    {
90        LCID("ACK frame in: %.*s", (int) sz, buf);
91        free(buf);
92    }
93}
94
95
96void
97lsquic_ev_log_stream_frame_in (const lsquic_cid_t *cid,
98                                        const struct stream_frame *frame)
99{
100    LCID("STREAM frame in: stream %"PRIu64"; offset %"PRIu64"; size %"PRIu16
101        "; fin: %d", frame->stream_id, frame->data_frame.df_offset,
102        frame->data_frame.df_size, (int) frame->data_frame.df_fin);
103}
104
105
106void
107lsquic_ev_log_crypto_frame_in (const lsquic_cid_t *cid,
108                        const struct stream_frame *frame, unsigned enc_level)
109{
110    LCID("CRYPTO frame in: level %u; offset %"PRIu64"; size %"PRIu16,
111        enc_level, frame->data_frame.df_offset, frame->data_frame.df_size);
112}
113
114
115void
116lsquic_ev_log_stop_waiting_frame_in (const lsquic_cid_t *cid,
117                                                        lsquic_packno_t least)
118{
119    LCID("STOP_WAITING frame in: least unacked packno %"PRIu64, least);
120}
121
122
123void
124lsquic_ev_log_window_update_frame_in (const lsquic_cid_t *cid,
125                                lsquic_stream_id_t stream_id, uint64_t offset)
126{
127    LCID("WINDOW_UPDATE frame in: stream %"PRIu64"; offset %"PRIu64,
128        stream_id, offset);
129}
130
131
132void
133lsquic_ev_log_blocked_frame_in (const lsquic_cid_t *cid,
134                                            lsquic_stream_id_t stream_id)
135{
136    LCID("BLOCKED frame in: stream %"PRIu64, stream_id);
137}
138
139
140void
141lsquic_ev_log_connection_close_frame_in (const lsquic_cid_t *cid,
142                    uint64_t error_code, int reason_len, const char *reason)
143{
144    LCID("CONNECTION_CLOSE frame in: error code %"PRIu64", reason: %.*s",
145        error_code, reason_len, reason);
146}
147
148
149void
150lsquic_ev_log_goaway_frame_in (const lsquic_cid_t *cid, uint32_t error_code,
151            lsquic_stream_id_t stream_id, int reason_len, const char *reason)
152{
153    LCID("GOAWAY frame in: error code %"PRIu32", stream %"PRIu64
154        ", reason: %.*s", error_code, stream_id, reason_len, reason);
155}
156
157
158void
159lsquic_ev_log_rst_stream_frame_in (const lsquic_cid_t *cid,
160        lsquic_stream_id_t stream_id, uint64_t offset, uint64_t error_code)
161{
162    LCID("RST_STREAM frame in: error code %"PRIu64", stream %"PRIu64
163        ", offset: %"PRIu64, error_code, stream_id, offset);
164}
165
166
167void
168lsquic_ev_log_stop_sending_frame_in (const lsquic_cid_t *cid,
169                        lsquic_stream_id_t stream_id, uint64_t error_code)
170{
171    LCID("STOP_SENDING frame in: error code %"PRIu64", stream %"PRIu64,
172                                                     error_code, stream_id);
173}
174
175
176void
177lsquic_ev_log_padding_frame_in (const lsquic_cid_t *cid, size_t len)
178{
179    LCID("PADDING frame in of %zd bytes", len);
180}
181
182
183void
184lsquic_ev_log_ping_frame_in (const lsquic_cid_t *cid)
185{
186    LCID("PING frame in");
187}
188
189
190void
191lsquic_ev_log_packet_created (const lsquic_cid_t *cid,
192                                const struct lsquic_packet_out *packet_out)
193{
194    LCID("created packet %"PRIu64"; flags: version=%d, nonce=%d, conn_id=%d",
195        packet_out->po_packno,
196        !!(packet_out->po_flags & PO_VERSION),
197        !!(packet_out->po_flags & PO_NONCE),
198        !!(packet_out->po_flags & PO_CONN_ID));
199}
200
201
202void
203lsquic_ev_log_packet_sent (const lsquic_cid_t *cid,
204                                const struct lsquic_packet_out *packet_out)
205{
206    char frames[lsquic_frame_types_str_sz];
207    if (lsquic_packet_out_verneg(packet_out))
208        LCID("sent version negotiation packet, size %hu",
209                                                    packet_out->po_data_sz);
210    else if (lsquic_packet_out_retry(packet_out))
211        LCID("sent stateless retry packet, size %hu", packet_out->po_data_sz);
212    else if (lsquic_packet_out_pubres(packet_out))
213        LCID("sent public reset packet, size %hu", packet_out->po_data_sz);
214    else if (packet_out->po_lflags & POL_GQUIC)
215        LCID("sent packet %"PRIu64", size %hu, frame types: %s",
216            packet_out->po_packno, packet_out->po_enc_data_sz,
217                /* Frame types is a list of different frames types contained
218                 * in the packet, no more.  Count and order of frames is not
219                 * printed.
220                 */
221                lsquic_frame_types_to_str(frames, sizeof(frames),
222                                                packet_out->po_frame_types));
223    else
224        LCID("sent packet %"PRIu64", type %s, crypto: %s, size %hu, frame "
225            "types: %s, ecn: %u, spin: %d; kp: %u, path: %hhu",
226            packet_out->po_packno, lsquic_hety2str[packet_out->po_header_type],
227            lsquic_enclev2str[ lsquic_packet_out_enc_level(packet_out) ],
228            packet_out->po_enc_data_sz,
229                /* Frame types is a list of different frames types contained
230                 * in the packet, no more.  Count and order of frames is not
231                 * printed.
232                 */
233                lsquic_frame_types_to_str(frames, sizeof(frames),
234                                                packet_out->po_frame_types),
235                lsquic_packet_out_ecn(packet_out),
236                /* spin bit value is only valid for short packet headers */
237                lsquic_packet_out_spin_bit(packet_out),
238                lsquic_packet_out_kp(packet_out),
239                packet_out->po_path->np_path_id);
240}
241
242
243void
244lsquic_ev_log_packet_not_sent (const lsquic_cid_t *cid,
245                                const struct lsquic_packet_out *packet_out)
246{
247    char frames[lsquic_frame_types_str_sz];
248    LCID("unsent packet %"PRIu64", size %hu, frame types: %s",
249        packet_out->po_packno, packet_out->po_enc_data_sz,
250            /* Frame types is a list of different frames types contained in
251             * the packet, no more.  Count and order of frames is not printed.
252             */
253            lsquic_frame_types_to_str(frames, sizeof(frames),
254                                                packet_out->po_frame_types));
255}
256
257
258void
259lsquic_ev_log_http_headers_in (const lsquic_cid_t *cid, int is_server,
260                                        const struct uncompressed_headers *uh)
261{
262    const struct http1x_headers *h1h;
263    const char *cr, *p;
264
265    if (uh->uh_flags & UH_PP)
266        LCID("read push promise; stream %"PRIu64", promised stream %"PRIu64,
267            uh->uh_stream_id, uh->uh_oth_stream_id);
268    else
269        LCID("read %s headers; stream: %"PRIu64", depends on stream: %"PRIu64
270            ", weight: %hu, exclusive: %d, fin: %d",
271            is_server ? "request" : "response",
272            uh->uh_stream_id, uh->uh_oth_stream_id, uh->uh_weight,
273            (int) uh->uh_exclusive, !!(uh->uh_flags & UH_FIN));
274
275    if (uh->uh_flags & UH_H1H)
276    {
277        h1h = uh->uh_hset;
278        for (p = h1h->h1h_buf; p < h1h->h1h_buf + h1h->h1h_size; p = cr + 2)
279        {
280            cr = strchr(p, '\r');
281            if (cr && cr > p)
282                LCID("  %.*s", (int) (cr - p), p);
283            else
284                break;
285        }
286    }
287}
288
289
290void
291lsquic_ev_log_action_stream_frame (const lsquic_cid_t *cid,
292    const struct parse_funcs *pf, const unsigned char *buf, size_t bufsz,
293    const char *what)
294{
295    struct stream_frame frame;
296    int len;
297
298    len = pf->pf_parse_stream_frame(buf, bufsz, &frame);
299    if (len > 0)
300        LCID("%s STREAM frame: stream %"PRIu64", offset: %"PRIu64
301            ", size: %"PRIu16", fin: %d", what, frame.stream_id,
302            frame.data_frame.df_offset, frame.data_frame.df_size,
303            frame.data_frame.df_fin);
304    else
305        LSQ_LOG2(LSQ_LOG_WARN, "cannot parse STREAM frame");
306}
307
308
309void
310lsquic_ev_log_generated_crypto_frame (const lsquic_cid_t *cid,
311       const struct parse_funcs *pf, const unsigned char *buf, size_t bufsz)
312{
313    struct stream_frame frame;
314    int len;
315
316    len = pf->pf_parse_crypto_frame(buf, bufsz, &frame);
317    if (len > 0)
318        LCID("generated CRYPTO frame: offset: %"PRIu64", size: %"PRIu16,
319            frame.data_frame.df_offset, frame.data_frame.df_size);
320    else
321        LSQ_LOG2(LSQ_LOG_WARN, "cannot parse CRYPTO frame");
322}
323
324
325void
326lsquic_ev_log_generated_ack_frame (const lsquic_cid_t *cid,
327                const struct parse_funcs *pf, const unsigned char *ack_buf,
328                size_t ack_buf_sz)
329{
330    struct ack_info acki;
331    size_t sz;
332    char *buf;
333    int len;
334
335    len = pf->pf_parse_ack_frame(ack_buf, ack_buf_sz, &acki,
336                                                    TP_DEF_ACK_DELAY_EXP);
337    if (len < 0)
338    {
339        LSQ_LOG2(LSQ_LOG_WARN, "cannot parse ACK frame");
340        return;
341    }
342
343    if ((buf = acki2str(&acki, &sz)))
344    {
345        LCID("generated ACK frame: %.*s", (int) sz, buf);
346        free(buf);
347    }
348}
349
350
351void
352lsquic_ev_log_generated_new_token_frame (const lsquic_cid_t *cid,
353                const struct parse_funcs *pf, const unsigned char *frame_buf,
354                size_t frame_buf_sz)
355{
356    const unsigned char *token;
357    size_t sz;
358    char *buf;
359    int len;
360
361    len = pf->pf_parse_new_token_frame(frame_buf, frame_buf_sz, &token, &sz);
362    if (len < 0)
363    {
364        LSQ_LOG2(LSQ_LOG_WARN, "cannot parse NEW_TOKEN frame");
365        return;
366    }
367
368    buf = malloc(sz * 2 + 1);
369    if (buf)
370    {
371        lsquic_hexstr(token, sz, buf, sz * 2 + 1);
372        LCID("generated NEW_TOKEN frame: %s", buf);
373        free(buf);
374    }
375}
376
377
378void
379lsquic_ev_log_generated_path_chal_frame (const lsquic_cid_t *cid,
380                const struct parse_funcs *pf, const unsigned char *frame_buf,
381                size_t frame_buf_sz)
382{
383    uint64_t chal;
384    int len;
385    char hexbuf[sizeof(chal) * 2 + 1];
386
387    len = pf->pf_parse_path_chal_frame(frame_buf, frame_buf_sz, &chal);
388    if (len > 0)
389        LCID("generated PATH_CHALLENGE(%s) frame",
390                        HEXSTR((unsigned char *) &chal, sizeof(chal), hexbuf));
391    else
392        LSQ_LOG2(LSQ_LOG_WARN, "cannot parse PATH_CHALLENGE frame");
393}
394
395
396void
397lsquic_ev_log_generated_path_resp_frame (const lsquic_cid_t *cid,
398                const struct parse_funcs *pf, const unsigned char *frame_buf,
399                size_t frame_buf_sz)
400{
401    uint64_t resp;
402    int len;
403    char hexbuf[sizeof(resp) * 2 + 1];
404
405    len = pf->pf_parse_path_resp_frame(frame_buf, frame_buf_sz, &resp);
406    if (len > 0)
407        LCID("generated PATH_RESPONSE(%s) frame",
408                        HEXSTR((unsigned char *) &resp, sizeof(resp), hexbuf));
409    else
410        LSQ_LOG2(LSQ_LOG_WARN, "cannot parse PATH_RESPONSE frame");
411}
412
413
414void
415lsquic_ev_log_generated_new_connection_id_frame (const lsquic_cid_t *cid,
416                const struct parse_funcs *pf, const unsigned char *frame_buf,
417                size_t frame_buf_sz)
418{
419    const unsigned char *token;
420    lsquic_cid_t new_cid;
421    uint64_t seqno, retire_prior_to;
422    int len;
423    char token_buf[IQUIC_SRESET_TOKEN_SZ * 2 + 1];
424    char cid_buf[MAX_CID_LEN * 2 + 1];
425
426    len = pf->pf_parse_new_conn_id(frame_buf, frame_buf_sz, &seqno,
427                                        &retire_prior_to, &new_cid, &token);
428    if (len < 0)
429    {
430        LSQ_LOG2(LSQ_LOG_WARN, "cannot parse NEW_CONNECTION_ID frame");
431        return;
432    }
433
434    lsquic_hexstr(new_cid.idbuf, new_cid.len, cid_buf, sizeof(cid_buf));
435    lsquic_hexstr(token, IQUIC_SRESET_TOKEN_SZ, token_buf, sizeof(token_buf));
436    LCID("generated NEW_CONNECTION_ID frame: seqno: %"PRIu64"; retire prior "
437        "to: %"PRIu64"; cid: %s; token: %s", seqno, retire_prior_to,
438        cid_buf, token_buf);
439}
440
441
442void
443lsquic_ev_log_generated_stop_waiting_frame (const lsquic_cid_t *cid,
444                                            lsquic_packno_t lunack)
445{
446    LCID("generated STOP_WAITING frame; least unacked: %"PRIu64, lunack);
447}
448
449
450void
451lsquic_ev_log_generated_stop_sending_frame (const lsquic_cid_t *cid,
452                            lsquic_stream_id_t stream_id, uint16_t error_code)
453{
454    LCID("generated STOP_SENDING frame; stream ID: %"PRIu64"; error code: "
455                                            "%"PRIu16, stream_id, error_code);
456}
457
458
459void
460lsquic_ev_log_generated_http_headers (const lsquic_cid_t *cid,
461                    lsquic_stream_id_t stream_id,
462                    int is_server, const struct http_prio_frame *prio_frame,
463                    const struct lsquic_http_headers *headers)
464{
465    lsquic_stream_id_t dep_stream_id;
466    int exclusive, i;
467    unsigned short weight;
468
469    if (is_server)
470        LCID("generated HTTP response HEADERS for stream %"PRIu64, stream_id);
471    else
472    {
473        memcpy(&dep_stream_id, prio_frame->hpf_stream_id, 4);
474        dep_stream_id = htonl(dep_stream_id);
475        exclusive = dep_stream_id >> 31;
476        dep_stream_id &= ~(1 << 31);
477        weight = prio_frame->hpf_weight + 1;
478        LCID("generated HTTP request HEADERS for stream %"PRIu64
479            ", dep stream: %"PRIu64", weight: %hu, exclusive: %d", stream_id,
480            dep_stream_id, weight, exclusive);
481    }
482
483    for (i = 0; i < headers->count; ++i)
484        LCID("  %.*s: %.*s",
485            (int)    headers->headers[i].name.iov_len,
486            (char *) headers->headers[i].name.iov_base,
487            (int)    headers->headers[i].value.iov_len,
488            (char *) headers->headers[i].value.iov_base);
489}
490
491
492void
493lsquic_ev_log_generated_http_push_promise (const lsquic_cid_t *cid,
494            lsquic_stream_id_t stream_id, lsquic_stream_id_t promised_stream_id,
495            const struct lsquic_http_headers *headers,
496            const struct lsquic_http_headers *extra_headers)
497{
498    int i;
499
500    LCID("generated HTTP PUSH_PROMISE for stream %"PRIu64"; promised stream %"
501        PRIu64, stream_id, promised_stream_id);
502
503    for (i = 0; i < headers->count; ++i)
504        LCID("  %.*s: %.*s",
505            (int)    headers->headers[i].name.iov_len,
506            (char *) headers->headers[i].name.iov_base,
507            (int)    headers->headers[i].value.iov_len,
508            (char *) headers->headers[i].value.iov_base);
509
510    if (extra_headers)
511        for (i = 0; i < extra_headers->count; ++i)
512            LCID("  %.*s: %.*s",
513                (int)    extra_headers->headers[i].name.iov_len,
514                (char *) extra_headers->headers[i].name.iov_base,
515                (int)    extra_headers->headers[i].value.iov_len,
516                (char *) extra_headers->headers[i].value.iov_base);
517}
518
519void
520lsquic_ev_log_create_connection (const lsquic_cid_t *cid,
521                                    const struct sockaddr *local_sa,
522                                    const struct sockaddr *peer_sa)
523{
524    LCID("connection created");
525}
526
527
528void
529lsquic_ev_log_hsk_completed (const lsquic_cid_t *cid)
530{
531    LCID("handshake completed");
532}
533
534
535void
536lsquic_ev_log_zero_rtt (const lsquic_cid_t *cid)
537{
538    LCID("zero_rtt successful");
539}
540
541
542void
543lsquic_ev_log_check_certs (const lsquic_cid_t *cid, const lsquic_str_t **certs,
544                                                                size_t count)
545{
546    LCID("check certs");
547}
548
549
550void
551lsquic_ev_log_version_negotiation (const lsquic_cid_t *cid,
552                                        const char *action, const char *ver)
553{
554    LCID("version negotiation: %s version %s", action, ver);
555}
556