ssl/quic/qlog.c

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