QLOG: Frontend: Implementation
authorHugo Landau <hlandau@openssl.org>
Wed, 23 Aug 2023 17:14:40 +0000 (18:14 +0100)
committerHugo Landau <hlandau@openssl.org>
Fri, 2 Feb 2024 11:49:34 +0000 (11:49 +0000)
Reviewed-by: Matt Caswell <matt@openssl.org>
Reviewed-by: Neil Horman <nhorman@openssl.org>
(Merged from https://github.com/openssl/openssl/pull/22037)

include/internal/common.h
ssl/quic/build.info
ssl/quic/qlog.c [new file with mode: 0644]

index 47cb6631f50247652a2e2a6e2f8cdecaa26769c1..2530ff0412d6a789a696ab6638ff105a0b7b2c5f 100644 (file)
@@ -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
index 9015202b69e043b867dfe2498924570cc103bd94..ec31f25306fc1c672aa4eb0f54d1b178cd63f079 100644 (file)
@@ -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 (file)
index 0000000..33ed4e0
--- /dev/null
@@ -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;
+}