/src/openssl/ssl/quic/qlog_event_helpers.c

Source (jump to first uncovered line)
/*
 * Copyright 2023 The OpenSSL Project Authors. All Rights Reserved.
 *
 * Licensed under the Apache License 2.0 (the "License").  You may not use
 * this file except in compliance with the License.  You can obtain a copy
 * in the file LICENSE in the source distribution or at
 * https://www.openssl.org/source/license.html
 */

#include "internal/qlog_event_helpers.h"
#include "internal/common.h"
#include "internal/packet.h"
#include "internal/quic_channel.h"
#include "internal/quic_error.h"

void ossl_qlog_event_connectivity_connection_started(QLOG *qlog,
                                                     const QUIC_CONN_ID *init_dcid)
{
#ifndef OPENSSL_NO_QLOG
    QLOG_EVENT_BEGIN(qlog, connectivity, connection_started)
        QLOG_STR("protocol", "quic");
        QLOG_CID("dst_cid", init_dcid);
    QLOG_EVENT_END()
#endif
}

#ifndef OPENSSL_NO_QLOG
static const char *map_state_to_qlog(uint32_t state,
                                     int handshake_complete,
                                     int handshake_confirmed)
{
    switch (state) {
    default:
    case QUIC_CHANNEL_STATE_IDLE:
        return NULL;

    case QUIC_CHANNEL_STATE_ACTIVE:
        if (handshake_confirmed)
            return "handshake_confirmed";
        else if (handshake_complete)
            return "handshake_complete";
        else
            return "attempted";

    case QUIC_CHANNEL_STATE_TERMINATING_CLOSING:
        return "closing";

    case QUIC_CHANNEL_STATE_TERMINATING_DRAINING:
        return "draining";

    case QUIC_CHANNEL_STATE_TERMINATED:
        return "closed";
    }
}
#endif

void ossl_qlog_event_connectivity_connection_state_updated(QLOG *qlog,
                                                           uint32_t old_state,
                                                           uint32_t new_state,
                                                           int handshake_complete,
                                                           int handshake_confirmed)
{
#ifndef OPENSSL_NO_QLOG
    const char *state_s;

    QLOG_EVENT_BEGIN(qlog, connectivity, connection_state_updated)
        state_s = map_state_to_qlog(new_state,
                                    handshake_complete,
                                    handshake_confirmed);

        if (state_s != NULL)
            QLOG_STR("state", state_s);
    QLOG_EVENT_END()
#endif
}

#ifndef OPENSSL_NO_QLOG
static const char *quic_err_to_qlog(uint64_t error_code)
{
    switch (error_code) {
        case QUIC_ERR_INTERNAL_ERROR:
            return "internal_error";
        case QUIC_ERR_CONNECTION_REFUSED:
            return "connection_refused";
        case QUIC_ERR_FLOW_CONTROL_ERROR:
            return "flow_control_error";
        case QUIC_ERR_STREAM_LIMIT_ERROR:
            return "stream_limit_error";
        case QUIC_ERR_STREAM_STATE_ERROR:
            return "stream_state_error";
        case QUIC_ERR_FINAL_SIZE_ERROR:
            return "final_size_error";
        case QUIC_ERR_FRAME_ENCODING_ERROR:
            return "frame_encoding_error";
        case QUIC_ERR_TRANSPORT_PARAMETER_ERROR:
            return "transport_parameter_error";
        case QUIC_ERR_CONNECTION_ID_LIMIT_ERROR:
            return "connection_id_limit_error";
        case QUIC_ERR_PROTOCOL_VIOLATION:
            return "protocol_violation";
        case QUIC_ERR_INVALID_TOKEN:
            return "invalid_token";
        case QUIC_ERR_APPLICATION_ERROR:
            return "application_error";
        case QUIC_ERR_CRYPTO_BUFFER_EXCEEDED:
            return "crypto_buffer_exceeded";
        case QUIC_ERR_KEY_UPDATE_ERROR:
            return "key_update_error";
        case QUIC_ERR_AEAD_LIMIT_REACHED:
            return "aead_limit_reached";
        case QUIC_ERR_NO_VIABLE_PATH:
            return "no_viable_path";
        default:
            return NULL;
    }
}
#endif

void ossl_qlog_event_connectivity_connection_closed(QLOG *qlog,
                                                    const QUIC_TERMINATE_CAUSE *tcause)
{
#ifndef OPENSSL_NO_QLOG
    QLOG_EVENT_BEGIN(qlog, connectivity, connection_closed)
        QLOG_STR("owner", tcause->remote ? "remote" : "local");
        if (tcause->app) {
            QLOG_U64("application_code", tcause->error_code);
        } else {
            const char *m = quic_err_to_qlog(tcause->error_code);
            char ce[32];

            if (tcause->error_code >= QUIC_ERR_CRYPTO_ERR_BEGIN
                && tcause->error_code <= QUIC_ERR_CRYPTO_ERR_END) {
                BIO_snprintf(ce, sizeof(ce), "crypto_error_0x%03llx",
                             (unsigned long long)tcause->error_code);
                m = ce;
            }
            /* TODO(QLOG FUTURE): Consider adding ERR information in the output. */

            if (m != NULL)
                QLOG_STR("connection_code", m);
            else
                QLOG_U64("connection_code", tcause->error_code);
        }

        QLOG_STR_LEN("reason", tcause->reason, tcause->reason_len);
    QLOG_EVENT_END()
#endif
}

#ifndef OPENSSL_NO_QLOG
static const char *quic_pkt_type_to_qlog(uint32_t pkt_type)
{
    switch (pkt_type) {
        case QUIC_PKT_TYPE_INITIAL:
            return "initial";
        case QUIC_PKT_TYPE_HANDSHAKE:
            return "handshake";
        case QUIC_PKT_TYPE_0RTT:
            return "0RTT";
        case QUIC_PKT_TYPE_1RTT:
            return "1RTT";
        case QUIC_PKT_TYPE_VERSION_NEG:
            return "version_negotiation";
        case QUIC_PKT_TYPE_RETRY:
            return "retry";
        default:
            return "unknown";
    }
}
#endif

