1 /* 2 * Copyright 2023-2024 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.h" 11 #include "internal/json_enc.h" 12 #include "internal/common.h" 13 #include "internal/cryptlib.h" 14 #include "crypto/ctype.h" 15 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) 18 19 static ossl_unused ossl_inline int bit_get(const size_t *p, uint32_t bit_no) 20 { 21 return p[bit_no / BITS_PER_WORD] & (((size_t)1) << (bit_no % BITS_PER_WORD)); 22 } 23 24 static ossl_unused ossl_inline void bit_set(size_t *p, uint32_t bit_no, int enable) 25 { 26 size_t mask = (((size_t)1) << (bit_no % BITS_PER_WORD)); 27 28 if (enable) 29 p[bit_no / BITS_PER_WORD] |= mask; 30 else 31 p[bit_no / BITS_PER_WORD] &= ~mask; 32 } 33 34 struct qlog_st { 35 QLOG_TRACE_INFO info; 36 37 BIO *bio; 38 size_t enabled[NUM_ENABLED_W]; 39 uint32_t event_type; 40 const char *event_cat, *event_name, *event_combined_name; 41 OSSL_TIME event_time, prev_event_time; 42 OSSL_JSON_ENC json; 43 int header_done, first_event_done; 44 }; 45 46 static OSSL_TIME default_now(void *arg) 47 { 48 return ossl_time_now(); 49 } 50 51 /* 52 * Construction 53 * ============ 54 */ 55 QLOG *ossl_qlog_new(const QLOG_TRACE_INFO *info) 56 { 57 QLOG *qlog = OPENSSL_zalloc(sizeof(QLOG)); 58 59 if (qlog == NULL) 60 return NULL; 61 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; 67 68 if (info->title != NULL 69 && (qlog->info.title = OPENSSL_strdup(info->title)) == NULL) 70 goto err; 71 72 if (info->description != NULL 73 && (qlog->info.description = OPENSSL_strdup(info->description)) == NULL) 74 goto err; 75 76 if (info->group_id != NULL 77 && (qlog->info.group_id = OPENSSL_strdup(info->group_id)) == NULL) 78 goto err; 79 80 if (info->override_impl_name != NULL 81 && (qlog->info.override_impl_name 82 = OPENSSL_strdup(info->override_impl_name)) 83 == NULL) 84 goto err; 85 86 if (!ossl_json_init(&qlog->json, NULL, 87 OSSL_JSON_FLAG_IJSON | OSSL_JSON_FLAG_SEQ)) 88 goto err; 89 90 if (qlog->info.now_cb == NULL) 91 qlog->info.now_cb = default_now; 92 93 return qlog; 94 95 err: 96 if (qlog != NULL) { 97 OPENSSL_free((char *)qlog->info.title); 98 OPENSSL_free((char *)qlog->info.description); 99 OPENSSL_free((char *)qlog->info.group_id); 100 OPENSSL_free((char *)qlog->info.override_impl_name); 101 OPENSSL_free(qlog); 102 } 103 return NULL; 104 } 105 106 QLOG *ossl_qlog_new_from_env(const QLOG_TRACE_INFO *info) 107 { 108 QLOG *qlog = NULL; 109 const char *qlogdir = ossl_safe_getenv("QLOGDIR"); 110 const char *qfilter = ossl_safe_getenv("OSSL_QFILTER"); 111 char qlogdir_sep, *filename = NULL; 112 size_t i, l, strl; 113 114 if (info == NULL || qlogdir == NULL) 115 return NULL; 116 117 l = strlen(qlogdir); 118 if (l == 0) 119 return NULL; 120 121 qlogdir_sep = ossl_determine_dirsep(qlogdir); 122 123 /* dir; [sep]; ODCID; _; strlen("client" / "server"); strlen(".sqlog"); NUL */ 124 strl = l + 1 + info->odcid.id_len * 2 + 1 + 6 + 6 + 1; 125 filename = OPENSSL_malloc(strl); 126 if (filename == NULL) 127 return NULL; 128 129 memcpy(filename, qlogdir, l); 130 if (qlogdir_sep != '\0') 131 filename[l++] = qlogdir_sep; 132 133 for (i = 0; i < info->odcid.id_len; ++i) 134 l += BIO_snprintf(filename + l, strl - l, "%02x", info->odcid.id[i]); 135 136 l += BIO_snprintf(filename + l, strl - l, "_%s.sqlog", 137 info->is_server ? "server" : "client"); 138 139 qlog = ossl_qlog_new(info); 140 if (qlog == NULL) 141 goto err; 142 143 if (!ossl_qlog_set_sink_filename(qlog, filename)) 144 goto err; 145 146 if (qfilter == NULL || qfilter[0] == '\0') 147 qfilter = "*"; 148 149 if (!ossl_qlog_set_filter(qlog, qfilter)) 150 goto err; 151 152 OPENSSL_free(filename); 153 return qlog; 154 155 err: 156 OPENSSL_free(filename); 157 ossl_qlog_free(qlog); 158 return NULL; 159 } 160 161 void ossl_qlog_free(QLOG *qlog) 162 { 163 if (qlog == NULL) 164 return; 165 166 ossl_json_flush_cleanup(&qlog->json); 167 BIO_free_all(qlog->bio); 168 OPENSSL_free((char *)qlog->info.title); 169 OPENSSL_free((char *)qlog->info.description); 170 OPENSSL_free((char *)qlog->info.group_id); 171 OPENSSL_free((char *)qlog->info.override_impl_name); 172 OPENSSL_free(qlog); 173 } 174 175 /* 176 * Configuration 177 * ============= 178 */ 179 int ossl_qlog_set_sink_bio(QLOG *qlog, BIO *bio) 180 { 181 if (qlog == NULL) 182 return 0; 183 184 ossl_qlog_flush(qlog); /* best effort */ 185 BIO_free_all(qlog->bio); 186 qlog->bio = bio; 187 ossl_json_set0_sink(&qlog->json, bio); 188 return 1; 189 } 190 191 #ifndef OPENSSL_NO_STDIO 192 193 int ossl_qlog_set_sink_file(QLOG *qlog, FILE *f, int close_flag) 194 { 195 BIO *bio; 196 197 if (qlog == NULL) 198 return 0; 199 200 bio = BIO_new_fp(f, BIO_CLOSE); 201 if (bio == NULL) 202 return 0; 203 204 if (!ossl_qlog_set_sink_bio(qlog, bio)) { 205 BIO_free_all(bio); 206 return 0; 207 } 208 209 return 1; 210 } 211 212 #endif 213 214 int ossl_qlog_set_sink_filename(QLOG *qlog, const char *filename) 215 { 216 BIO *bio; 217 218 if (qlog == NULL) 219 return 0; 220 221 /* 222 * We supply our own text encoding as JSON requires UTF-8, so disable any 223 * OS-specific processing here. 224 */ 225 bio = BIO_new_file(filename, "wb"); 226 if (bio == NULL) 227 return 0; 228 229 if (!ossl_qlog_set_sink_bio(qlog, bio)) { 230 BIO_free_all(bio); 231 return 0; 232 } 233 234 return 1; 235 } 236 237 int ossl_qlog_flush(QLOG *qlog) 238 { 239 if (qlog == NULL) 240 return 1; 241 242 return ossl_json_flush(&qlog->json); 243 } 244 245 int ossl_qlog_set_event_type_enabled(QLOG *qlog, uint32_t event_type, 246 int enabled) 247 { 248 if (qlog == NULL || event_type >= QLOG_EVENT_TYPE_NUM) 249 return 0; 250 251 bit_set(qlog->enabled, event_type, enabled); 252 return 1; 253 } 254 255 int ossl_qlog_enabled(QLOG *qlog, uint32_t event_type) 256 { 257 if (qlog == NULL) 258 return 0; 259 260 return bit_get(qlog->enabled, event_type) != 0; 261 } 262 263 /* 264 * Event Lifecycle 265 * =============== 266 */ 267 static void write_str_once(QLOG *qlog, const char *key, char **p) 268 { 269 if (*p == NULL) 270 return; 271 272 ossl_json_key(&qlog->json, key); 273 ossl_json_str(&qlog->json, *p); 274 275 OPENSSL_free(*p); 276 *p = NULL; 277 } 278 279 static void qlog_event_seq_header(QLOG *qlog) 280 { 281 if (qlog->header_done) 282 return; 283 284 ossl_json_object_begin(&qlog->json); 285 { 286 ossl_json_key(&qlog->json, "qlog_version"); 287 ossl_json_str(&qlog->json, "0.3"); 288 289 ossl_json_key(&qlog->json, "qlog_format"); 290 ossl_json_str(&qlog->json, "JSON-SEQ"); 291 292 write_str_once(qlog, "title", (char **)&qlog->info.title); 293 write_str_once(qlog, "description", (char **)&qlog->info.description); 294 295 ossl_json_key(&qlog->json, "trace"); 296 ossl_json_object_begin(&qlog->json); 297 { 298 ossl_json_key(&qlog->json, "common_fields"); 299 ossl_json_object_begin(&qlog->json); 300 { 301 ossl_json_key(&qlog->json, "time_format"); 302 ossl_json_str(&qlog->json, "delta"); 303 304 ossl_json_key(&qlog->json, "protocol_type"); 305 ossl_json_array_begin(&qlog->json); 306 { 307 ossl_json_str(&qlog->json, "QUIC"); 308 } /* protocol_type */ 309 ossl_json_array_end(&qlog->json); 310 311 write_str_once(qlog, "group_id", (char **)&qlog->info.group_id); 312 313 ossl_json_key(&qlog->json, "system_info"); 314 ossl_json_object_begin(&qlog->json); 315 { 316 if (qlog->info.override_process_id != 0) { 317 ossl_json_key(&qlog->json, "process_id"); 318 ossl_json_u64(&qlog->json, qlog->info.override_process_id); 319 } else { 320 #if defined(OPENSSL_SYS_UNIX) 321 ossl_json_key(&qlog->json, "process_id"); 322 ossl_json_u64(&qlog->json, (uint64_t)getpid()); 323 #elif defined(OPENSSL_SYS_WINDOWS) 324 ossl_json_key(&qlog->json, "process_id"); 325 ossl_json_u64(&qlog->json, (uint64_t)GetCurrentProcessId()); 326 #endif 327 } 328 } /* system_info */ 329 ossl_json_object_end(&qlog->json); 330 } /* common_fields */ 331 ossl_json_object_end(&qlog->json); 332 333 ossl_json_key(&qlog->json, "vantage_point"); 334 ossl_json_object_begin(&qlog->json); 335 { 336 char buf[128]; 337 const char *p = buf; 338 339 if (qlog->info.override_impl_name != NULL) { 340 p = qlog->info.override_impl_name; 341 } else { 342 BIO_snprintf(buf, sizeof(buf), "OpenSSL/%s (%s)", 343 OpenSSL_version(OPENSSL_FULL_VERSION_STRING), 344 OpenSSL_version(OPENSSL_PLATFORM) + 10); 345 } 346 347 ossl_json_key(&qlog->json, "type"); 348 ossl_json_str(&qlog->json, 349 qlog->info.is_server ? "server" : "client"); 350 351 ossl_json_key(&qlog->json, "name"); 352 ossl_json_str(&qlog->json, p); 353 } /* vantage_point */ 354 ossl_json_object_end(&qlog->json); 355 } /* trace */ 356 ossl_json_object_end(&qlog->json); 357 } 358 ossl_json_object_end(&qlog->json); 359 360 qlog->header_done = 1; 361 } 362 363 static void qlog_event_prologue(QLOG *qlog) 364 { 365 qlog_event_seq_header(qlog); 366 367 ossl_json_object_begin(&qlog->json); 368 369 ossl_json_key(&qlog->json, "name"); 370 ossl_json_str(&qlog->json, qlog->event_combined_name); 371 372 ossl_json_key(&qlog->json, "data"); 373 ossl_json_object_begin(&qlog->json); 374 } 375 376 static void qlog_event_epilogue(QLOG *qlog) 377 { 378 ossl_json_object_end(&qlog->json); 379 380 ossl_json_key(&qlog->json, "time"); 381 if (!qlog->first_event_done) { 382 ossl_json_u64(&qlog->json, ossl_time2ms(qlog->event_time)); 383 qlog->prev_event_time = qlog->event_time; 384 qlog->first_event_done = 1; 385 } else { 386 OSSL_TIME delta = ossl_time_subtract(qlog->event_time, 387 qlog->prev_event_time); 388 389 ossl_json_u64(&qlog->json, ossl_time2ms(delta)); 390 qlog->prev_event_time = qlog->event_time; 391 } 392 393 ossl_json_object_end(&qlog->json); 394 } 395 396 int ossl_qlog_event_try_begin(QLOG *qlog, 397 uint32_t event_type, 398 const char *event_cat, 399 const char *event_name, 400 const char *event_combined_name) 401 { 402 if (qlog == NULL) 403 return 0; 404 405 if (!ossl_assert(qlog->event_type == QLOG_EVENT_TYPE_NONE) 406 || !ossl_qlog_enabled(qlog, event_type)) 407 return 0; 408 409 qlog->event_type = event_type; 410 qlog->event_cat = event_cat; 411 qlog->event_name = event_name; 412 qlog->event_combined_name = event_combined_name; 413 qlog->event_time = qlog->info.now_cb(qlog->info.now_cb_arg); 414 415 qlog_event_prologue(qlog); 416 return 1; 417 } 418 419 void ossl_qlog_event_end(QLOG *qlog) 420 { 421 if (!ossl_assert(qlog != NULL && qlog->event_type != QLOG_EVENT_TYPE_NONE)) 422 return; 423 424 qlog_event_epilogue(qlog); 425 qlog->event_type = QLOG_EVENT_TYPE_NONE; 426 } 427 428 /* 429 * Field Generators 430 * ================ 431 */ 432 void ossl_qlog_group_begin(QLOG *qlog, const char *name) 433 { 434 if (name != NULL) 435 ossl_json_key(&qlog->json, name); 436 437 ossl_json_object_begin(&qlog->json); 438 } 439 440 void ossl_qlog_group_end(QLOG *qlog) 441 { 442 ossl_json_object_end(&qlog->json); 443 } 444 445 void ossl_qlog_array_begin(QLOG *qlog, const char *name) 446 { 447 if (name != NULL) 448 ossl_json_key(&qlog->json, name); 449 450 ossl_json_array_begin(&qlog->json); 451 } 452 453 void ossl_qlog_array_end(QLOG *qlog) 454 { 455 ossl_json_array_end(&qlog->json); 456 } 457 458 void ossl_qlog_override_time(QLOG *qlog, OSSL_TIME event_time) 459 { 460 qlog->event_time = event_time; 461 } 462 463 void ossl_qlog_str(QLOG *qlog, const char *name, const char *value) 464 { 465 if (name != NULL) 466 ossl_json_key(&qlog->json, name); 467 468 ossl_json_str(&qlog->json, value); 469 } 470 471 void ossl_qlog_str_len(QLOG *qlog, const char *name, 472 const char *value, size_t value_len) 473 { 474 if (name != NULL) 475 ossl_json_key(&qlog->json, name); 476 477 ossl_json_str_len(&qlog->json, value, value_len); 478 } 479 480 void ossl_qlog_u64(QLOG *qlog, const char *name, uint64_t value) 481 { 482 if (name != NULL) 483 ossl_json_key(&qlog->json, name); 484 485 ossl_json_u64(&qlog->json, value); 486 } 487 488 void ossl_qlog_i64(QLOG *qlog, const char *name, int64_t value) 489 { 490 if (name != NULL) 491 ossl_json_key(&qlog->json, name); 492 493 ossl_json_i64(&qlog->json, value); 494 } 495 496 void ossl_qlog_bool(QLOG *qlog, const char *name, int value) 497 { 498 if (name != NULL) 499 ossl_json_key(&qlog->json, name); 500 501 ossl_json_bool(&qlog->json, value); 502 } 503 504 void ossl_qlog_bin(QLOG *qlog, const char *name, 505 const void *value, size_t value_len) 506 { 507 if (name != NULL) 508 ossl_json_key(&qlog->json, name); 509 510 ossl_json_str_hex(&qlog->json, value, value_len); 511 } 512 513 /* 514 * Filter Parsing 515 * ============== 516 */ 517 struct lexer { 518 const char *p, *term_end, *end; 519 }; 520 521 static ossl_inline int is_term_sep_ws(char c) 522 { 523 return c == ' ' || c == '\r' || c == '\n' || c == '\t'; 524 } 525 526 static ossl_inline int is_name_char(char c) 527 { 528 return ossl_isalpha(c) || ossl_isdigit(c) || c == '_' || c == '-'; 529 } 530 531 static int lex_init(struct lexer *lex, const char *in, size_t in_len) 532 { 533 if (in == NULL) 534 return 0; 535 536 lex->p = in; 537 lex->term_end = in; 538 lex->end = in + in_len; 539 return 1; 540 } 541 542 static int lex_do(struct lexer *lex) 543 { 544 const char *p = lex->term_end, *end = lex->end, *term_end; 545 546 for (; is_term_sep_ws(*p) && p < end; ++p) 547 ; 548 549 if (p == end) { 550 lex->p = end; 551 lex->term_end = end; 552 return 0; 553 } 554 555 for (term_end = p; !is_term_sep_ws(*term_end) && term_end < end; ++term_end) 556 ; 557 558 lex->p = p; 559 lex->term_end = term_end; 560 return 1; 561 } 562 563 static int lex_eot(struct lexer *lex) 564 { 565 return lex->p == lex->term_end; 566 } 567 568 static int lex_peek_char(struct lexer *lex) 569 { 570 return lex_eot(lex) ? -1 : *lex->p; 571 } 572 573 static int lex_skip_char(struct lexer *lex) 574 { 575 if (lex_eot(lex)) 576 return 0; 577 578 ++lex->p; 579 return 1; 580 } 581 582 static int lex_match(struct lexer *lex, const char *s, size_t s_len) 583 { 584 if ((size_t)(lex->term_end - lex->p) != s_len) 585 return 0; 586 587 if (memcmp(lex->p, s, s_len)) 588 return 0; 589 590 return 1; 591 } 592 593 static void lex_get_rest(struct lexer *lex, const char **str, size_t *str_l) 594 { 595 *str = lex->p; 596 *str_l = lex->term_end - lex->p; 597 } 598 599 static int lex_extract_to(struct lexer *lex, char c, 600 const char **str, size_t *str_l) 601 { 602 const char *p = lex->p, *term_end = lex->term_end, *s; 603 604 for (s = p; s < term_end && *s != c; ++s) 605 ; 606 if (s == term_end) 607 return 0; 608 609 *str = p; 610 *str_l = s - p; 611 lex->p = ++s; 612 return 1; 613 } 614 615 static int ossl_unused filter_match_event(const char *cat, size_t cat_l, 616 const char *event, size_t event_l, 617 const char *expect_cat, 618 const char *expect_event) 619 { 620 size_t expect_cat_l = strlen(expect_cat); 621 size_t expect_event_l = strlen(expect_event); 622 623 if ((cat != NULL && cat_l != expect_cat_l) 624 || (event != NULL && event_l != expect_event_l) 625 || (cat != NULL && memcmp(cat, expect_cat, expect_cat_l)) 626 || (event != NULL && memcmp(event, expect_event, expect_event_l))) 627 return 0; 628 629 return 1; 630 } 631 632 /* 633 * enabled: event enablement bitmask Array of size NUM_ENABLED_W. 634 * add: 1 to enable an event, 0 to disable. 635 * cat: Category name/length. Not necessarily zero terminated. 636 * NULL to match any. 637 * event: Event name/length. Not necessarily zero terminated. 638 * NULL to match any. 639 */ 640 static void filter_apply(size_t *enabled, int add, 641 const char *cat, size_t cat_l, 642 const char *event, size_t event_l) 643 { 644 /* Find events which match the given filters. */ 645 #define QLOG_EVENT(e_cat, e_name) \ 646 if (filter_match_event(cat, cat_l, event, event_l, \ 647 #e_cat, #e_name)) \ 648 bit_set(enabled, QLOG_EVENT_TYPE_##e_cat##_##e_name, add); 649 #include "internal/qlog_events.h" 650 #undef QLOG_EVENT 651 } 652 653 static int lex_fail(struct lexer *lex, const char *msg) 654 { 655 /* 656 * TODO(QLOG FUTURE): Determine how to print log messages about bad filter 657 * strings 658 */ 659 lex->p = lex->term_end = lex->end; 660 return 0; 661 } 662 663 static int validate_name(const char **p, size_t *l) 664 { 665 const char *p_ = *p; 666 size_t i, l_ = *l; 667 668 if (l_ == 1 && *p_ == '*') { 669 *p = NULL; 670 *l = 0; 671 return 1; 672 } 673 674 if (l_ == 0) 675 return 0; 676 677 for (i = 0; i < l_; ++i) 678 if (!is_name_char(p_[i])) 679 return 0; 680 681 return 1; 682 } 683 684 int ossl_qlog_set_filter(QLOG *qlog, const char *filter) 685 { 686 struct lexer lex = { 0 }; 687 char c; 688 const char *cat, *event; 689 size_t cat_l, event_l, enabled[NUM_ENABLED_W]; 690 int add; 691 692 memcpy(enabled, qlog->enabled, sizeof(enabled)); 693 694 if (!lex_init(&lex, filter, strlen(filter))) 695 return 0; 696 697 while (lex_do(&lex)) { 698 c = lex_peek_char(&lex); 699 if (c == '+' || c == '-') { 700 add = (c == '+'); 701 lex_skip_char(&lex); 702 703 c = lex_peek_char(&lex); 704 if (!is_name_char(c) && c != '*') 705 return lex_fail(&lex, "expected alphanumeric name or '*'" 706 " after +/-"); 707 } else if (!is_name_char(c) && c != '*') { 708 return lex_fail(&lex, "expected +/- or alphanumeric name or '*'"); 709 } else { 710 add = 1; 711 } 712 713 if (lex_match(&lex, "*", 1)) { 714 filter_apply(enabled, add, NULL, 0, NULL, 0); 715 continue; 716 } 717 718 if (!lex_extract_to(&lex, ':', &cat, &cat_l)) 719 return lex_fail(&lex, "expected ':' after category name"); 720 721 lex_get_rest(&lex, &event, &event_l); 722 if (!validate_name(&cat, &cat_l)) 723 return lex_fail(&lex, "expected alphanumeric category name or '*'"); 724 if (!validate_name(&event, &event_l)) 725 return lex_fail(&lex, "expected alphanumeric event name or '*'"); 726 727 filter_apply(enabled, add, cat, cat_l, event, event_l); 728 } 729 730 memcpy(qlog->enabled, enabled, sizeof(enabled)); 731 return 1; 732 } 733