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