void ossl_qlog_event_recovery_packet_lost(QLOG *qlog,
                                          const QUIC_TXPIM_PKT *tpkt)
{
#ifndef OPENSSL_NO_QLOG
    QLOG_EVENT_BEGIN(qlog, recovery, packet_lost)
        QLOG_BEGIN("header")
            QLOG_STR("packet_type", quic_pkt_type_to_qlog(tpkt->pkt_type));
            if (ossl_quic_pkt_type_has_pn(tpkt->pkt_type))
                QLOG_U64("packet_number", tpkt->ackm_pkt.pkt_num);
        QLOG_END()
    QLOG_EVENT_END()
#endif
}

#ifndef OPENSSL_NO_QLOG
# define MAX_ACK_RANGES 32

static void ignore_res(int x) {}

/*
 * For logging received packets, we need to parse all the frames in the packet
 * to log them. We should do this separately to the RXDP code because we want to
 * log the packet and its contents before we start to actually process it in
 * case it causes an error. We also in general don't want to do other
 * non-logging related work in the middle of an event logging transaction.
 * Reparsing packet data allows us to meet these needs while avoiding the need
 * to keep around bookkeeping data on what frames were in a packet, etc.
 *
 * For logging transmitted packets, we actually reuse the same code and reparse
 * the outgoing packet's payload. This again has the advantage that we only log
 * a packet when it is actually queued for transmission (and not if something
 * goes wrong before then) while avoiding the need to keep around bookkeeping
 * data on what frames it contained.
 */
