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