root
/
openssl
mirror of https://github.com/openssl/openssl.git
1
0
Fork 0
Code Issues Actions 7 Packages Projects Releases Wiki Activity
openssl/ssl/quic/qlog_event_helpers.c

637 lines
20 KiB
C
Raw Blame History

/*
* Copyright 2023-2024 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 OSSL_QUIC_ERR_INTERNAL_ERROR:
return "internal_error";
case OSSL_QUIC_ERR_CONNECTION_REFUSED:
return "connection_refused";
case OSSL_QUIC_ERR_FLOW_CONTROL_ERROR:
return "flow_control_error";
case OSSL_QUIC_ERR_STREAM_LIMIT_ERROR:
return "stream_limit_error";
case OSSL_QUIC_ERR_STREAM_STATE_ERROR:
return "stream_state_error";
case OSSL_QUIC_ERR_FINAL_SIZE_ERROR:
return "final_size_error";
case OSSL_QUIC_ERR_FRAME_ENCODING_ERROR:
return "frame_encoding_error";
case OSSL_QUIC_ERR_TRANSPORT_PARAMETER_ERROR:
return "transport_parameter_error";
case OSSL_QUIC_ERR_CONNECTION_ID_LIMIT_ERROR:
return "connection_id_limit_error";
case OSSL_QUIC_ERR_PROTOCOL_VIOLATION:
return "protocol_violation";
case OSSL_QUIC_ERR_INVALID_TOKEN:
return "invalid_token";
case OSSL_QUIC_ERR_APPLICATION_ERROR:
return "application_error";
case OSSL_QUIC_ERR_CRYPTO_BUFFER_EXCEEDED:
return "crypto_buffer_exceeded";
case OSSL_QUIC_ERR_KEY_UPDATE_ERROR:
return "key_update_error";
case OSSL_QUIC_ERR_AEAD_LIMIT_REACHED:
return "aead_limit_reached";
case OSSL_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 >= OSSL_QUIC_ERR_CRYPTO_ERR_BEGIN
&& tcause->error_code <= OSSL_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)) {
*need_skip = SIZE_MAX;
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
}
Reference in New Issue View Git Blame Copy Permalink