2 * Copyright 2023-2024 The OpenSSL Project Authors. All Rights Reserved.
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
10 #include "internal/qlog.h"
11 #include "internal/json_enc.h"
12 #include "internal/common.h"
13 #include "internal/cryptlib.h"
14 #include "crypto/ctype.h"
16 #define BITS_PER_WORD (sizeof(size_t) * 8)
17 #define NUM_ENABLED_W ((QLOG_EVENT_TYPE_NUM + BITS_PER_WORD - 1) / BITS_PER_WORD)
19 static ossl_unused ossl_inline int bit_get(const size_t *p, uint32_t bit_no)
21 return p[bit_no / BITS_PER_WORD] & (((size_t)1) << (bit_no % BITS_PER_WORD));
24 static ossl_unused ossl_inline void bit_set(size_t *p, uint32_t bit_no, int enable)
26 size_t mask = (((size_t)1) << (bit_no % BITS_PER_WORD));
29 p[bit_no / BITS_PER_WORD] |= mask;
31 p[bit_no / BITS_PER_WORD] &= ~mask;
38 size_t enabled[NUM_ENABLED_W];
40 const char *event_cat, *event_name, *event_combined_name;
41 OSSL_TIME event_time, prev_event_time;
43 int header_done, first_event_done;
46 static OSSL_TIME default_now(void *arg)
48 return ossl_time_now();
55 QLOG *ossl_qlog_new(const QLOG_TRACE_INFO *info)
57 QLOG *qlog = OPENSSL_zalloc(sizeof(QLOG));
62 qlog->info.odcid = info->odcid;
63 qlog->info.is_server = info->is_server;
64 qlog->info.now_cb = info->now_cb;
65 qlog->info.now_cb_arg = info->now_cb_arg;
66 qlog->info.override_process_id = info->override_process_id;
68 if (info->title != NULL
69 && (qlog->info.title = OPENSSL_strdup(info->title)) == NULL)
72 if (info->description != NULL
73 && (qlog->info.description = OPENSSL_strdup(info->description)) == NULL)
76 if (info->group_id != NULL
77 && (qlog->info.group_id = OPENSSL_strdup(info->group_id)) == NULL)
80 if (info->override_impl_name != NULL
81 && (qlog->info.override_impl_name
82 = OPENSSL_strdup(info->override_impl_name)) == NULL)
85 if (!ossl_json_init(&qlog->json, NULL,
86 OSSL_JSON_FLAG_IJSON | OSSL_JSON_FLAG_SEQ))
89 if (qlog->info.now_cb == NULL)
90 qlog->info.now_cb = default_now;
96 OPENSSL_free((char *)qlog->info.title);
97 OPENSSL_free((char *)qlog->info.description);
98 OPENSSL_free((char *)qlog->info.group_id);
99 OPENSSL_free((char *)qlog->info.override_impl_name);
105 QLOG *ossl_qlog_new_from_env(const QLOG_TRACE_INFO *info)
108 const char *qlogdir = ossl_safe_getenv("QLOGDIR");
109 const char *qfilter = ossl_safe_getenv("OSSL_QFILTER");
110 char qlogdir_sep, *filename = NULL;
113 if (info == NULL || qlogdir == NULL)
120 qlogdir_sep = ossl_determine_dirsep(qlogdir);
122 /* dir; [sep]; ODCID; _; strlen("client" / "server"); strlen(".sqlog"); NUL */
123 strl = l + 1 + info->odcid.id_len * 2 + 1 + 6 + 6 + 1;
124 filename = OPENSSL_malloc(strl);
125 if (filename == NULL)
128 memcpy(filename, qlogdir, l);
129 if (qlogdir_sep != '\0')
130 filename[l++] = qlogdir_sep;
132 for (i = 0; i < info->odcid.id_len; ++i)
133 l += BIO_snprintf(filename + l, strl - l, "%02x", info->odcid.id[i]);
135 l += BIO_snprintf(filename + l, strl - l, "_%s.sqlog",
136 info->is_server ? "server" : "client");
138 qlog = ossl_qlog_new(info);
142 if (!ossl_qlog_set_sink_filename(qlog, filename))
145 if (qfilter == NULL || qfilter[0] == '\0')
148 if (!ossl_qlog_set_filter(qlog, qfilter))
151 OPENSSL_free(filename);
155 OPENSSL_free(filename);
156 ossl_qlog_free(qlog);
160 void ossl_qlog_free(QLOG *qlog)
165 ossl_json_flush_cleanup(&qlog->json);
166 BIO_free_all(qlog->bio);
167 OPENSSL_free((char *)qlog->info.title);
168 OPENSSL_free((char *)qlog->info.description);
169 OPENSSL_free((char *)qlog->info.group_id);
170 OPENSSL_free((char *)qlog->info.override_impl_name);
178 int ossl_qlog_set_sink_bio(QLOG *qlog, BIO *bio)
183 ossl_qlog_flush(qlog); /* best effort */
184 BIO_free_all(qlog->bio);
186 ossl_json_set0_sink(&qlog->json, bio);
190 #ifndef OPENSSL_NO_STDIO
192 int ossl_qlog_set_sink_file(QLOG *qlog, FILE *f, int close_flag)
199 bio = BIO_new_fp(f, BIO_CLOSE);
203 if (!ossl_qlog_set_sink_bio(qlog, bio)) {
213 int ossl_qlog_set_sink_filename(QLOG *qlog, const char *filename)
221 * We supply our own text encoding as JSON requires UTF-8, so disable any
222 * OS-specific processing here.
224 bio = BIO_new_file(filename, "wb");
228 if (!ossl_qlog_set_sink_bio(qlog, bio)) {
236 int ossl_qlog_flush(QLOG *qlog)
241 return ossl_json_flush(&qlog->json);
244 int ossl_qlog_set_event_type_enabled(QLOG *qlog, uint32_t event_type,
247 if (qlog == NULL || event_type >= QLOG_EVENT_TYPE_NUM)
250 bit_set(qlog->enabled, event_type, enabled);
254 int ossl_qlog_enabled(QLOG *qlog, uint32_t event_type)
259 return bit_get(qlog->enabled, event_type) != 0;
266 static void write_str_once(QLOG *qlog, const char *key, char **p)
271 ossl_json_key(&qlog->json, key);
272 ossl_json_str(&qlog->json, *p);
278 static void qlog_event_seq_header(QLOG *qlog)
280 if (qlog->header_done)
283 ossl_json_object_begin(&qlog->json);
285 ossl_json_key(&qlog->json, "qlog_version");
286 ossl_json_str(&qlog->json, "0.3");
288 ossl_json_key(&qlog->json, "qlog_format");
289 ossl_json_str(&qlog->json, "JSON-SEQ");
291 write_str_once(qlog, "title", (char **)&qlog->info.title);
292 write_str_once(qlog, "description", (char **)&qlog->info.description);
294 ossl_json_key(&qlog->json, "trace");
295 ossl_json_object_begin(&qlog->json);
297 ossl_json_key(&qlog->json, "common_fields");
298 ossl_json_object_begin(&qlog->json);
300 ossl_json_key(&qlog->json, "time_format");
301 ossl_json_str(&qlog->json, "delta");
303 ossl_json_key(&qlog->json, "protocol_type");
304 ossl_json_array_begin(&qlog->json);
306 ossl_json_str(&qlog->json, "QUIC");
307 } /* protocol_type */
308 ossl_json_array_end(&qlog->json);
310 write_str_once(qlog, "group_id", (char **)&qlog->info.group_id);
312 ossl_json_key(&qlog->json, "system_info");
313 ossl_json_object_begin(&qlog->json);
315 if (qlog->info.override_process_id != 0) {
316 ossl_json_key(&qlog->json, "process_id");
317 ossl_json_u64(&qlog->json, qlog->info.override_process_id);
319 #if defined(OPENSSL_SYS_UNIX)
320 ossl_json_key(&qlog->json, "process_id");
321 ossl_json_u64(&qlog->json, (uint64_t)getpid());
322 #elif defined(OPENSSL_SYS_WINDOWS)
323 ossl_json_key(&qlog->json, "process_id");
324 ossl_json_u64(&qlog->json, (uint64_t)GetCurrentProcessId());
328 ossl_json_object_end(&qlog->json);
329 } /* common_fields */
330 ossl_json_object_end(&qlog->json);
332 ossl_json_key(&qlog->json, "vantage_point");
333 ossl_json_object_begin(&qlog->json);
338 if (qlog->info.override_impl_name != NULL) {
339 p = qlog->info.override_impl_name;
341 BIO_snprintf(buf, sizeof(buf), "OpenSSL/%s (%s)",
342 OpenSSL_version(OPENSSL_FULL_VERSION_STRING),
343 OpenSSL_version(OPENSSL_PLATFORM) + 10);
346 ossl_json_key(&qlog->json, "type");
347 ossl_json_str(&qlog->json,
348 qlog->info.is_server ? "server" : "client");
350 ossl_json_key(&qlog->json, "name");
351 ossl_json_str(&qlog->json, p);
352 } /* vantage_point */
353 ossl_json_object_end(&qlog->json);
355 ossl_json_object_end(&qlog->json);
357 ossl_json_object_end(&qlog->json);
359 qlog->header_done = 1;
362 static void qlog_event_prologue(QLOG *qlog)
364 qlog_event_seq_header(qlog);
366 ossl_json_object_begin(&qlog->json);
368 ossl_json_key(&qlog->json, "name");
369 ossl_json_str(&qlog->json, qlog->event_combined_name);
371 ossl_json_key(&qlog->json, "data");
372 ossl_json_object_begin(&qlog->json);
375 static void qlog_event_epilogue(QLOG *qlog)
377 ossl_json_object_end(&qlog->json);
379 ossl_json_key(&qlog->json, "time");
380 if (!qlog->first_event_done) {
381 ossl_json_u64(&qlog->json, ossl_time2ms(qlog->event_time));
382 qlog->prev_event_time = qlog->event_time;
383 qlog->first_event_done = 1;
385 OSSL_TIME delta = ossl_time_subtract(qlog->event_time,
386 qlog->prev_event_time);
388 ossl_json_u64(&qlog->json, ossl_time2ms(delta));
389 qlog->prev_event_time = qlog->event_time;
392 ossl_json_object_end(&qlog->json);
395 int ossl_qlog_event_try_begin(QLOG *qlog,
397 const char *event_cat,
398 const char *event_name,
399 const char *event_combined_name)
404 if (!ossl_assert(qlog->event_type == QLOG_EVENT_TYPE_NONE)
405 || !ossl_qlog_enabled(qlog, event_type))
408 qlog->event_type = event_type;
409 qlog->event_cat = event_cat;
410 qlog->event_name = event_name;
411 qlog->event_combined_name = event_combined_name;
412 qlog->event_time = qlog->info.now_cb(qlog->info.now_cb_arg);
414 qlog_event_prologue(qlog);
418 void ossl_qlog_event_end(QLOG *qlog)
420 if (!ossl_assert(qlog != NULL && qlog->event_type != QLOG_EVENT_TYPE_NONE))
423 qlog_event_epilogue(qlog);
424 qlog->event_type = QLOG_EVENT_TYPE_NONE;
431 void ossl_qlog_group_begin(QLOG *qlog, const char *name)
434 ossl_json_key(&qlog->json, name);
436 ossl_json_object_begin(&qlog->json);
439 void ossl_qlog_group_end(QLOG *qlog)
441 ossl_json_object_end(&qlog->json);
444 void ossl_qlog_array_begin(QLOG *qlog, const char *name)
447 ossl_json_key(&qlog->json, name);
449 ossl_json_array_begin(&qlog->json);
452 void ossl_qlog_array_end(QLOG *qlog)
454 ossl_json_array_end(&qlog->json);
457 void ossl_qlog_override_time(QLOG *qlog, OSSL_TIME event_time)
459 qlog->event_time = event_time;
462 void ossl_qlog_str(QLOG *qlog, const char *name, const char *value)
465 ossl_json_key(&qlog->json, name);
467 ossl_json_str(&qlog->json, value);
470 void ossl_qlog_str_len(QLOG *qlog, const char *name,
471 const char *value, size_t value_len)
474 ossl_json_key(&qlog->json, name);
476 ossl_json_str_len(&qlog->json, value, value_len);
479 void ossl_qlog_u64(QLOG *qlog, const char *name, uint64_t value)
482 ossl_json_key(&qlog->json, name);
484 ossl_json_u64(&qlog->json, value);
487 void ossl_qlog_i64(QLOG *qlog, const char *name, int64_t value)
490 ossl_json_key(&qlog->json, name);
492 ossl_json_i64(&qlog->json, value);
495 void ossl_qlog_bool(QLOG *qlog, const char *name, int value)
498 ossl_json_key(&qlog->json, name);
500 ossl_json_bool(&qlog->json, value);
503 void ossl_qlog_bin(QLOG *qlog, const char *name,
504 const void *value, size_t value_len)
507 ossl_json_key(&qlog->json, name);
509 ossl_json_str_hex(&qlog->json, value, value_len);
517 const char *p, *term_end, *end;
520 static ossl_inline int is_term_sep_ws(char c)
522 return c == ' ' || c == '\r' || c == '\n' || c == '\t';
525 static ossl_inline int is_name_char(char c)
527 return ossl_isalpha(c) || ossl_isdigit(c) || c == '_' || c == '-';
530 static int lex_init(struct lexer *lex, const char *in, size_t in_len)
537 lex->end = in + in_len;
541 static int lex_do(struct lexer *lex)
543 const char *p = lex->term_end, *end = lex->end, *term_end;
545 for (; is_term_sep_ws(*p) && p < end; ++p);
553 for (term_end = p; !is_term_sep_ws(*term_end) && term_end < end; ++term_end);
556 lex->term_end = term_end;
560 static int lex_eot(struct lexer *lex)
562 return lex->p == lex->term_end;
565 static int lex_peek_char(struct lexer *lex)
567 return lex_eot(lex) ? -1 : *lex->p;
570 static int lex_skip_char(struct lexer *lex)
579 static int lex_match(struct lexer *lex, const char *s, size_t s_len)
581 if ((size_t)(lex->term_end - lex->p) != s_len)
584 if (memcmp(lex->p, s, s_len))
590 static void lex_get_rest(struct lexer *lex, const char **str, size_t *str_l)
593 *str_l = lex->term_end - lex->p;
596 static int lex_extract_to(struct lexer *lex, char c,
597 const char **str, size_t *str_l)
599 const char *p = lex->p, *term_end = lex->term_end, *s;
601 for (s = p; s < term_end && *s != c; ++s);
611 static int ossl_unused filter_match_event(const char *cat, size_t cat_l,
612 const char *event, size_t event_l,
613 const char *expect_cat,
614 const char *expect_event)
616 size_t expect_cat_l = strlen(expect_cat);
617 size_t expect_event_l = strlen(expect_event);
619 if ((cat != NULL && cat_l != expect_cat_l)
620 || (event != NULL && event_l != expect_event_l)
621 || (cat != NULL && memcmp(cat, expect_cat, expect_cat_l))
622 || (event != NULL && memcmp(event, expect_event, expect_event_l)))
629 * enabled: event enablement bitmask Array of size NUM_ENABLED_W.
630 * add: 1 to enable an event, 0 to disable.
631 * cat: Category name/length. Not necessarily zero terminated.
633 * event: Event name/length. Not necessarily zero terminated.
636 static void filter_apply(size_t *enabled, int add,
637 const char *cat, size_t cat_l,
638 const char *event, size_t event_l)
640 /* Find events which match the given filters. */
641 # define QLOG_EVENT(e_cat, e_name) \
642 if (filter_match_event(cat, cat_l, event, event_l, \
644 bit_set(enabled, QLOG_EVENT_TYPE_##e_cat##_##e_name, add);
645 # include "internal/qlog_events.h"
649 static int lex_fail(struct lexer *lex, const char *msg)
652 * TODO(QLOG FUTURE): Determine how to print log messages about bad filter
655 lex->p = lex->term_end = lex->end;
659 static int validate_name(const char **p, size_t *l)
664 if (l_ == 1 && *p_ == '*') {
673 for (i = 0; i < l_; ++i)
674 if (!is_name_char(p_[i]))
680 int ossl_qlog_set_filter(QLOG *qlog, const char *filter)
682 struct lexer lex = {0};
684 const char *cat, *event;
685 size_t cat_l, event_l, enabled[NUM_ENABLED_W];
688 memcpy(enabled, qlog->enabled, sizeof(enabled));
690 if (!lex_init(&lex, filter, strlen(filter)))
693 while (lex_do(&lex)) {
694 c = lex_peek_char(&lex);
695 if (c == '+' || c == '-') {
699 c = lex_peek_char(&lex);
700 if (!is_name_char(c) && c != '*')
701 return lex_fail(&lex, "expected alphanumeric name or '*'"
703 } else if (!is_name_char(c) && c != '*') {
704 return lex_fail(&lex, "expected +/- or alphanumeric name or '*'");
709 if (lex_match(&lex, "*", 1)) {
710 filter_apply(enabled, add, NULL, 0, NULL, 0);
714 if (!lex_extract_to(&lex, ':', &cat, &cat_l))
715 return lex_fail(&lex, "expected ':' after category name");
717 lex_get_rest(&lex, &event, &event_l);
718 if (!validate_name(&cat, &cat_l))
719 return lex_fail(&lex, "expected alphanumeric category name or '*'");
720 if (!validate_name(&event, &event_l))
721 return lex_fail(&lex, "expected alphanumeric event name or '*'");
723 filter_apply(enabled, add, cat, cat_l, event, event_l);
726 memcpy(qlog->enabled, enabled, sizeof(enabled));