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