Copyright year updates
[openssl.git] / ssl / quic / qlog.c
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 }