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