lsquic_ev_log.c revision c51ce338
150aadb33SDmitri Tikhonov/* Copyright (c) 2017 LiteSpeed Technologies Inc.  See LICENSE. */
250aadb33SDmitri Tikhonov#include <arpa/inet.h>
350aadb33SDmitri Tikhonov#include <errno.h>
450aadb33SDmitri Tikhonov#include <inttypes.h>
550aadb33SDmitri Tikhonov#include <stdlib.h>
650aadb33SDmitri Tikhonov#include <string.h>
750aadb33SDmitri Tikhonov
850aadb33SDmitri Tikhonov#include "lsquic.h"
950aadb33SDmitri Tikhonov#include "lsquic_types.h"
1050aadb33SDmitri Tikhonov#include "lsquic_int_types.h"
1150aadb33SDmitri Tikhonov#include "lsquic_packet_common.h"
1250aadb33SDmitri Tikhonov#include "lsquic_packet_in.h"
1350aadb33SDmitri Tikhonov#include "lsquic_packet_out.h"
1450aadb33SDmitri Tikhonov#include "lsquic_parse.h"
1550aadb33SDmitri Tikhonov#include "lsquic_frame_common.h"
1650aadb33SDmitri Tikhonov#include "lsquic_frame_reader.h"
1750aadb33SDmitri Tikhonov#include "lsquic_ev_log.h"
1850aadb33SDmitri Tikhonov
1950aadb33SDmitri Tikhonov#define LSQUIC_LOGGER_MODULE LSQLM_EVENT
2050aadb33SDmitri Tikhonov#include "lsquic_logger.h"
2150aadb33SDmitri Tikhonov
2250aadb33SDmitri Tikhonov
2350aadb33SDmitri Tikhonov/*  ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^  */
2450aadb33SDmitri Tikhonov/*  ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||  */
2550aadb33SDmitri Tikhonov/* Messages that do not include connection ID go above this point */
2650aadb33SDmitri Tikhonov
2750aadb33SDmitri Tikhonov#define LSQUIC_LOG_CONN_ID cid
2850aadb33SDmitri Tikhonov#define LCID(a...) LSQ_LOG2(LSQ_LOG_DEBUG, a)   /* LCID: log with CID */
2950aadb33SDmitri Tikhonov
3050aadb33SDmitri Tikhonov/* Messages that are to include connection ID go below this point */
3150aadb33SDmitri Tikhonov/*  ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||  */
3250aadb33SDmitri Tikhonov/*  VVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVVV  */
3350aadb33SDmitri Tikhonov
3450aadb33SDmitri Tikhonovvoid
3550aadb33SDmitri Tikhonovlsquic_ev_log_packet_in (lsquic_cid_t cid, const lsquic_packet_in_t *packet_in)
3650aadb33SDmitri Tikhonov{
3750aadb33SDmitri Tikhonov        LCID("packet in: %"PRIu64, packet_in->pi_packno);
3850aadb33SDmitri Tikhonov}
3950aadb33SDmitri Tikhonov
4050aadb33SDmitri Tikhonov
4150aadb33SDmitri Tikhonovvoid
4250aadb33SDmitri Tikhonovlsquic_ev_log_ack_frame_in (lsquic_cid_t cid, const struct ack_info *acki)
4350aadb33SDmitri Tikhonov{
4450aadb33SDmitri Tikhonov    size_t sz;
4550aadb33SDmitri Tikhonov    char *buf;
4650aadb33SDmitri Tikhonov
4750aadb33SDmitri Tikhonov    if ((buf = acki2str(acki, &sz)))
4850aadb33SDmitri Tikhonov    {
4950aadb33SDmitri Tikhonov        LCID("ACK frame in: %.*s", (int) sz, buf);
5050aadb33SDmitri Tikhonov        free(buf);
5150aadb33SDmitri Tikhonov    }
5250aadb33SDmitri Tikhonov}
5350aadb33SDmitri Tikhonov
5450aadb33SDmitri Tikhonov
5550aadb33SDmitri Tikhonovvoid
5650aadb33SDmitri Tikhonovlsquic_ev_log_stream_frame_in (lsquic_cid_t cid,
5750aadb33SDmitri Tikhonov                                        const struct stream_frame *frame)
5850aadb33SDmitri Tikhonov{
5950aadb33SDmitri Tikhonov    LCID("STREAM frame in: stream %u; offset %"PRIu64"; size %"PRIu16
6050aadb33SDmitri Tikhonov        "; fin: %d", frame->stream_id, frame->data_frame.df_offset,
6150aadb33SDmitri Tikhonov        frame->data_frame.df_size, (int) frame->data_frame.df_fin);
6250aadb33SDmitri Tikhonov}
6350aadb33SDmitri Tikhonov
6450aadb33SDmitri Tikhonov
6550aadb33SDmitri Tikhonovvoid
6650aadb33SDmitri Tikhonovlsquic_ev_log_stop_waiting_frame_in (lsquic_cid_t cid, lsquic_packno_t least)
6750aadb33SDmitri Tikhonov{
6850aadb33SDmitri Tikhonov    LCID("STOP_WAITING frame in: least unacked packno %"PRIu64, least);
6950aadb33SDmitri Tikhonov}
7050aadb33SDmitri Tikhonov
7150aadb33SDmitri Tikhonov
7250aadb33SDmitri Tikhonovvoid
7350aadb33SDmitri Tikhonovlsquic_ev_log_window_update_frame_in (lsquic_cid_t cid, uint32_t stream_id,
7450aadb33SDmitri Tikhonov                                                            uint64_t offset)
7550aadb33SDmitri Tikhonov{
7650aadb33SDmitri Tikhonov    LCID("WINDOW_UPDATE frame in: stream %"PRIu32"; offset %"PRIu64,
7750aadb33SDmitri Tikhonov        stream_id, offset);
7850aadb33SDmitri Tikhonov}
7950aadb33SDmitri Tikhonov
8050aadb33SDmitri Tikhonov
8150aadb33SDmitri Tikhonovvoid
8250aadb33SDmitri Tikhonovlsquic_ev_log_blocked_frame_in (lsquic_cid_t cid, uint32_t stream_id)
8350aadb33SDmitri Tikhonov{
8450aadb33SDmitri Tikhonov    LCID("BLOCKED frame in: stream %"PRIu32, stream_id);
8550aadb33SDmitri Tikhonov}
8650aadb33SDmitri Tikhonov
8750aadb33SDmitri Tikhonov
8850aadb33SDmitri Tikhonovvoid
8950aadb33SDmitri Tikhonovlsquic_ev_log_connection_close_frame_in (lsquic_cid_t cid,
9050aadb33SDmitri Tikhonov                    uint32_t error_code, int reason_len, const char *reason)
9150aadb33SDmitri Tikhonov{
9250aadb33SDmitri Tikhonov    LCID("CONNECTION_CLOSE frame in: error code %"PRIu32", reason: %.*s",
9350aadb33SDmitri Tikhonov        error_code, reason_len, reason);
9450aadb33SDmitri Tikhonov}
9550aadb33SDmitri Tikhonov
9650aadb33SDmitri Tikhonov
9750aadb33SDmitri Tikhonovvoid
9850aadb33SDmitri Tikhonovlsquic_ev_log_goaway_frame_in (lsquic_cid_t cid, uint32_t error_code,
9950aadb33SDmitri Tikhonov                    uint32_t stream_id, int reason_len, const char *reason)
10050aadb33SDmitri Tikhonov{
10150aadb33SDmitri Tikhonov    LCID("GOAWAY frame in: error code %"PRIu32", stream %"PRIu32
10250aadb33SDmitri Tikhonov        ", reason: %.*s", error_code, stream_id, reason_len, reason);
10350aadb33SDmitri Tikhonov}
10450aadb33SDmitri Tikhonov
10550aadb33SDmitri Tikhonov
10650aadb33SDmitri Tikhonovvoid
10750aadb33SDmitri Tikhonovlsquic_ev_log_rst_stream_frame_in (lsquic_cid_t cid, uint32_t stream_id,
10850aadb33SDmitri Tikhonov                                        uint64_t offset, uint32_t error_code)
10950aadb33SDmitri Tikhonov{
11050aadb33SDmitri Tikhonov    LCID("RST_FRAME frame in: error code %"PRIu32", stream %"PRIu32
11150aadb33SDmitri Tikhonov        ", offset: %"PRIu64, error_code, stream_id, offset);
11250aadb33SDmitri Tikhonov}
11350aadb33SDmitri Tikhonov
11450aadb33SDmitri Tikhonov
11550aadb33SDmitri Tikhonovvoid
11650aadb33SDmitri Tikhonovlsquic_ev_log_padding_frame_in (lsquic_cid_t cid, size_t len)
11750aadb33SDmitri Tikhonov{
11850aadb33SDmitri Tikhonov    LCID("PADDING frame in of %zd bytes", len);
11950aadb33SDmitri Tikhonov}
12050aadb33SDmitri Tikhonov
12150aadb33SDmitri Tikhonov
12250aadb33SDmitri Tikhonovvoid
12350aadb33SDmitri Tikhonovlsquic_ev_log_ping_frame_in (lsquic_cid_t cid)
12450aadb33SDmitri Tikhonov{
12550aadb33SDmitri Tikhonov    LCID("PING frame in");
12650aadb33SDmitri Tikhonov}
12750aadb33SDmitri Tikhonov
12850aadb33SDmitri Tikhonov
12950aadb33SDmitri Tikhonovvoid
13050aadb33SDmitri Tikhonovlsquic_ev_log_packet_created (lsquic_cid_t cid,
13150aadb33SDmitri Tikhonov                                const struct lsquic_packet_out *packet_out)
13250aadb33SDmitri Tikhonov{
13350aadb33SDmitri Tikhonov    LCID("created packet %"PRIu64"; flags: version=%d, nonce=%d, conn_id=%d",
13450aadb33SDmitri Tikhonov        packet_out->po_packno,
13550aadb33SDmitri Tikhonov        !!(packet_out->po_flags & PO_VERSION),
13650aadb33SDmitri Tikhonov        !!(packet_out->po_flags & PO_NONCE),
13750aadb33SDmitri Tikhonov        !!(packet_out->po_flags & PO_CONN_ID));
13850aadb33SDmitri Tikhonov}
13950aadb33SDmitri Tikhonov
14050aadb33SDmitri Tikhonov
14150aadb33SDmitri Tikhonovvoid
14250aadb33SDmitri Tikhonovlsquic_ev_log_packet_sent (lsquic_cid_t cid,
14350aadb33SDmitri Tikhonov                                const struct lsquic_packet_out *packet_out)
14450aadb33SDmitri Tikhonov{
14550aadb33SDmitri Tikhonov    char frames[lsquic_frame_types_str_sz];
14650aadb33SDmitri Tikhonov    if (lsquic_packet_out_verneg(packet_out))
14750aadb33SDmitri Tikhonov        LCID("sent version negotiation packet, size %hu",
14850aadb33SDmitri Tikhonov                                                    packet_out->po_data_sz);
14950aadb33SDmitri Tikhonov    else if (lsquic_packet_out_pubres(packet_out))
15050aadb33SDmitri Tikhonov        LCID("sent public reset packet, size %hu", packet_out->po_data_sz);
15150aadb33SDmitri Tikhonov    else
15250aadb33SDmitri Tikhonov        LCID("sent packet %"PRIu64", size %hu, frame types: %s",
15350aadb33SDmitri Tikhonov            packet_out->po_packno, packet_out->po_enc_data_sz,
15450aadb33SDmitri Tikhonov                /* Frame types is a list of different frames types contained
15550aadb33SDmitri Tikhonov                 * in the packet, no more.  Count and order of frames is not
15650aadb33SDmitri Tikhonov                 * printed.
15750aadb33SDmitri Tikhonov                 */
15850aadb33SDmitri Tikhonov                lsquic_frame_types_to_str(frames, sizeof(frames),
15950aadb33SDmitri Tikhonov                                                packet_out->po_frame_types));
16050aadb33SDmitri Tikhonov}
16150aadb33SDmitri Tikhonov
16250aadb33SDmitri Tikhonov
16350aadb33SDmitri Tikhonovvoid
16450aadb33SDmitri Tikhonovlsquic_ev_log_packet_not_sent (lsquic_cid_t cid,
16550aadb33SDmitri Tikhonov                                const struct lsquic_packet_out *packet_out)
16650aadb33SDmitri Tikhonov{
16750aadb33SDmitri Tikhonov    char frames[lsquic_frame_types_str_sz];
16850aadb33SDmitri Tikhonov    LCID("unsent packet %"PRIu64", size %hu, frame types: %s",
16950aadb33SDmitri Tikhonov        packet_out->po_packno, packet_out->po_enc_data_sz,
17050aadb33SDmitri Tikhonov            /* Frame types is a list of different frames types contained in
17150aadb33SDmitri Tikhonov             * the packet, no more.  Count and order of frames is not printed.
17250aadb33SDmitri Tikhonov             */
17350aadb33SDmitri Tikhonov            lsquic_frame_types_to_str(frames, sizeof(frames),
17450aadb33SDmitri Tikhonov                                                packet_out->po_frame_types));
17550aadb33SDmitri Tikhonov}
17650aadb33SDmitri Tikhonov
17750aadb33SDmitri Tikhonov
17850aadb33SDmitri Tikhonovvoid
17950aadb33SDmitri Tikhonovlsquic_ev_log_http_headers_in (lsquic_cid_t cid, int is_server,
18050aadb33SDmitri Tikhonov                                        const struct uncompressed_headers *uh)
18150aadb33SDmitri Tikhonov{
18250aadb33SDmitri Tikhonov    const char *cr, *p;
18350aadb33SDmitri Tikhonov
18450aadb33SDmitri Tikhonov    if (uh->uh_flags & UH_PP)
18550aadb33SDmitri Tikhonov        LCID("read push promise; stream %"PRIu32", promised stream %"PRIu32,
18650aadb33SDmitri Tikhonov            uh->uh_stream_id, uh->uh_oth_stream_id);
18750aadb33SDmitri Tikhonov    else
18850aadb33SDmitri Tikhonov        LCID("read %s headers; stream: %"PRIu32", depends on stream: %"PRIu32
18950aadb33SDmitri Tikhonov            ", weight: %hu, exclusive: %d, fin: %d",
19050aadb33SDmitri Tikhonov            is_server ? "request" : "response",
19150aadb33SDmitri Tikhonov            uh->uh_stream_id, uh->uh_oth_stream_id, uh->uh_weight,
19250aadb33SDmitri Tikhonov            (int) uh->uh_exclusive, !!(uh->uh_flags & UH_FIN));
19350aadb33SDmitri Tikhonov
19450aadb33SDmitri Tikhonov    for (p = uh->uh_headers; p < uh->uh_headers + uh->uh_size; p = cr + 2)
19550aadb33SDmitri Tikhonov    {
19650aadb33SDmitri Tikhonov        cr = strchr(p, '\r');
19750aadb33SDmitri Tikhonov        if (cr && cr > p)
19850aadb33SDmitri Tikhonov            LCID("  %.*s", (int) (cr - p), p);
19950aadb33SDmitri Tikhonov        else
20050aadb33SDmitri Tikhonov            break;
20150aadb33SDmitri Tikhonov    }
20250aadb33SDmitri Tikhonov}
20350aadb33SDmitri Tikhonov
20450aadb33SDmitri Tikhonov
20550aadb33SDmitri Tikhonovvoid
206c51ce338SDmitri Tikhonovlsquic_ev_log_action_stream_frame (lsquic_cid_t cid,
207c51ce338SDmitri Tikhonov    const struct parse_funcs *pf, const unsigned char *buf, size_t bufsz,
208c51ce338SDmitri Tikhonov    const char *what)
20950aadb33SDmitri Tikhonov{
21050aadb33SDmitri Tikhonov    struct stream_frame frame;
21150aadb33SDmitri Tikhonov    int len;
21250aadb33SDmitri Tikhonov
21350aadb33SDmitri Tikhonov    len = pf->pf_parse_stream_frame(buf, bufsz, &frame);
21450aadb33SDmitri Tikhonov    if (len > 0)
215c51ce338SDmitri Tikhonov        LCID("%s STREAM frame: stream %"PRIu32", offset: %"PRIu64
216c51ce338SDmitri Tikhonov            ", size: %"PRIu16", fin: %d", what, frame.stream_id,
21750aadb33SDmitri Tikhonov            frame.data_frame.df_offset, frame.data_frame.df_size,
21850aadb33SDmitri Tikhonov            frame.data_frame.df_fin);
21950aadb33SDmitri Tikhonov    else
22050aadb33SDmitri Tikhonov        LSQ_LOG2(LSQ_LOG_WARN, "cannot parse STREAM frame");
22150aadb33SDmitri Tikhonov}
22250aadb33SDmitri Tikhonov
22350aadb33SDmitri Tikhonov
22450aadb33SDmitri Tikhonovvoid
22550aadb33SDmitri Tikhonovlsquic_ev_log_generated_ack_frame (lsquic_cid_t cid, const struct parse_funcs *pf,
22650aadb33SDmitri Tikhonov                                   const unsigned char *ack_buf, size_t ack_buf_sz)
22750aadb33SDmitri Tikhonov{
22850aadb33SDmitri Tikhonov    struct ack_info acki;
22950aadb33SDmitri Tikhonov    size_t sz;
23050aadb33SDmitri Tikhonov    char *buf;
23150aadb33SDmitri Tikhonov    int len;
23250aadb33SDmitri Tikhonov
23350aadb33SDmitri Tikhonov    len = pf->pf_parse_ack_frame(ack_buf, ack_buf_sz, &acki);
23450aadb33SDmitri Tikhonov    if (len < 0)
23550aadb33SDmitri Tikhonov    {
23650aadb33SDmitri Tikhonov        LSQ_LOG2(LSQ_LOG_WARN, "cannot parse ACK frame");
23750aadb33SDmitri Tikhonov        return;
23850aadb33SDmitri Tikhonov    }
23950aadb33SDmitri Tikhonov
24050aadb33SDmitri Tikhonov    if ((buf = acki2str(&acki, &sz)))
24150aadb33SDmitri Tikhonov    {
24250aadb33SDmitri Tikhonov        LCID("generated ACK frame: %.*s", (int) sz, buf);
24350aadb33SDmitri Tikhonov        free(buf);
24450aadb33SDmitri Tikhonov    }
24550aadb33SDmitri Tikhonov}
24650aadb33SDmitri Tikhonov
24750aadb33SDmitri Tikhonov
24850aadb33SDmitri Tikhonovvoid
24950aadb33SDmitri Tikhonovlsquic_ev_log_generated_stop_waiting_frame (lsquic_cid_t cid,
25050aadb33SDmitri Tikhonov                                            lsquic_packno_t lunack)
25150aadb33SDmitri Tikhonov{
25250aadb33SDmitri Tikhonov    LCID("generated STOP_WAITING frame; least unacked: %"PRIu64, lunack);
25350aadb33SDmitri Tikhonov}
25450aadb33SDmitri Tikhonov
25550aadb33SDmitri Tikhonov
25650aadb33SDmitri Tikhonovvoid
25750aadb33SDmitri Tikhonovlsquic_ev_log_generated_http_headers (lsquic_cid_t cid, uint32_t stream_id,
25850aadb33SDmitri Tikhonov                    int is_server, const struct http_prio_frame *prio_frame,
25950aadb33SDmitri Tikhonov                    const struct lsquic_http_headers *headers)
26050aadb33SDmitri Tikhonov{
26150aadb33SDmitri Tikhonov    uint32_t dep_stream_id;
26250aadb33SDmitri Tikhonov    int exclusive, i;
26350aadb33SDmitri Tikhonov    unsigned short weight;
26450aadb33SDmitri Tikhonov
26550aadb33SDmitri Tikhonov    if (is_server)
26650aadb33SDmitri Tikhonov        LCID("generated HTTP response HEADERS for stream %"PRIu32, stream_id);
26750aadb33SDmitri Tikhonov    else
26850aadb33SDmitri Tikhonov    {
26950aadb33SDmitri Tikhonov        memcpy(&dep_stream_id, prio_frame->hpf_stream_id, 4);
27050aadb33SDmitri Tikhonov        dep_stream_id = htonl(dep_stream_id);
27150aadb33SDmitri Tikhonov        exclusive = dep_stream_id >> 31;
27250aadb33SDmitri Tikhonov        dep_stream_id &= ~(1 << 31);
27350aadb33SDmitri Tikhonov        weight = prio_frame->hpf_weight + 1;
27450aadb33SDmitri Tikhonov        LCID("generated HTTP request HEADERS for stream %"PRIu32
27550aadb33SDmitri Tikhonov            ", dep stream: %"PRIu32", weight: %hu, exclusive: %d", stream_id,
27650aadb33SDmitri Tikhonov            dep_stream_id, weight, exclusive);
27750aadb33SDmitri Tikhonov    }
27850aadb33SDmitri Tikhonov
27950aadb33SDmitri Tikhonov    for (i = 0; i < headers->count; ++i)
28050aadb33SDmitri Tikhonov        LCID("  %.*s: %.*s",
28150aadb33SDmitri Tikhonov            (int)    headers->headers[i].name.iov_len,
28250aadb33SDmitri Tikhonov            (char *) headers->headers[i].name.iov_base,
28350aadb33SDmitri Tikhonov            (int)    headers->headers[i].value.iov_len,
28450aadb33SDmitri Tikhonov            (char *) headers->headers[i].value.iov_base);
28550aadb33SDmitri Tikhonov}
28650aadb33SDmitri Tikhonov
28750aadb33SDmitri Tikhonov
28850aadb33SDmitri Tikhonovvoid
28950aadb33SDmitri Tikhonovlsquic_ev_log_generated_http_push_promise (lsquic_cid_t cid,
29050aadb33SDmitri Tikhonov                            uint32_t stream_id, uint32_t promised_stream_id,
29150aadb33SDmitri Tikhonov                            const struct lsquic_http_headers *headers,
29250aadb33SDmitri Tikhonov                            const struct lsquic_http_headers *extra_headers)
29350aadb33SDmitri Tikhonov{
29450aadb33SDmitri Tikhonov    int i;
29550aadb33SDmitri Tikhonov
29650aadb33SDmitri Tikhonov    LCID("generated HTTP PUSH_PROMISE for stream %"PRIu32"; promised stream %"
29750aadb33SDmitri Tikhonov        PRIu32, stream_id, promised_stream_id);
29850aadb33SDmitri Tikhonov
29950aadb33SDmitri Tikhonov    for (i = 0; i < headers->count; ++i)
30050aadb33SDmitri Tikhonov        LCID("  %.*s: %.*s",
30150aadb33SDmitri Tikhonov            (int)    headers->headers[i].name.iov_len,
30250aadb33SDmitri Tikhonov            (char *) headers->headers[i].name.iov_base,
30350aadb33SDmitri Tikhonov            (int)    headers->headers[i].value.iov_len,
30450aadb33SDmitri Tikhonov            (char *) headers->headers[i].value.iov_base);
30550aadb33SDmitri Tikhonov
30650aadb33SDmitri Tikhonov    if (extra_headers)
30750aadb33SDmitri Tikhonov        for (i = 0; i < extra_headers->count; ++i)
30850aadb33SDmitri Tikhonov            LCID("  %.*s: %.*s",
30950aadb33SDmitri Tikhonov                (int)    extra_headers->headers[i].name.iov_len,
31050aadb33SDmitri Tikhonov                (char *) extra_headers->headers[i].name.iov_base,
31150aadb33SDmitri Tikhonov                (int)    extra_headers->headers[i].value.iov_len,
31250aadb33SDmitri Tikhonov                (char *) extra_headers->headers[i].value.iov_base);
31350aadb33SDmitri Tikhonov}
31450aadb33SDmitri Tikhonov
31550aadb33SDmitri Tikhonov
316