static int log_frame_actual(QLOG *qlog_instance, PACKET *pkt,
                            size_t *need_skip)
{
    uint64_t frame_type;
    OSSL_QUIC_FRAME_ACK ack;
    OSSL_QUIC_ACK_RANGE ack_ranges[MAX_ACK_RANGES];
    uint64_t num_ranges, total_ranges;
    size_t i;
    PACKET orig_pkt = *pkt;

    if (!ossl_quic_wire_peek_frame_header(pkt, &frame_type, NULL))
        return 0;

    /*
     * If something goes wrong decoding a frame we cannot log it as that frame
     * as we need to know how to decode it in order to be able to do so, but in
     * that case we log it as an unknown frame to assist with diagnosis.
     */
    switch (frame_type) {
    case OSSL_QUIC_FRAME_TYPE_PADDING:
        QLOG_STR("frame_type", "padding");
        QLOG_U64("payload_length",
                 ossl_quic_wire_decode_padding(pkt));
        break;
    case OSSL_QUIC_FRAME_TYPE_PING:
        if (!ossl_quic_wire_decode_frame_ping(pkt))
            goto unknown;

        QLOG_STR("frame_type", "ping");
        break;
    case OSSL_QUIC_FRAME_TYPE_ACK_WITHOUT_ECN:
    case OSSL_QUIC_FRAME_TYPE_ACK_WITH_ECN:
        if (!ossl_quic_wire_peek_frame_ack_num_ranges(pkt, &num_ranges))
            goto unknown;

        ack.ack_ranges      = ack_ranges;
        ack.num_ack_ranges  = OSSL_NELEM(ack_ranges);
        if (!ossl_quic_wire_decode_frame_ack(pkt, 3, &ack, &total_ranges))
            goto unknown;

        QLOG_STR("frame_type", "ack");
        QLOG_U64("ack_delay", ossl_time2ms(ack.delay_time));
        if (ack.ecn_present) {
            QLOG_U64("ect1", ack.ect0);
            QLOG_U64("ect0", ack.ect1);
            QLOG_U64("ce", ack.ecnce);
        }
        QLOG_BEGIN_ARRAY("acked_ranges");
        for (i = 0; i < ack.num_ack_ranges; ++i) {
            QLOG_BEGIN_ARRAY(NULL)
                QLOG_U64(NULL, ack.ack_ranges[i].start);
                if (ack.ack_ranges[i].end != ack.ack_ranges[i].start)
                    QLOG_U64(NULL, ack.ack_ranges[i].end);
            QLOG_END_ARRAY()
        }
        QLOG_END_ARRAY()
        break;
    case OSSL_QUIC_FRAME_TYPE_RESET_STREAM:
        {
            OSSL_QUIC_FRAME_RESET_STREAM f;

            if (!ossl_quic_wire_decode_frame_reset_stream(pkt, &f))
                goto unknown;

            QLOG_STR("frame_type", "reset_stream");
            QLOG_U64("stream_id", f.stream_id);
            QLOG_U64("error_code", f.app_error_code);
            QLOG_U64("final_size", f.final_size);
        }
        break;
    case OSSL_QUIC_FRAME_TYPE_STOP_SENDING:
        {
            OSSL_QUIC_FRAME_STOP_SENDING f;

            if (!ossl_quic_wire_decode_frame_stop_sending(pkt, &f))
                goto unknown;

            QLOG_STR("frame_type", "stop_sending");
            QLOG_U64("stream_id", f.stream_id);
            QLOG_U64("error_code", f.app_error_code);
        }
        break;
    case OSSL_QUIC_FRAME_TYPE_CRYPTO:
        {
            OSSL_QUIC_FRAME_CRYPTO f;

            if (!ossl_quic_wire_decode_frame_crypto(pkt, 1, &f))
                goto unknown;

            QLOG_STR("frame_type", "crypto");
            QLOG_U64("offset", f.offset);
            QLOG_U64("payload_length", f.len);
            *need_skip += (size_t)f.len;
        }
        break;
    case OSSL_QUIC_FRAME_TYPE_STREAM:
    case OSSL_QUIC_FRAME_TYPE_STREAM_FIN:
    case OSSL_QUIC_FRAME_TYPE_STREAM_LEN:
    case OSSL_QUIC_FRAME_TYPE_STREAM_LEN_FIN:
    case OSSL_QUIC_FRAME_TYPE_STREAM_OFF:
    case OSSL_QUIC_FRAME_TYPE_STREAM_OFF_FIN:
    case OSSL_QUIC_FRAME_TYPE_STREAM_OFF_LEN:
    case OSSL_QUIC_FRAME_TYPE_STREAM_OFF_LEN_FIN:
        {
            OSSL_QUIC_FRAME_STREAM f;

            if (!ossl_quic_wire_decode_frame_stream(pkt, 1, &f))
                goto unknown;

            QLOG_STR("frame_type", "stream");
            QLOG_U64("stream_id", f.stream_id);
            QLOG_U64("offset", f.offset);
            QLOG_U64("payload_length", f.len);
            QLOG_BOOL("explicit_length", f.has_explicit_len);
            if (f.is_fin)
                QLOG_BOOL("fin", 1);
            *need_skip = f.has_explicit_len
                ? *need_skip + (size_t)f.len : SIZE_MAX;
        }
        break;
    case OSSL_QUIC_FRAME_TYPE_MAX_DATA:
        {
            uint64_t x;

            if (!ossl_quic_wire_decode_frame_max_data(pkt, &x))
                goto unknown;

            QLOG_STR("frame_type", "max_data");
            QLOG_U64("maximum", x);
        }
        break;
    case OSSL_QUIC_FRAME_TYPE_MAX_STREAMS_BIDI:
    case OSSL_QUIC_FRAME_TYPE_MAX_STREAMS_UNI:
        {
            uint64_t x;

            if (!ossl_quic_wire_decode_frame_max_streams(pkt, &x))
                goto unknown;

            QLOG_STR("frame_type", "max_streams");
            QLOG_STR("stream_type",
                     frame_type == OSSL_QUIC_FRAME_TYPE_MAX_STREAMS_BIDI
                        ? "bidirectional" : "unidirectional");
            QLOG_U64("maximum", x);
        }
        break;
    case OSSL_QUIC_FRAME_TYPE_MAX_STREAM_DATA:
        {
            uint64_t stream_id, max_data;

            if (!ossl_quic_wire_decode_frame_max_stream_data(pkt, &stream_id,
                                                             &max_data))
                goto unknown;

            QLOG_STR("frame_type", "max_stream_data");
            QLOG_U64("stream_id", stream_id);
            QLOG_U64("maximum", max_data);
        }
        break;
    case OSSL_QUIC_FRAME_TYPE_PATH_CHALLENGE:
        {
            uint64_t challenge;

            if (!ossl_quic_wire_decode_frame_path_challenge(pkt, &challenge))
                goto unknown;

            QLOG_STR("frame_type", "path_challenge");
        }
        break;
    case OSSL_QUIC_FRAME_TYPE_PATH_RESPONSE:
        {
            uint64_t challenge;

            if (!ossl_quic_wire_decode_frame_path_response(pkt, &challenge))
                goto unknown;

            QLOG_STR("frame_type", "path_response");
        }
        break;
    case OSSL_QUIC_FRAME_TYPE_CONN_CLOSE_APP:
    case OSSL_QUIC_FRAME_TYPE_CONN_CLOSE_TRANSPORT:
        {
            OSSL_QUIC_FRAME_CONN_CLOSE f;

            if (!ossl_quic_wire_decode_frame_conn_close(pkt, &f))
                goto unknown;

            QLOG_STR("frame_type", "connection_close");
            QLOG_STR("error_space", f.is_app ? "application" : "transport");
            QLOG_U64("error_code_value", f.error_code);
            if (f.is_app)
                QLOG_U64("error_code", f.error_code);
            if (!f.is_app && f.frame_type != 0)
                QLOG_U64("trigger_frame_type", f.frame_type);
            QLOG_STR_LEN("reason", f.reason, f.reason_len);
        }
        break;
    case OSSL_QUIC_FRAME_TYPE_HANDSHAKE_DONE:
        {
            if (!ossl_quic_wire_decode_frame_handshake_done(pkt))
                goto unknown;

            QLOG_STR("frame_type", "handshake_done");
        }
        break;
    case OSSL_QUIC_FRAME_TYPE_NEW_CONN_ID:
        {
            OSSL_QUIC_FRAME_NEW_CONN_ID f;

            if (!ossl_quic_wire_decode_frame_new_conn_id(pkt, &f))
                goto unknown;

            QLOG_STR("frame_type", "new_connection_id");
            QLOG_U64("sequence_number", f.seq_num);
            QLOG_U64("retire_prior_to", f.retire_prior_to);
            QLOG_CID("connection_id", &f.conn_id);
            QLOG_BIN("stateless_reset_token",
                     f.stateless_reset.token,
                     sizeof(f.stateless_reset.token));
        }
        break;
    case OSSL_QUIC_FRAME_TYPE_RETIRE_CONN_ID:
        {
            uint64_t seq_num;

            if (!ossl_quic_wire_decode_frame_retire_conn_id(pkt, &seq_num))
                goto unknown;

            QLOG_STR("frame_type", "retire_connection_id");
            QLOG_U64("sequence_number", seq_num);
        }
        break;
    case OSSL_QUIC_FRAME_TYPE_DATA_BLOCKED:
        {
            uint64_t x;

            if (!ossl_quic_wire_decode_frame_data_blocked(pkt, &x))
                goto unknown;

            QLOG_STR("frame_type", "data_blocked");
            QLOG_U64("limit", x);
        }
        break;
    case OSSL_QUIC_FRAME_TYPE_STREAM_DATA_BLOCKED:
        {
            uint64_t stream_id, x;

            if (!ossl_quic_wire_decode_frame_stream_data_blocked(pkt,
                                                                 &stream_id,
                                                                 &x))
                goto unknown;

            QLOG_STR("frame_type", "stream_data_blocked");
            QLOG_U64("stream_id", stream_id);
            QLOG_U64("limit", x);
        }
        break;
    case OSSL_QUIC_FRAME_TYPE_STREAMS_BLOCKED_BIDI:
    case OSSL_QUIC_FRAME_TYPE_STREAMS_BLOCKED_UNI:
        {
            uint64_t x;

            if (!ossl_quic_wire_decode_frame_streams_blocked(pkt, &x))
                goto unknown;

            QLOG_STR("frame_type", "streams_blocked");
            QLOG_STR("stream_type",
                     frame_type == OSSL_QUIC_FRAME_TYPE_STREAMS_BLOCKED_BIDI
                        ? "bidirectional" : "unidirectional");
            QLOG_U64("limit", x);
        }
        break;
    case OSSL_QUIC_FRAME_TYPE_NEW_TOKEN:
        {
            const unsigned char *token;
            size_t token_len;

            if (!ossl_quic_wire_decode_frame_new_token(pkt, &token, &token_len))
                goto unknown;

            QLOG_STR("frame_type", "new_token");
            QLOG_BEGIN("token");
                QLOG_BEGIN("raw");
                    QLOG_BIN("data", token, token_len);
                QLOG_END();
            QLOG_END();
        }
        break;
    default:
unknown:
        QLOG_STR("frame_type", "unknown");
        QLOG_U64("frame_type_value", frame_type);

        /*
         * Can't continue scanning for frames in this case as the frame length
         * is unknown. We log the entire body of the rest of the packet payload
         * as the raw data of the frame.
         */
        QLOG_BEGIN("raw");
            QLOG_BIN("data", PACKET_data(&orig_pkt),
                     PACKET_remaining(&orig_pkt));
        QLOG_END();
        ignore_res(PACKET_forward(pkt, PACKET_remaining(pkt)));
        break;
    }

    return 1;
}

