diff --git a/include/internal/common.h b/include/internal/common.h index 47cb6631f5..2530ff0412 100644 --- a/include/internal/common.h +++ b/include/internal/common.h @@ -198,6 +198,20 @@ static ossl_inline int ossl_ends_with_dirsep(const char *path) return *path == '/'; } +static ossl_inline char ossl_determine_dirsep(const char *path) +{ + if (ossl_ends_with_dirsep(path)) + return '\0'; + +# if defined(_WIN32) + return '\\'; +# elif defined(__VMS) + return ':'; +# else + return '/'; +# endif +} + static ossl_inline int ossl_is_absolute_path(const char *path) { # if defined __VMS diff --git a/ssl/quic/build.info b/ssl/quic/build.info index 9015202b69..ec31f25306 100644 --- a/ssl/quic/build.info +++ b/ssl/quic/build.info @@ -18,5 +18,6 @@ SOURCE[$LIBSSL]=quic_srtm.c quic_srt_gen.c SOURCE[$LIBSSL]=quic_lcidm.c quic_rcidm.c SOURCE[$LIBSSL]=quic_types.c IF[{- !$disabled{qlog} -}] - SOURCE[$LIBSSL]=json_enc.c + SOURCE[$LIBSSL]=json_enc.c qlog.c + SHARED_SOURCE[$LIBSSL]=../../crypto/getenv.c ENDIF diff --git a/ssl/quic/qlog.c b/ssl/quic/qlog.c new file mode 100644 index 0000000000..33ed4e0986 --- /dev/null +++ b/ssl/quic/qlog.c @@ -0,0 +1,702 @@ +/* + * 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.h" +#include "internal/json_enc.h" +#include "internal/common.h" +#include "internal/cryptlib.h" + +# define BITS_PER_WORD (sizeof(size_t) * 8) +# define NUM_ENABLED_W ((QLOG_EVENT_TYPE_NUM + BITS_PER_WORD - 1) / BITS_PER_WORD) + +static ossl_unused ossl_inline int bit_get(const size_t *p, uint32_t bit_no) +{ + return p[bit_no / BITS_PER_WORD] & (((size_t)1) << (bit_no % BITS_PER_WORD)); +} + +static ossl_unused ossl_inline void bit_set(size_t *p, uint32_t bit_no, int enable) +{ + size_t mask = (((size_t)1) << (bit_no % BITS_PER_WORD)); + + if (enable) + p[bit_no / BITS_PER_WORD] |= mask; + else + p[bit_no / BITS_PER_WORD] &= mask; +} + +/* TODO abort */ + +struct qlog_st { + QLOG_TRACE_INFO info; + + BIO *bio; + size_t enabled[NUM_ENABLED_W]; + uint32_t event_type; + const char *event_cat, *event_name, *event_combined_name; + OSSL_TIME event_time, prev_event_time; + JSON_ENC json; + int header_done, first_event_done; +}; + +static OSSL_TIME default_now(void *arg) +{ + return ossl_time_now(); +} + +/* + * Construction + * ============ + */ +QLOG *ossl_qlog_new(const QLOG_TRACE_INFO *info) +{ + QLOG *qlog = OPENSSL_zalloc(sizeof(QLOG)); + + if (qlog == NULL) + return NULL; + + qlog->info = *info; + + qlog->info.title = NULL; + qlog->info.description = NULL; + qlog->info.group_id = NULL; + + if (info->title != NULL + && (qlog->info.title = OPENSSL_strdup(info->title)) == NULL) + goto err; + + if (info->description != NULL + && (qlog->info.description = OPENSSL_strdup(info->description)) == NULL) + goto err; + + if (info->group_id != NULL + && (qlog->info.group_id = OPENSSL_strdup(info->group_id)) == NULL) + goto err; + + if (!ossl_json_init(&qlog->json, NULL, JSON_FLAG_IJSON | JSON_FLAG_SEQ)) + goto err; + + if (qlog->info.now_cb == NULL) + qlog->info.now_cb = default_now; + + return qlog; + +err: + if (qlog != NULL) { + OPENSSL_free((char *)qlog->info.title); + OPENSSL_free((char *)qlog->info.description); + OPENSSL_free((char *)qlog->info.group_id); + OPENSSL_free(qlog); + } + return NULL; +} + +QLOG *ossl_qlog_new_from_env(const QLOG_TRACE_INFO *info) +{ + QLOG *qlog; + const char *qlogdir = ossl_safe_getenv("QLOGDIR"); + const char *qfilter = ossl_safe_getenv("QFILTER"); + char qlogdir_sep, *filename = NULL; + size_t i, l, strl; + + if (info == NULL || qlogdir == NULL || strlen(qlogdir) == 0) + return NULL; + + l = strlen(qlogdir); + qlogdir_sep = ossl_determine_dirsep(qlogdir); + + /* strlen("client" / "server"); strlen(".sqlog"); _; separator; _; NUL */ + strl = l + info->odcid.id_len * 2 + 6 + 7 + 2; + filename = OPENSSL_malloc(strl + 1); + if (filename == NULL) + return NULL; + + memcpy(filename, qlogdir, l); + if (qlogdir_sep != '\0') + filename[l++] = qlogdir_sep; + + for (i = 0; i < info->odcid.id_len; ++i) + l += sprintf(filename + l, "%02x", info->odcid.id[i]); + + l += snprintf(filename + l, strl, "_%s.sqlog", + info->is_server ? "server" : "client"); + + qlog = ossl_qlog_new(info); + if (qlog == NULL) { + OPENSSL_free(filename); + return NULL; + } + + if (!ossl_qlog_set_sink_filename(qlog, filename)) { + OPENSSL_free(filename); + ossl_qlog_free(qlog); + return NULL; + } + + if (qfilter != NULL && !ossl_qlog_set_filter(qlog, qfilter)) { + OPENSSL_free(filename); + ossl_qlog_free(qlog); + return NULL; + } + + OPENSSL_free(filename); + return qlog; +} + +void ossl_qlog_free(QLOG *qlog) +{ + if (qlog == NULL) + return; + + ossl_json_cleanup(&qlog->json); + BIO_free_all(qlog->bio); + OPENSSL_free((char *)qlog->info.title); + OPENSSL_free((char *)qlog->info.description); + OPENSSL_free((char *)qlog->info.group_id); + OPENSSL_free(qlog); +} + +/* + * Configuration + * ============= + */ +int ossl_qlog_set_sink_bio(QLOG *qlog, BIO *bio) +{ + if (qlog == NULL) + return 0; + + ossl_qlog_flush(qlog); /* best effort */ + BIO_free_all(qlog->bio); + qlog->bio = bio; + ossl_json_set_sink(&qlog->json, bio); + return 1; +} + +#ifndef OPENSSL_NO_STDIO + +int ossl_qlog_set_sink_file(QLOG *qlog, FILE *f, int close_flag) +{ + BIO *bio; + + if (qlog == NULL) + return 0; + + bio = BIO_new_fp(f, BIO_CLOSE); + if (bio == NULL) + return 0; + + if (!ossl_qlog_set_sink_bio(qlog, bio)) { + BIO_free_all(bio); + return 0; + } + + return 1; +} + +#endif + +int ossl_qlog_set_sink_filename(QLOG *qlog, const char *filename) +{ + BIO *bio; + + if (qlog == NULL) + return 0; + + /* + * We supply our own text encoding as JSON requires UTF-8, so disable any + * OS-specific processing here. + */ + bio = BIO_new_file(filename, "wb"); + if (bio == NULL) + return 0; + + if (!ossl_qlog_set_sink_bio(qlog, bio)) { + BIO_free_all(bio); + return 0; + } + + return 1; +} + +int ossl_qlog_flush(QLOG *qlog) +{ + if (qlog == NULL) + return 1; + + return ossl_json_flush(&qlog->json); +} + +int ossl_qlog_set_event_type_enabled(QLOG *qlog, uint32_t event_type, + int enabled) +{ + if (qlog == NULL || event_type >= QLOG_EVENT_TYPE_NUM) + return 0; + + bit_set(qlog->enabled, event_type, enabled); + return 1; +} + +int ossl_qlog_enabled(QLOG *qlog, uint32_t event_type) +{ + if (qlog == NULL) + return 0; + + return bit_get(qlog->enabled, event_type); +} + +/* + * Event Lifecycle + * =============== + */ +static void write_str_once(QLOG *qlog, const char *key, char **p) +{ + if (*p == NULL) + return; + + ossl_json_key(&qlog->json, key); + ossl_json_str(&qlog->json, *p); + + OPENSSL_free(*p); + *p = NULL; +} + +static void qlog_event_seq_header(QLOG *qlog) +{ + if (qlog->header_done) + return; + + ossl_json_object_begin(&qlog->json); + { + ossl_json_key(&qlog->json, "qlog_version"); + ossl_json_str(&qlog->json, "0.3"); + + ossl_json_key(&qlog->json, "qlog_format"); + ossl_json_str(&qlog->json, "JSON-SEQ"); + + write_str_once(qlog, "title", (char **)&qlog->info.title); + write_str_once(qlog, "description", (char **)&qlog->info.description); + + ossl_json_key(&qlog->json, "trace"); + ossl_json_object_begin(&qlog->json); + { + ossl_json_key(&qlog->json, "common_fields"); + ossl_json_object_begin(&qlog->json); + { + ossl_json_key(&qlog->json, "time_format"); + ossl_json_str(&qlog->json, "delta"); + + ossl_json_key(&qlog->json, "protocol_type"); + ossl_json_array_begin(&qlog->json); + { + ossl_json_str(&qlog->json, "QUIC"); + } + ossl_json_array_end(&qlog->json); + + write_str_once(qlog, "group_id", (char **)&qlog->info.group_id); + + ossl_json_key(&qlog->json, "system_info"); + ossl_json_object_begin(&qlog->json); + { + ossl_json_key(&qlog->json, "process_id"); + ossl_json_u64(&qlog->json, (uint64_t)getpid()); + } + ossl_json_object_end(&qlog->json); + } + ossl_json_object_end(&qlog->json); + + ossl_json_key(&qlog->json, "vantage_point"); + ossl_json_object_begin(&qlog->json); + { + ossl_json_key(&qlog->json, "type"); + ossl_json_str(&qlog->json, qlog->info.is_server + ? "server" : "client"); + } + ossl_json_object_end(&qlog->json); + } + ossl_json_object_end(&qlog->json); + } + ossl_json_object_end(&qlog->json); + + qlog->header_done = 1; +} + +static void qlog_event_prologue(QLOG *qlog) +{ + qlog_event_seq_header(qlog); + + ossl_json_object_begin(&qlog->json); + + ossl_json_key(&qlog->json, "name"); + ossl_json_str(&qlog->json, qlog->event_combined_name); + + ossl_json_key(&qlog->json, "data"); + ossl_json_object_begin(&qlog->json); +} + +static void qlog_event_epilogue(QLOG *qlog) +{ + ossl_json_object_end(&qlog->json); + + ossl_json_key(&qlog->json, "time"); + if (!qlog->first_event_done) { + ossl_json_u64(&qlog->json, ossl_time2ms(qlog->event_time)); + qlog->prev_event_time = qlog->event_time; + qlog->first_event_done = 1; + } else { + OSSL_TIME delta = ossl_time_subtract(qlog->event_time, + qlog->prev_event_time); + + ossl_json_u64(&qlog->json, ossl_time2ms(delta)); + qlog->prev_event_time = qlog->event_time; + } + + ossl_json_object_end(&qlog->json); +} + +int ossl_qlog_event_try_begin(QLOG *qlog, + uint32_t event_type, + const char *event_cat, + const char *event_name, + const char *event_combined_name) +{ + if (qlog == NULL) + return 0; + + if (!ossl_assert(qlog->event_type == QLOG_EVENT_TYPE_NONE) + || !ossl_qlog_enabled(qlog, event_type)) + return 0; + + qlog->event_type = event_type; + qlog->event_cat = event_cat; + qlog->event_name = event_name; + qlog->event_combined_name = event_combined_name; + qlog->event_time = qlog->info.now_cb(qlog->info.now_cb_arg); + + qlog_event_prologue(qlog); + return 1; +} + +static void qlog_event_end(QLOG *qlog, int abort) +{ + if (!ossl_assert(qlog != NULL && qlog->event_type != QLOG_EVENT_TYPE_NONE)) + return; + + qlog_event_epilogue(qlog); + qlog->event_type = QLOG_EVENT_TYPE_NONE; +} + +void ossl_qlog_event_end(QLOG *qlog) +{ + qlog_event_end(qlog, /*abort=*/0); +} + +void ossl_qlog_event_abort(QLOG *qlog) +{ + qlog_event_end(qlog, /*abort=*/1); +} + +/* + * Field Generators + * ================ + */ +void ossl_qlog_group_begin(QLOG *qlog, const char *name) +{ + if (name != NULL) + ossl_json_key(&qlog->json, name); + + ossl_json_object_begin(&qlog->json); +} + +void ossl_qlog_group_end(QLOG *qlog) +{ + ossl_json_object_end(&qlog->json); +} + +void ossl_qlog_array_begin(QLOG *qlog, const char *name) +{ + if (name != NULL) + ossl_json_key(&qlog->json, name); + + ossl_json_array_begin(&qlog->json); +} + +void ossl_qlog_array_end(QLOG *qlog) +{ + ossl_json_array_end(&qlog->json); +} + +void ossl_qlog_override_time(QLOG *qlog, OSSL_TIME event_time) +{ + qlog->event_time = event_time; +} + +void ossl_qlog_str(QLOG *qlog, const char *name, const char *value) +{ + if (name != NULL) + ossl_json_key(&qlog->json, name); + + ossl_json_str(&qlog->json, value); +} + +void ossl_qlog_str_len(QLOG *qlog, const char *name, + const char *value, size_t value_len) +{ + if (name != NULL) + ossl_json_key(&qlog->json, name); + + ossl_json_str_len(&qlog->json, value, value_len); +} + +void ossl_qlog_u64(QLOG *qlog, const char *name, uint64_t value) +{ + if (name != NULL) + ossl_json_key(&qlog->json, name); + + ossl_json_u64(&qlog->json, value); +} + +void ossl_qlog_i64(QLOG *qlog, const char *name, int64_t value) +{ + if (name != NULL) + ossl_json_key(&qlog->json, name); + + ossl_json_i64(&qlog->json, value); +} + +void ossl_qlog_bool(QLOG *qlog, const char *name, int value) +{ + if (name != NULL) + ossl_json_key(&qlog->json, name); + + ossl_json_bool(&qlog->json, value); +} + +void ossl_qlog_bin(QLOG *qlog, const char *name, + const void *value, size_t value_len) +{ + if (name != NULL) + ossl_json_key(&qlog->json, name); + + ossl_json_str_hex(&qlog->json, value, value_len); +} + +/* + * Filter Parsing + * ============== + */ +struct lexer { + const char *p, *term_end, *end; +}; + +static ossl_inline int is_term_sep_ws(char c) +{ + return c == ' ' || c == '\r' || c == '\n' || c == '\t'; +} + +static ossl_inline int is_name_char(char c) +{ + return (c >= 'a' && c <= 'z') + || (c >= 'A' && c <= 'Z') + || c == '_' || c == '-'; +} + +static int lex_init(struct lexer *lex, const char *in, size_t in_len) +{ + if (in == NULL) + return 0; + + lex->p = in; + lex->term_end = in; + lex->end = in + in_len; + return 1; +} + +static int lex_do(struct lexer *lex) +{ + const char *p = lex->term_end, *end = lex->end, *term_end; + + for (; is_term_sep_ws(*p) && p < end; ++p); + + if (p == end) { + lex->p = end; + lex->term_end = end; + return 0; + } + + for (term_end = p; !is_term_sep_ws(*term_end) && term_end < end; ++term_end); + + lex->p = p; + lex->term_end = term_end; + return 1; +} + +static int lex_eot(struct lexer *lex) +{ + return lex->p == lex->term_end; +} + +static int lex_peek_char(struct lexer *lex) +{ + return lex_eot(lex) ? -1 : *lex->p; +} + +static int lex_skip_char(struct lexer *lex) +{ + if (lex_eot(lex)) + return 0; + + ++lex->p; + return 1; +} + +static int lex_match(struct lexer *lex, const char *s, size_t s_len) +{ + if ((size_t)(lex->term_end - lex->p) != s_len) + return 0; + + if (memcmp(lex->p, s, s_len)) + return 0; + + return 1; +} + +static void lex_get_rest(struct lexer *lex, const char **str, size_t *str_l) +{ + *str = lex->p; + *str_l = lex->term_end - lex->p; +} + +static int lex_extract_to(struct lexer *lex, char c, + const char **str, size_t *str_l) +{ + const char *p = lex->p, *term_end = lex->term_end, *s; + + for (s = p; s < term_end && *s != c; ++s); + if (s == term_end) + return 0; + + *str = p; + *str_l = term_end - s; + lex->p = ++s; + return 1; +} + +static int ossl_unused filter_match_event(const char *cat, size_t cat_l, + const char *event, size_t event_l, + const char *expect_cat, + const char *expect_event) +{ + size_t expect_cat_l = strlen(expect_cat); + size_t expect_event_l = strlen(expect_event); + + if ((cat != NULL && cat_l != expect_cat_l) + || (event != NULL && event_l != expect_event_l) + || (cat != NULL && memcmp(cat, expect_cat, expect_cat_l)) + || (event != NULL && memcmp(event, expect_event, expect_event_l))) + return 0; + + return 1; +} + +/* + * enabled: event enablement bitmask Array of size NUM_ENABLED_W. + * add: 1 to enable an event, 0 to disable. + * cat: Category name/length. Not necessarily zero terminated. + * NULL to match any. + * event: Event name/length. Not necessarily zero terminated. + * NULL to match any. + */ +static void filter_apply(size_t *enabled, int add, + const char *cat, size_t cat_l, + const char *event, size_t event_l) +{ + /* Find events which match the given filters. */ +# define QLOG_EVENT(e_cat, e_name) \ + if (filter_match_event(cat, cat_l, event, event_l, \ + #e_cat, #e_name)) \ + bit_set(enabled, QLOG_EVENT_TYPE_##e_cat##_##e_name, add); +# include "internal/qlog_events.h" +# undef QLOG_EVENT +} + +static int lex_fail(struct lexer *lex, const char *msg) +{ + lex->p = lex->term_end = lex->end; + return 0; +} + +static int validate_name(const char **p, size_t *l) +{ + const char *p_ = *p; + size_t i, l_ = *l; + + if (l_ == 1 && *p_ == '*') { + *p = NULL; + *l = 0; + return 1; + } + + if (l_ == 0) + return 0; + + for (i = 0; i < l_; ++i) + if (!is_name_char(p_[i])) + return 0; + + return 1; +} + +int ossl_qlog_set_filter(QLOG *qlog, const char *filter) +{ + struct lexer lex = {0}; + char c; + const char *cat, *event; + size_t cat_l, event_l, enabled[NUM_ENABLED_W]; + int add; + + memcpy(enabled, qlog->enabled, sizeof(enabled)); + + if (!lex_init(&lex, filter, strlen(filter))) + return 0; + + while (lex_do(&lex)) { + c = lex_peek_char(&lex); + if (c == '+' || c == '-') { + add = (c == '+'); + lex_skip_char(&lex); + + c = lex_peek_char(&lex); + if (!is_name_char(c) && c != '*') + return lex_fail(&lex, "expected alphanumeric name or '*'" + " after +/-"); + } else if (!is_name_char(c) && c != '*') { + return lex_fail(&lex, "expected +/- or alphanumeric name or '*'"); + } else { + add = 1; + } + + if (lex_match(&lex, "*", 1)) { + filter_apply(enabled, add, NULL, 0, NULL, 0); + continue; + } + + if (!lex_extract_to(&lex, ':', &cat, &cat_l)) + return lex_fail(&lex, "expected ':' after category name"); + + lex_get_rest(&lex, &event, &event_l); + if (!validate_name(&cat, &cat_l)) + return lex_fail(&lex, "expected alphanumeric category name or '*'"); + if (!validate_name(&event, &event_l)) + return lex_fail(&lex, "expected alphanumeric event name or '*'"); + + filter_apply(enabled, add, cat, cat_l, event, event_l); + } + + memcpy(qlog->enabled, enabled, sizeof(enabled)); + return 1; +}