static void log_frame(QLOG *qlog_instance, PACKET *pkt,
                      size_t *need_skip)
{
    size_t rem_before, rem_after;

    rem_before = PACKET_remaining(pkt);

    if (!log_frame_actual(qlog_instance, pkt, need_skip))
        return;

    rem_after = PACKET_remaining(pkt);
    QLOG_U64("length", rem_before - rem_after);
}

static int log_frames(QLOG *qlog_instance,
                      const OSSL_QTX_IOVEC *iovec,
                      size_t num_iovec)
{
    size_t i;
    PACKET pkt;
    size_t need_skip = 0;

    for (i = 0; i < num_iovec; ++i) {
        if (!PACKET_buf_init(&pkt, iovec[i].buf, iovec[i].buf_len))
            return 0;

        while (PACKET_remaining(&pkt) > 0) {
            if (need_skip > 0) {
                size_t adv = need_skip;

                if (adv < PACKET_remaining(&pkt))
                    adv = PACKET_remaining(&pkt);

                if (!PACKET_forward(&pkt, adv))
                    return 0;

                need_skip -= adv;
                continue;
            }

            QLOG_BEGIN(NULL)
            {
                log_frame(qlog_instance, &pkt, &need_skip);
            }
            QLOG_END()
        }
    }

    return 1;
}

static void log_packet(QLOG *qlog_instance,
                       const QUIC_PKT_HDR *hdr,
                       QUIC_PN pn,
                       const OSSL_QTX_IOVEC *iovec,
                       size_t num_iovec,
                       uint64_t datagram_id)
{
    const char *type_s;

    QLOG_BEGIN("header")
        type_s = quic_pkt_type_to_qlog(hdr->type);
        if (type_s == NULL)
            type_s = "unknown";

        QLOG_STR("packet_type", type_s);
        if (ossl_quic_pkt_type_has_pn(hdr->type))
            QLOG_U64("packet_number", pn);

        QLOG_CID("dcid", &hdr->dst_conn_id);
        if (ossl_quic_pkt_type_has_scid(hdr->type))
            QLOG_CID("scid", &hdr->src_conn_id);

        if (hdr->token_len > 0) {
            QLOG_BEGIN("token")
                QLOG_BEGIN("raw")
                    QLOG_BIN("data", hdr->token, hdr->token_len);
                QLOG_END()
            QLOG_END()
        }
        /* TODO(QLOG FUTURE): flags, length */
    QLOG_END()
    QLOG_U64("datagram_id", datagram_id);

    if (ossl_quic_pkt_type_is_encrypted(hdr->type)) {
        QLOG_BEGIN_ARRAY("frames")
            log_frames(qlog_instance, iovec, num_iovec);
        QLOG_END_ARRAY()
    }
}

#endif

void ossl_qlog_event_transport_packet_sent(QLOG *qlog,
                                           const QUIC_PKT_HDR *hdr,
                                           QUIC_PN pn,
                                           const OSSL_QTX_IOVEC *iovec,
                                           size_t num_iovec,
                                           uint64_t datagram_id)
{
#ifndef OPENSSL_NO_QLOG
    QLOG_EVENT_BEGIN(qlog, transport, packet_sent)
        log_packet(qlog, hdr, pn, iovec, num_iovec, datagram_id);
    QLOG_EVENT_END()
#endif
}

void ossl_qlog_event_transport_packet_received(QLOG *qlog,
                                               const QUIC_PKT_HDR *hdr,
                                               QUIC_PN pn,
                                               const OSSL_QTX_IOVEC *iovec,
                                               size_t num_iovec,
                                               uint64_t datagram_id)
{
#ifndef OPENSSL_NO_QLOG
    QLOG_EVENT_BEGIN(qlog, transport, packet_received)
        log_packet(qlog, hdr, pn, iovec, num_iovec, datagram_id);
    QLOG_EVENT_END()
#endif
}

Coverage Report

Created: 2024-02-25 06:25

Line	Count	Source (jump to first uncovered line)
1		/*
2		* Copyright 2023 The OpenSSL Project Authors. All Rights Reserved.
3		*
4		* Licensed under the Apache License 2.0 (the "License"). You may not use
5		* this file except in compliance with the License. You can obtain a copy
6		* in the file LICENSE in the source distribution or at
7		* https://www.openssl.org/source/license.html
8		*/
9
10		#include "internal/qlog_event_helpers.h"
11		#include "internal/common.h"
12		#include "internal/packet.h"
13		#include "internal/quic_channel.h"
14		#include "internal/quic_error.h"
15
16		void ossl_qlog_event_connectivity_connection_started(QLOG *qlog,
17		const QUIC_CONN_ID *init_dcid)
18	0	{
19		#ifndef OPENSSL_NO_QLOG
20		QLOG_EVENT_BEGIN(qlog, connectivity, connection_started)
21		QLOG_STR("protocol", "quic");
22		QLOG_CID("dst_cid", init_dcid);
23		QLOG_EVENT_END()
24		#endif
25	0	}
26
27		#ifndef OPENSSL_NO_QLOG
28		static const char *map_state_to_qlog(uint32_t state,
29		int handshake_complete,
30		int handshake_confirmed)
31		{
32		switch (state) {
33		default:
34		case QUIC_CHANNEL_STATE_IDLE:
35		return NULL;
36
37		case QUIC_CHANNEL_STATE_ACTIVE:
38		if (handshake_confirmed)
39		return "handshake_confirmed";
40		else if (handshake_complete)
41		return "handshake_complete";
42		else
43		return "attempted";
44
45		case QUIC_CHANNEL_STATE_TERMINATING_CLOSING:
46		return "closing";
47
48		case QUIC_CHANNEL_STATE_TERMINATING_DRAINING:
49		return "draining";
50
51		case QUIC_CHANNEL_STATE_TERMINATED:
52		return "closed";
53		}
54		}
55		#endif
56
57		void ossl_qlog_event_connectivity_connection_state_updated(QLOG *qlog,
58		uint32_t old_state,
59		uint32_t new_state,
60		int handshake_complete,
61		int handshake_confirmed)
62	0	{
63		#ifndef OPENSSL_NO_QLOG
64		const char *state_s;
65
66		QLOG_EVENT_BEGIN(qlog, connectivity, connection_state_updated)
67		state_s = map_state_to_qlog(new_state,
68		handshake_complete,
69		handshake_confirmed);
70
71		if (state_s != NULL)
72		QLOG_STR("state", state_s);
73		QLOG_EVENT_END()
74		#endif
75	0	}
76
77		#ifndef OPENSSL_NO_QLOG
78		static const char *quic_err_to_qlog(uint64_t error_code)
79		{
80		switch (error_code) {
81		case QUIC_ERR_INTERNAL_ERROR:
82		return "internal_error";
83		case QUIC_ERR_CONNECTION_REFUSED:
84		return "connection_refused";
85		case QUIC_ERR_FLOW_CONTROL_ERROR:
86		return "flow_control_error";
87		case QUIC_ERR_STREAM_LIMIT_ERROR:
88		return "stream_limit_error";
89		case QUIC_ERR_STREAM_STATE_ERROR:
90		return "stream_state_error";
91		case QUIC_ERR_FINAL_SIZE_ERROR:
92		return "final_size_error";
93		case QUIC_ERR_FRAME_ENCODING_ERROR:
94		return "frame_encoding_error";
95		case QUIC_ERR_TRANSPORT_PARAMETER_ERROR:
96		return "transport_parameter_error";
97		case QUIC_ERR_CONNECTION_ID_LIMIT_ERROR:
98		return "connection_id_limit_error";
99		case QUIC_ERR_PROTOCOL_VIOLATION:
100		return "protocol_violation";
101		case QUIC_ERR_INVALID_TOKEN:
102		return "invalid_token";
103		case QUIC_ERR_APPLICATION_ERROR:
104		return "application_error";
105		case QUIC_ERR_CRYPTO_BUFFER_EXCEEDED:
106		return "crypto_buffer_exceeded";
107		case QUIC_ERR_KEY_UPDATE_ERROR:
108		return "key_update_error";
109		case QUIC_ERR_AEAD_LIMIT_REACHED:
110		return "aead_limit_reached";
111		case QUIC_ERR_NO_VIABLE_PATH:
112		return "no_viable_path";
113		default:
114		return NULL;
115		}
116		}
117		#endif
118
119		void ossl_qlog_event_connectivity_connection_closed(QLOG *qlog,
120		const QUIC_TERMINATE_CAUSE *tcause)
121	0	{
122		#ifndef OPENSSL_NO_QLOG
123		QLOG_EVENT_BEGIN(qlog, connectivity, connection_closed)
124		QLOG_STR("owner", tcause->remote ? "remote" : "local");
125		if (tcause->app) {
126		QLOG_U64("application_code", tcause->error_code);
127		} else {
128		const char *m = quic_err_to_qlog(tcause->error_code);
129		char ce[32];
130
131		if (tcause->error_code >= QUIC_ERR_CRYPTO_ERR_BEGIN
132		&& tcause->error_code <= QUIC_ERR_CRYPTO_ERR_END) {
133		BIO_snprintf(ce, sizeof(ce), "crypto_error_0x%03llx",
134		(unsigned long long)tcause->error_code);
135		m = ce;
136		}
137		/* TODO(QLOG FUTURE): Consider adding ERR information in the output. */
138
139		if (m != NULL)
140		QLOG_STR("connection_code", m);
141		else
142		QLOG_U64("connection_code", tcause->error_code);
143		}
144
145		QLOG_STR_LEN("reason", tcause->reason, tcause->reason_len);
146		QLOG_EVENT_END()
147		#endif
148	0	}
149
150		#ifndef OPENSSL_NO_QLOG
151		static const char *quic_pkt_type_to_qlog(uint32_t pkt_type)
152		{
153		switch (pkt_type) {
154		case QUIC_PKT_TYPE_INITIAL:
155		return "initial";
156		case QUIC_PKT_TYPE_HANDSHAKE:
157		return "handshake";
158		case QUIC_PKT_TYPE_0RTT:
159		return "0RTT";
160		case QUIC_PKT_TYPE_1RTT:
161		return "1RTT";
162		case QUIC_PKT_TYPE_VERSION_NEG:
163		return "version_negotiation";
164		case QUIC_PKT_TYPE_RETRY:
165		return "retry";
166		default:
167		return "unknown";
168		}
169		}
170		#endif
171
172		void ossl_qlog_event_recovery_packet_lost(QLOG *qlog,
173		const QUIC_TXPIM_PKT *tpkt)
174	0	{
175		#ifndef OPENSSL_NO_QLOG
176		QLOG_EVENT_BEGIN(qlog, recovery, packet_lost)
177		QLOG_BEGIN("header")
178		QLOG_STR("packet_type", quic_pkt_type_to_qlog(tpkt->pkt_type));
179		if (ossl_quic_pkt_type_has_pn(tpkt->pkt_type))
180		QLOG_U64("packet_number", tpkt->ackm_pkt.pkt_num);
181		QLOG_END()
182		QLOG_EVENT_END()
183		#endif
184	0	}
185
186		#ifndef OPENSSL_NO_QLOG
187		# define MAX_ACK_RANGES 32
188
189		static void ignore_res(int x) {}
190
191		/*
192		* For logging received packets, we need to parse all the frames in the packet
193		* to log them. We should do this separately to the RXDP code because we want to
194		* log the packet and its contents before we start to actually process it in
195		* case it causes an error. We also in general don't want to do other
196		* non-logging related work in the middle of an event logging transaction.
197		* Reparsing packet data allows us to meet these needs while avoiding the need
198		* to keep around bookkeeping data on what frames were in a packet, etc.
199		*
200		* For logging transmitted packets, we actually reuse the same code and reparse
201		* the outgoing packet's payload. This again has the advantage that we only log
202		* a packet when it is actually queued for transmission (and not if something
203		* goes wrong before then) while avoiding the need to keep around bookkeeping
204		* data on what frames it contained.
205		*/
206		static int log_frame_actual(QLOG qlog_instance, PACKET pkt,
207		size_t *need_skip)
208		{
209		uint64_t frame_type;
210		OSSL_QUIC_FRAME_ACK ack;
211		OSSL_QUIC_ACK_RANGE ack_ranges[MAX_ACK_RANGES];
212		uint64_t num_ranges, total_ranges;
213		size_t i;
214		PACKET orig_pkt = *pkt;
215
216		if (!ossl_quic_wire_peek_frame_header(pkt, &frame_type, NULL))
217		return 0;
218
219		/*
220		* If something goes wrong decoding a frame we cannot log it as that frame
221		* as we need to know how to decode it in order to be able to do so, but in
222		* that case we log it as an unknown frame to assist with diagnosis.
223		*/
224		switch (frame_type) {
225		case OSSL_QUIC_FRAME_TYPE_PADDING:
226		QLOG_STR("frame_type", "padding");
227		QLOG_U64("payload_length",
228		ossl_quic_wire_decode_padding(pkt));
229		break;
230		case OSSL_QUIC_FRAME_TYPE_PING:
231		if (!ossl_quic_wire_decode_frame_ping(pkt))
232		goto unknown;
233
234		QLOG_STR("frame_type", "ping");
235		break;
236		case OSSL_QUIC_FRAME_TYPE_ACK_WITHOUT_ECN:
237		case OSSL_QUIC_FRAME_TYPE_ACK_WITH_ECN:
238		if (!ossl_quic_wire_peek_frame_ack_num_ranges(pkt, &num_ranges))
239		goto unknown;
240
241		ack.ack_ranges = ack_ranges;
242		ack.num_ack_ranges = OSSL_NELEM(ack_ranges);
243		if (!ossl_quic_wire_decode_frame_ack(pkt, 3, &ack, &total_ranges))
244		goto unknown;
245
246		QLOG_STR("frame_type", "ack");
247		QLOG_U64("ack_delay", ossl_time2ms(ack.delay_time));
248		if (ack.ecn_present) {
249		QLOG_U64("ect1", ack.ect0);
250		QLOG_U64("ect0", ack.ect1);
251		QLOG_U64("ce", ack.ecnce);
252		}
253		QLOG_BEGIN_ARRAY("acked_ranges");
254		for (i = 0; i < ack.num_ack_ranges; ++i) {
255		QLOG_BEGIN_ARRAY(NULL)
256		QLOG_U64(NULL, ack.ack_ranges[i].start);
257		if (ack.ack_ranges[i].end != ack.ack_ranges[i].start)
258		QLOG_U64(NULL, ack.ack_ranges[i].end);
259		QLOG_END_ARRAY()
260		}
261		QLOG_END_ARRAY()
262		break;
263		case OSSL_QUIC_FRAME_TYPE_RESET_STREAM:
264		{
265		OSSL_QUIC_FRAME_RESET_STREAM f;
266
267		if (!ossl_quic_wire_decode_frame_reset_stream(pkt, &f))
268		goto unknown;
269
270		QLOG_STR("frame_type", "reset_stream");
271		QLOG_U64("stream_id", f.stream_id);
272		QLOG_U64("error_code", f.app_error_code);
273		QLOG_U64("final_size", f.final_size);
274		}
275		break;
276		case OSSL_QUIC_FRAME_TYPE_STOP_SENDING:
277		{
278		OSSL_QUIC_FRAME_STOP_SENDING f;
279
280		if (!ossl_quic_wire_decode_frame_stop_sending(pkt, &f))
281		goto unknown;
282
283		QLOG_STR("frame_type", "stop_sending");
284		QLOG_U64("stream_id", f.stream_id);
285		QLOG_U64("error_code", f.app_error_code);
286		}
287		break;
288		case OSSL_QUIC_FRAME_TYPE_CRYPTO:
289		{
290		OSSL_QUIC_FRAME_CRYPTO f;
291
292		if (!ossl_quic_wire_decode_frame_crypto(pkt, 1, &f))
293		goto unknown;
294
295		QLOG_STR("frame_type", "crypto");
296		QLOG_U64("offset", f.offset);
297		QLOG_U64("payload_length", f.len);
298		*need_skip += (size_t)f.len;
299		}
300		break;
301		case OSSL_QUIC_FRAME_TYPE_STREAM:
302		case OSSL_QUIC_FRAME_TYPE_STREAM_FIN:
303		case OSSL_QUIC_FRAME_TYPE_STREAM_LEN:
304		case OSSL_QUIC_FRAME_TYPE_STREAM_LEN_FIN:
305		case OSSL_QUIC_FRAME_TYPE_STREAM_OFF:
306		case OSSL_QUIC_FRAME_TYPE_STREAM_OFF_FIN:
307		case OSSL_QUIC_FRAME_TYPE_STREAM_OFF_LEN:
308		case OSSL_QUIC_FRAME_TYPE_STREAM_OFF_LEN_FIN:
309		{
310		OSSL_QUIC_FRAME_STREAM f;
311
312		if (!ossl_quic_wire_decode_frame_stream(pkt, 1, &f))
313		goto unknown;
314
315		QLOG_STR("frame_type", "stream");
316		QLOG_U64("stream_id", f.stream_id);
317		QLOG_U64("offset", f.offset);
318		QLOG_U64("payload_length", f.len);
319		QLOG_BOOL("explicit_length", f.has_explicit_len);
320		if (f.is_fin)
321		QLOG_BOOL("fin", 1);
322		*need_skip = f.has_explicit_len
323		? *need_skip + (size_t)f.len : SIZE_MAX;
324		}
325		break;
326		case OSSL_QUIC_FRAME_TYPE_MAX_DATA:
327		{
328		uint64_t x;
329
330		if (!ossl_quic_wire_decode_frame_max_data(pkt, &x))
331		goto unknown;
332
333		QLOG_STR("frame_type", "max_data");
334		QLOG_U64("maximum", x);
335		}
336		break;
337		case OSSL_QUIC_FRAME_TYPE_MAX_STREAMS_BIDI:
338		case OSSL_QUIC_FRAME_TYPE_MAX_STREAMS_UNI:
339		{
340		uint64_t x;
341
342		if (!ossl_quic_wire_decode_frame_max_streams(pkt, &x))
343		goto unknown;
344
345		QLOG_STR("frame_type", "max_streams");
346		QLOG_STR("stream_type",
347		frame_type == OSSL_QUIC_FRAME_TYPE_MAX_STREAMS_BIDI
348		? "bidirectional" : "unidirectional");
349		QLOG_U64("maximum", x);
350		}
351		break;
352		case OSSL_QUIC_FRAME_TYPE_MAX_STREAM_DATA:
353		{
354		uint64_t stream_id, max_data;
355
356		if (!ossl_quic_wire_decode_frame_max_stream_data(pkt, &stream_id,
357		&max_data))
358		goto unknown;
359
360		QLOG_STR("frame_type", "max_stream_data");
361		QLOG_U64("stream_id", stream_id);
362		QLOG_U64("maximum", max_data);
363		}
364		break;
365		case OSSL_QUIC_FRAME_TYPE_PATH_CHALLENGE:
366		{
367		uint64_t challenge;
368
369		if (!ossl_quic_wire_decode_frame_path_challenge(pkt, &challenge))
370		goto unknown;
371
372		QLOG_STR("frame_type", "path_challenge");
373		}
374		break;
375		case OSSL_QUIC_FRAME_TYPE_PATH_RESPONSE:
376		{
377		uint64_t challenge;
378
379		if (!ossl_quic_wire_decode_frame_path_response(pkt, &challenge))
380		goto unknown;
381
382		QLOG_STR("frame_type", "path_response");
383		}
384		break;
385		case OSSL_QUIC_FRAME_TYPE_CONN_CLOSE_APP:
386		case OSSL_QUIC_FRAME_TYPE_CONN_CLOSE_TRANSPORT:
387		{
388		OSSL_QUIC_FRAME_CONN_CLOSE f;
389
390		if (!ossl_quic_wire_decode_frame_conn_close(pkt, &f))
391		goto unknown;
392
393		QLOG_STR("frame_type", "connection_close");
394		QLOG_STR("error_space", f.is_app ? "application" : "transport");
395		QLOG_U64("error_code_value", f.error_code);
396		if (f.is_app)
397		QLOG_U64("error_code", f.error_code);
398		if (!f.is_app && f.frame_type != 0)
399		QLOG_U64("trigger_frame_type", f.frame_type);
400		QLOG_STR_LEN("reason", f.reason, f.reason_len);
401		}
402		break;
403		case OSSL_QUIC_FRAME_TYPE_HANDSHAKE_DONE:
404		{
405		if (!ossl_quic_wire_decode_frame_handshake_done(pkt))
406		goto unknown;
407
408		QLOG_STR("frame_type", "handshake_done");
409		}
410		break;
411		case OSSL_QUIC_FRAME_TYPE_NEW_CONN_ID:
412		{
413		OSSL_QUIC_FRAME_NEW_CONN_ID f;
414
415		if (!ossl_quic_wire_decode_frame_new_conn_id(pkt, &f))
416		goto unknown;
417
418		QLOG_STR("frame_type", "new_connection_id");
419		QLOG_U64("sequence_number", f.seq_num);
420		QLOG_U64("retire_prior_to", f.retire_prior_to);
421		QLOG_CID("connection_id", &f.conn_id);
422		QLOG_BIN("stateless_reset_token",
423		f.stateless_reset.token,
424		sizeof(f.stateless_reset.token));
425		}
426		break;
427		case OSSL_QUIC_FRAME_TYPE_RETIRE_CONN_ID:
428		{
429		uint64_t seq_num;
430
431		if (!ossl_quic_wire_decode_frame_retire_conn_id(pkt, &seq_num))
432		goto unknown;
433
434		QLOG_STR("frame_type", "retire_connection_id");
435		QLOG_U64("sequence_number", seq_num);
436		}
437		break;
438		case OSSL_QUIC_FRAME_TYPE_DATA_BLOCKED:
439		{
440		uint64_t x;
441
442		if (!ossl_quic_wire_decode_frame_data_blocked(pkt, &x))
443		goto unknown;
444
445		QLOG_STR("frame_type", "data_blocked");
446		QLOG_U64("limit", x);
447		}
448		break;
449		case OSSL_QUIC_FRAME_TYPE_STREAM_DATA_BLOCKED:
450		{
451		uint64_t stream_id, x;
452
453		if (!ossl_quic_wire_decode_frame_stream_data_blocked(pkt,
454		&stream_id,
455		&x))
456		goto unknown;
457
458		QLOG_STR("frame_type", "stream_data_blocked");
459		QLOG_U64("stream_id", stream_id);
460		QLOG_U64("limit", x);
461		}
462		break;
463		case OSSL_QUIC_FRAME_TYPE_STREAMS_BLOCKED_BIDI:
464		case OSSL_QUIC_FRAME_TYPE_STREAMS_BLOCKED_UNI:
465		{
466		uint64_t x;
467
468		if (!ossl_quic_wire_decode_frame_streams_blocked(pkt, &x))
469		goto unknown;
470
471		QLOG_STR("frame_type", "streams_blocked");
472		QLOG_STR("stream_type",
473		frame_type == OSSL_QUIC_FRAME_TYPE_STREAMS_BLOCKED_BIDI
474		? "bidirectional" : "unidirectional");
475		QLOG_U64("limit", x);
476		}
477		break;
478		case OSSL_QUIC_FRAME_TYPE_NEW_TOKEN:
479		{
480		const unsigned char *token;
481		size_t token_len;
482
483		if (!ossl_quic_wire_decode_frame_new_token(pkt, &token, &token_len))
484		goto unknown;
485
486		QLOG_STR("frame_type", "new_token");
487		QLOG_BEGIN("token");
488		QLOG_BEGIN("raw");
489		QLOG_BIN("data", token, token_len);
490		QLOG_END();
491		QLOG_END();
492		}
493		break;
494		default:
495		unknown:
496		QLOG_STR("frame_type", "unknown");
497		QLOG_U64("frame_type_value", frame_type);
498
499		/*
500		* Can't continue scanning for frames in this case as the frame length
501		* is unknown. We log the entire body of the rest of the packet payload
502		* as the raw data of the frame.
503		*/
504		QLOG_BEGIN("raw");
505		QLOG_BIN("data", PACKET_data(&orig_pkt),
506		PACKET_remaining(&orig_pkt));
507		QLOG_END();
508		ignore_res(PACKET_forward(pkt, PACKET_remaining(pkt)));
509		break;
510		}
511
512		return 1;
513		}
514
515		static void log_frame(QLOG qlog_instance, PACKET pkt,
516		size_t *need_skip)
517		{
518		size_t rem_before, rem_after;
519
520		rem_before = PACKET_remaining(pkt);
521
522		if (!log_frame_actual(qlog_instance, pkt, need_skip))
523		return;
524
525		rem_after = PACKET_remaining(pkt);
526		QLOG_U64("length", rem_before - rem_after);
527		}
528
529		static int log_frames(QLOG *qlog_instance,
530		const OSSL_QTX_IOVEC *iovec,
531		size_t num_iovec)
532		{
533		size_t i;
534		PACKET pkt;
535		size_t need_skip = 0;
536
537		for (i = 0; i < num_iovec; ++i) {
538		if (!PACKET_buf_init(&pkt, iovec[i].buf, iovec[i].buf_len))
539		return 0;
540
541		while (PACKET_remaining(&pkt) > 0) {
542		if (need_skip > 0) {
543		size_t adv = need_skip;
544
545		if (adv < PACKET_remaining(&pkt))
546		adv = PACKET_remaining(&pkt);
547
548		if (!PACKET_forward(&pkt, adv))
549		return 0;
550
551		need_skip -= adv;
552		continue;
553		}
554
555		QLOG_BEGIN(NULL)
556		{
557		log_frame(qlog_instance, &pkt, &need_skip);
558		}
559		QLOG_END()
560		}
561		}
562
563		return 1;
564		}
565
566		static void log_packet(QLOG *qlog_instance,
567		const QUIC_PKT_HDR *hdr,
568		QUIC_PN pn,
569		const OSSL_QTX_IOVEC *iovec,
570		size_t num_iovec,
571		uint64_t datagram_id)
572		{
573		const char *type_s;
574
575		QLOG_BEGIN("header")
576		type_s = quic_pkt_type_to_qlog(hdr->type);
577		if (type_s == NULL)
578		type_s = "unknown";
579
580		QLOG_STR("packet_type", type_s);
581		if (ossl_quic_pkt_type_has_pn(hdr->type))
582		QLOG_U64("packet_number", pn);
583
584		QLOG_CID("dcid", &hdr->dst_conn_id);
585		if (ossl_quic_pkt_type_has_scid(hdr->type))
586		QLOG_CID("scid", &hdr->src_conn_id);
587
588		if (hdr->token_len > 0) {
589		QLOG_BEGIN("token")
590		QLOG_BEGIN("raw")
591		QLOG_BIN("data", hdr->token, hdr->token_len);
592		QLOG_END()
593		QLOG_END()
594		}
595		/* TODO(QLOG FUTURE): flags, length */
596		QLOG_END()
597		QLOG_U64("datagram_id", datagram_id);
598
599		if (ossl_quic_pkt_type_is_encrypted(hdr->type)) {
600		QLOG_BEGIN_ARRAY("frames")
601		log_frames(qlog_instance, iovec, num_iovec);
602		QLOG_END_ARRAY()
603		}
604		}
605
606		#endif
607
608		void ossl_qlog_event_transport_packet_sent(QLOG *qlog,
609		const QUIC_PKT_HDR *hdr,
610		QUIC_PN pn,
611		const OSSL_QTX_IOVEC *iovec,
612		size_t num_iovec,
613		uint64_t datagram_id)
614	0	{
615		#ifndef OPENSSL_NO_QLOG
616		QLOG_EVENT_BEGIN(qlog, transport, packet_sent)
617		log_packet(qlog, hdr, pn, iovec, num_iovec, datagram_id);
618		QLOG_EVENT_END()
619		#endif
620	0	}
621
622		void ossl_qlog_event_transport_packet_received(QLOG *qlog,
623		const QUIC_PKT_HDR *hdr,
624		QUIC_PN pn,
625		const OSSL_QTX_IOVEC *iovec,
626		size_t num_iovec,
627		uint64_t datagram_id)
628	0	{
629		#ifndef OPENSSL_NO_QLOG
630		QLOG_EVENT_BEGIN(qlog, transport, packet_received)
631		log_packet(qlog, hdr, pn, iovec, num_iovec, datagram_id);
632		QLOG_EVENT_END()
633		#endif
634	0	}