QLOG: Minor updates
[openssl.git] / ssl / quic / qlog_event_helpers.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_event_helpers.h"
11 #include "internal/common.h"
12 #include "internal/packet.h"
13 #include "internal/quic_channel.h"
14 #include "internal/quic_error.h"
15
16 void ossl_qlog_event_connectivity_connection_started(QLOG *qlog,
17                                                      const QUIC_CONN_ID *init_dcid)
18 {
19 #ifndef OPENSSL_NO_QLOG
20     QLOG_EVENT_BEGIN(qlog, connectivity, connection_started)
21         QLOG_STR("protocol", "quic");
22         QLOG_CID("dst_cid", init_dcid);
23     QLOG_EVENT_END()
24 #endif
25 }
26
27 #ifndef OPENSSL_NO_QLOG
28 static const char *map_state_to_qlog(uint32_t state,
29                                      int handshake_complete,
30                                      int handshake_confirmed)
31 {
32     switch (state) {
33     default:
34     case QUIC_CHANNEL_STATE_IDLE:
35         return NULL;
36
37     case QUIC_CHANNEL_STATE_ACTIVE:
38         if (handshake_confirmed)
39             return "handshake_confirmed";
40         else if (handshake_complete)
41             return "handshake_complete";
42         else
43             return "attempted";
44
45     case QUIC_CHANNEL_STATE_TERMINATING_CLOSING:
46         return "closing";
47
48     case QUIC_CHANNEL_STATE_TERMINATING_DRAINING:
49         return "draining";
50
51     case QUIC_CHANNEL_STATE_TERMINATED:
52         return "closed";
53     }
54 }
55 #endif
56
57 void ossl_qlog_event_connectivity_connection_state_updated(QLOG *qlog,
58                                                            uint32_t old_state,
59                                                            uint32_t new_state,
60                                                            int handshake_complete,
61                                                            int handshake_confirmed)
62 {
63 #ifndef OPENSSL_NO_QLOG
64     const char *state_s;
65
66     QLOG_EVENT_BEGIN(qlog, connectivity, connection_state_updated)
67         state_s = map_state_to_qlog(new_state,
68                                     handshake_complete,
69                                     handshake_confirmed);
70
71         if (state_s != NULL)
72             QLOG_STR("state", state_s);
73     QLOG_EVENT_END()
74 #endif
75 }
76
77 #ifndef OPENSSL_NO_QLOG
78 static const char *quic_err_to_qlog(uint64_t error_code)
79 {
80     switch (error_code) {
81         case QUIC_ERR_INTERNAL_ERROR:
82             return "internal_error";
83         case QUIC_ERR_CONNECTION_REFUSED:
84             return "connection_refused";
85         case QUIC_ERR_FLOW_CONTROL_ERROR:
86             return "flow_control_error";
87         case QUIC_ERR_STREAM_LIMIT_ERROR:
88             return "stream_limit_error";
89         case QUIC_ERR_STREAM_STATE_ERROR:
90             return "stream_state_error";
91         case QUIC_ERR_FINAL_SIZE_ERROR:
92             return "final_size_error";
93         case QUIC_ERR_FRAME_ENCODING_ERROR:
94             return "frame_encoding_error";
95         case QUIC_ERR_TRANSPORT_PARAMETER_ERROR:
96             return "transport_parameter_error";
97         case QUIC_ERR_CONNECTION_ID_LIMIT_ERROR:
98             return "connection_id_limit_error";
99         case QUIC_ERR_PROTOCOL_VIOLATION:
100             return "protocol_violation";
101         case QUIC_ERR_INVALID_TOKEN:
102             return "invalid_token";
103         case QUIC_ERR_APPLICATION_ERROR:
104             return "application_error";
105         case QUIC_ERR_CRYPTO_BUFFER_EXCEEDED:
106             return "crypto_buffer_exceeded";
107         case QUIC_ERR_KEY_UPDATE_ERROR:
108             return "key_update_error";
109         case QUIC_ERR_AEAD_LIMIT_REACHED:
110             return "aead_limit_reached";
111         case QUIC_ERR_NO_VIABLE_PATH:
112             return "no_viable_path";
113         default:
114             return NULL;
115     }
116 }
117 #endif
118
119 void ossl_qlog_event_connectivity_connection_closed(QLOG *qlog,
120                                                     const QUIC_TERMINATE_CAUSE *tcause)
121 {
122 #ifndef OPENSSL_NO_QLOG
123     QLOG_EVENT_BEGIN(qlog, connectivity, connection_closed)
124         QLOG_STR("owner", tcause->remote ? "remote" : "local");
125         if (tcause->app) {
126             QLOG_U64("application_code", tcause->error_code);
127         } else {
128             const char *m = quic_err_to_qlog(tcause->error_code);
129             char ce[32];
130
131             if (tcause->error_code >= QUIC_ERR_CRYPTO_ERR_BEGIN
132                 && tcause->error_code <= QUIC_ERR_CRYPTO_ERR_END) {
133                 snprintf(ce, sizeof(ce), "crypto_error_0x%03llx",
134                          (unsigned long long)tcause->error_code);
135                 m = ce;
136             }
137             /* TODO(QLOG): Consider adding ERR information in the output. */
138
139             if (m != NULL)
140                 QLOG_STR("connection_code", m);
141             else
142                 QLOG_U64("connection_code", tcause->error_code);
143         }
144
145         QLOG_STR_LEN("reason", tcause->reason, tcause->reason_len);
146     QLOG_EVENT_END()
147 #endif
148 }
149
150 #ifndef OPENSSL_NO_QLOG
151 static const char *quic_pkt_type_to_qlog(uint32_t pkt_type)
152 {
153     switch (pkt_type) {
154         case QUIC_PKT_TYPE_INITIAL:
155             return "initial";
156         case QUIC_PKT_TYPE_HANDSHAKE:
157             return "handshake";
158         case QUIC_PKT_TYPE_0RTT:
159             return "0RTT";
160         case QUIC_PKT_TYPE_1RTT:
161             return "1RTT";
162         case QUIC_PKT_TYPE_VERSION_NEG:
163             return "version_negotiation";
164         case QUIC_PKT_TYPE_RETRY:
165             return "retry";
166         default:
167             return "unknown";
168     }
169 }
170 #endif
171
172 void ossl_qlog_event_recovery_packet_lost(QLOG *qlog,
173                                           const QUIC_TXPIM_PKT *tpkt)
174 {
175 #ifndef OPENSSL_NO_QLOG
176     QLOG_EVENT_BEGIN(qlog, recovery, packet_lost)
177         QLOG_BEGIN("header")
178             QLOG_STR("packet_type", quic_pkt_type_to_qlog(tpkt->pkt_type));
179             if (ossl_quic_pkt_type_has_pn(tpkt->pkt_type))
180                 QLOG_U64("packet_number", tpkt->ackm_pkt.pkt_num);
181         QLOG_END()
182     QLOG_EVENT_END()
183 #endif
184 }
185
186 #ifndef OPENSSL_NO_QLOG
187 # define MAX_ACK_RANGES 32
188
189 static void ignore_res(int x) {}
190
191 /*
192  * For logging received packets, we need to parse all the frames in the packet
193  * to log them. We should do this separately to the RXDP code because we want to
194  * log the packet and its contents before we start to actually process it in
195  * case it causes an error. We also in general don't want to do other
196  * non-logging related work in the middle of an event logging transaction.
197  * Reparsing packet data allows us to meet these needs while avoiding the need
198  * to keep around bookkeeping data on what frames were in a packet, etc.
199  *
200  * For logging transmitted packets, we actually reuse the same code and reparse
201  * the outgoing packet's payload. This again has the advantage that we only log
202  * a packet when it is actually queued for transmission (and not if something
203  * goes wrong before then) while avoiding the need to keep around bookkeeping
204  * data on what frames it contained.
205  */
206 static int log_frame_actual(QLOG *qlog_instance, PACKET *pkt,
207                             uint64_t *need_skip)
208 {
209     uint64_t frame_type;
210     OSSL_QUIC_FRAME_ACK ack;
211     OSSL_QUIC_ACK_RANGE ack_ranges[MAX_ACK_RANGES];
212     uint64_t num_ranges, total_ranges;
213     size_t i;
214     PACKET orig_pkt = *pkt;
215
216     if (!ossl_quic_wire_peek_frame_header(pkt, &frame_type, NULL))
217         return 0;
218
219     /*
220      * If something goes wrong decoding a frame we cannot log it as that frame
221      * as we need to know how to decode it in order to be able to do so, but in
222      * that case we log it as an unknown frame to assist with diagnosis.
223      */
224     switch (frame_type) {
225     case OSSL_QUIC_FRAME_TYPE_PADDING:
226         QLOG_STR("frame_type", "padding");
227         QLOG_U64("payload_length",
228                  ossl_quic_wire_decode_padding(pkt));
229         break;
230     case OSSL_QUIC_FRAME_TYPE_PING:
231         if (!ossl_quic_wire_decode_frame_ping(pkt))
232             goto unknown;
233
234         QLOG_STR("frame_type", "ping");
235         break;
236     case OSSL_QUIC_FRAME_TYPE_ACK_WITHOUT_ECN:
237     case OSSL_QUIC_FRAME_TYPE_ACK_WITH_ECN:
238         if (!ossl_quic_wire_peek_frame_ack_num_ranges(pkt, &num_ranges))
239             goto unknown;
240
241         ack.ack_ranges      = ack_ranges;
242         ack.num_ack_ranges  = OSSL_NELEM(ack_ranges);
243         if (!ossl_quic_wire_decode_frame_ack(pkt, 3, &ack, &total_ranges))
244             goto unknown;
245
246         QLOG_STR("frame_type", "ack");
247         QLOG_U64("ack_delay", ossl_time2ms(ack.delay_time));
248         if (ack.ecn_present) {
249             QLOG_U64("ect1", ack.ect0);
250             QLOG_U64("ect0", ack.ect1);
251             QLOG_U64("ce", ack.ecnce);
252         }
253         QLOG_BEGIN_ARRAY("acked_ranges");
254         for (i = 0; i < ack.num_ack_ranges; ++i) {
255             QLOG_BEGIN_ARRAY(NULL)
256                 QLOG_U64(NULL, ack.ack_ranges[i].start);
257                 if (ack.ack_ranges[i].end != ack.ack_ranges[i].start)
258                     QLOG_U64(NULL, ack.ack_ranges[i].end);
259             QLOG_END_ARRAY()
260         }
261         QLOG_END_ARRAY()
262         break;
263     case OSSL_QUIC_FRAME_TYPE_RESET_STREAM:
264         {
265             OSSL_QUIC_FRAME_RESET_STREAM f;
266
267             if (!ossl_quic_wire_decode_frame_reset_stream(pkt, &f))
268                 goto unknown;
269
270             QLOG_STR("frame_type", "reset_stream");
271             QLOG_U64("stream_id", f.stream_id);
272             QLOG_U64("error_code", f.app_error_code);
273             QLOG_U64("final_size", f.final_size);
274         }
275         break;
276     case OSSL_QUIC_FRAME_TYPE_STOP_SENDING:
277         {
278             OSSL_QUIC_FRAME_STOP_SENDING f;
279
280             if (!ossl_quic_wire_decode_frame_stop_sending(pkt, &f))
281                 goto unknown;
282
283             QLOG_STR("frame_type", "stop_sending");
284             QLOG_U64("stream_id", f.stream_id);
285             QLOG_U64("error_code", f.app_error_code);
286         }
287         break;
288     case OSSL_QUIC_FRAME_TYPE_CRYPTO:
289         {
290             OSSL_QUIC_FRAME_CRYPTO f;
291
292             if (!ossl_quic_wire_decode_frame_crypto(pkt, 1, &f))
293                 goto unknown;
294
295             QLOG_STR("frame_type", "crypto");
296             QLOG_U64("offset", f.offset);
297             QLOG_U64("payload_length", f.len);
298             *need_skip += f.len;
299         }
300         break;
301     case OSSL_QUIC_FRAME_TYPE_STREAM:
302     case OSSL_QUIC_FRAME_TYPE_STREAM_FIN:
303     case OSSL_QUIC_FRAME_TYPE_STREAM_LEN:
304     case OSSL_QUIC_FRAME_TYPE_STREAM_LEN_FIN:
305     case OSSL_QUIC_FRAME_TYPE_STREAM_OFF:
306     case OSSL_QUIC_FRAME_TYPE_STREAM_OFF_FIN:
307     case OSSL_QUIC_FRAME_TYPE_STREAM_OFF_LEN:
308     case OSSL_QUIC_FRAME_TYPE_STREAM_OFF_LEN_FIN:
309         {
310             OSSL_QUIC_FRAME_STREAM f;
311
312             if (!ossl_quic_wire_decode_frame_stream(pkt, 1, &f))
313                 goto unknown;
314
315             QLOG_STR("frame_type", "stream");
316             QLOG_U64("stream_id", f.stream_id);
317             QLOG_U64("offset", f.offset);
318             QLOG_U64("payload_length", f.len);
319             QLOG_BOOL("explicit_length", f.has_explicit_len);
320             if (f.is_fin)
321                 QLOG_BOOL("fin", 1);
322             *need_skip = f.has_explicit_len ? *need_skip + f.len : UINT64_MAX;
323         }
324         break;
325     case OSSL_QUIC_FRAME_TYPE_MAX_DATA:
326         {
327             uint64_t x;
328
329             if (!ossl_quic_wire_decode_frame_max_data(pkt, &x))
330                 goto unknown;
331
332             QLOG_STR("frame_type", "max_data");
333             QLOG_U64("maximum", x);
334         }
335         break;
336     case OSSL_QUIC_FRAME_TYPE_MAX_STREAMS_BIDI:
337     case OSSL_QUIC_FRAME_TYPE_MAX_STREAMS_UNI:
338         {
339             uint64_t x;
340
341             if (!ossl_quic_wire_decode_frame_max_streams(pkt, &x))
342                 goto unknown;
343
344             QLOG_STR("frame_type", "max_streams");
345             QLOG_STR("stream_type",
346                      frame_type == OSSL_QUIC_FRAME_TYPE_MAX_STREAMS_BIDI
347                         ? "bidirectional" : "unidirectional");
348             QLOG_U64("maximum", x);
349         }
350         break;
351     case OSSL_QUIC_FRAME_TYPE_MAX_STREAM_DATA:
352         {
353             uint64_t stream_id, max_data;
354
355             if (!ossl_quic_wire_decode_frame_max_stream_data(pkt, &stream_id,
356                                                              &max_data))
357                 goto unknown;
358
359             QLOG_STR("frame_type", "max_stream_data");
360             QLOG_U64("stream_id", stream_id);
361             QLOG_U64("maximum", max_data);
362         }
363         break;
364     case OSSL_QUIC_FRAME_TYPE_PATH_CHALLENGE:
365         {
366             uint64_t challenge;
367
368             if (!ossl_quic_wire_decode_frame_path_challenge(pkt, &challenge))
369                 goto unknown;
370
371             QLOG_STR("frame_type", "path_challenge");
372         }
373         break;
374     case OSSL_QUIC_FRAME_TYPE_PATH_RESPONSE:
375         {
376             uint64_t challenge;
377
378             if (!ossl_quic_wire_decode_frame_path_response(pkt, &challenge))
379                 goto unknown;
380
381             QLOG_STR("frame_type", "path_response");
382         }
383         break;
384     case OSSL_QUIC_FRAME_TYPE_CONN_CLOSE_APP:
385     case OSSL_QUIC_FRAME_TYPE_CONN_CLOSE_TRANSPORT:
386         {
387             OSSL_QUIC_FRAME_CONN_CLOSE f;
388
389             if (!ossl_quic_wire_decode_frame_conn_close(pkt, &f))
390                 goto unknown;
391
392             QLOG_STR("frame_type", "connection_close");
393             QLOG_STR("error_space", f.is_app ? "application" : "transport");
394             QLOG_U64("error_code_value", f.error_code);
395             if (f.is_app)
396                 QLOG_U64("error_code", f.error_code);
397             if (!f.is_app && f.frame_type != 0)
398                 QLOG_U64("trigger_frame_type", f.frame_type);
399             QLOG_STR_LEN("reason", f.reason, f.reason_len);
400         }
401         break;
402     case OSSL_QUIC_FRAME_TYPE_HANDSHAKE_DONE:
403         {
404             if (!ossl_quic_wire_decode_frame_handshake_done(pkt))
405                 goto unknown;
406
407             QLOG_STR("frame_type", "handshake_done");
408         }
409         break;
410     case OSSL_QUIC_FRAME_TYPE_NEW_CONN_ID:
411         {
412             OSSL_QUIC_FRAME_NEW_CONN_ID f;
413
414             if (!ossl_quic_wire_decode_frame_new_conn_id(pkt, &f))
415                 goto unknown;
416
417             QLOG_STR("frame_type", "new_connection_id");
418             QLOG_U64("sequence_number", f.seq_num);
419             QLOG_U64("retire_prior_to", f.retire_prior_to);
420             QLOG_CID("connection_id", &f.conn_id);
421             QLOG_BIN("stateless_reset_token",
422                      f.stateless_reset.token,
423                      sizeof(f.stateless_reset.token));
424         }
425         break;
426     case OSSL_QUIC_FRAME_TYPE_RETIRE_CONN_ID:
427         {
428             uint64_t seq_num;
429
430             if (!ossl_quic_wire_decode_frame_retire_conn_id(pkt, &seq_num))
431                 goto unknown;
432
433             QLOG_STR("frame_type", "retire_connection_id");
434             QLOG_U64("sequence_number", seq_num);
435         }
436         break;
437     case OSSL_QUIC_FRAME_TYPE_DATA_BLOCKED:
438         {
439             uint64_t x;
440
441             if (!ossl_quic_wire_decode_frame_data_blocked(pkt, &x))
442                 goto unknown;
443
444             QLOG_STR("frame_type", "data_blocked");
445             QLOG_U64("limit", x);
446         }
447         break;
448     case OSSL_QUIC_FRAME_TYPE_STREAM_DATA_BLOCKED:
449         {
450             uint64_t stream_id, x;
451
452             if (!ossl_quic_wire_decode_frame_stream_data_blocked(pkt,
453                                                                  &stream_id,
454                                                                  &x))
455                 goto unknown;
456
457             QLOG_STR("frame_type", "stream_data_blocked");
458             QLOG_U64("stream_id", stream_id);
459             QLOG_U64("limit", x);
460         }
461         break;
462     case OSSL_QUIC_FRAME_TYPE_STREAMS_BLOCKED_BIDI:
463     case OSSL_QUIC_FRAME_TYPE_STREAMS_BLOCKED_UNI:
464         {
465             uint64_t x;
466
467             if (!ossl_quic_wire_decode_frame_streams_blocked(pkt, &x))
468                 goto unknown;
469
470             QLOG_STR("frame_type", "streams_blocked");
471             QLOG_STR("stream_type",
472                      frame_type == OSSL_QUIC_FRAME_TYPE_STREAMS_BLOCKED_BIDI
473                         ? "bidirectional" : "unidirectional");
474             QLOG_U64("limit", x);
475         }
476         break;
477     case OSSL_QUIC_FRAME_TYPE_NEW_TOKEN:
478         {
479             const unsigned char *token;
480             size_t token_len;
481
482             if (!ossl_quic_wire_decode_frame_new_token(pkt, &token, &token_len))
483                 goto unknown;
484
485             QLOG_STR("frame_type", "new_token");
486             QLOG_BEGIN("token");
487                 QLOG_BEGIN("raw");
488                     QLOG_BIN("data", token, token_len);
489                 QLOG_END();
490             QLOG_END();
491         }
492         break;
493     default:
494 unknown:
495         QLOG_STR("frame_type", "unknown");
496         QLOG_U64("frame_type_value", frame_type);
497
498         /*
499          * Can't continue scanning for frames in this case as the frame length
500          * is unknown. We log the entire body the rest of the packet payload
501          * as the raw data of the frame.
502          */
503         QLOG_BEGIN("raw");
504             QLOG_BIN("data", PACKET_data(&orig_pkt),
505                      PACKET_remaining(&orig_pkt));
506         QLOG_END();
507         ignore_res(PACKET_forward(pkt, PACKET_remaining(pkt)));
508         break;
509     }
510
511     return 1;
512 }
513
514 static void log_frame(QLOG *qlog_instance, PACKET *pkt,
515                       uint64_t *need_skip)
516 {
517     size_t rem_before, rem_after;
518
519     rem_before = PACKET_remaining(pkt);
520
521     if (!log_frame_actual(qlog_instance, pkt, need_skip))
522         return;
523
524     rem_after = PACKET_remaining(pkt);
525     QLOG_U64("length", rem_before - rem_after);
526 }
527
528 static int log_frames(QLOG *qlog_instance,
529                       const OSSL_QTX_IOVEC *iovec,
530                       size_t num_iovec)
531 {
532     size_t i;
533     PACKET pkt;
534     uint64_t need_skip = 0;
535
536     for (i = 0; i < num_iovec; ++i) {
537         if (!PACKET_buf_init(&pkt, iovec[i].buf, iovec[i].buf_len))
538             return 0;
539
540         while (PACKET_remaining(&pkt) > 0) {
541             if (need_skip > 0) {
542                 size_t adv = need_skip;
543
544                 if (adv < PACKET_remaining(&pkt))
545                     adv = PACKET_remaining(&pkt);
546
547                 if (!PACKET_forward(&pkt, adv))
548                     return 0;
549
550                 need_skip -= adv;
551                 continue;
552             }
553
554             QLOG_BEGIN(NULL)
555             {
556                 log_frame(qlog_instance, &pkt, &need_skip);
557             }
558             QLOG_END()
559         }
560     }
561
562     return 1;
563 }
564
565 static void log_packet(QLOG *qlog_instance,
566                        const QUIC_PKT_HDR *hdr,
567                        QUIC_PN pn,
568                        const OSSL_QTX_IOVEC *iovec,
569                        size_t num_iovec,
570                        uint64_t datagram_id)
571 {
572     const char *type_s;
573
574     QLOG_BEGIN("header")
575         type_s = quic_pkt_type_to_qlog(hdr->type);
576         if (type_s == NULL)
577             type_s = "unknown";
578
579         QLOG_STR("packet_type", type_s);
580         if (ossl_quic_pkt_type_has_pn(hdr->type))
581             QLOG_U64("packet_number", pn);
582
583         QLOG_CID("dcid", &hdr->dst_conn_id);
584         if (ossl_quic_pkt_type_has_scid(hdr->type))
585             QLOG_CID("scid", &hdr->src_conn_id);
586
587         if (hdr->token_len > 0) {
588             QLOG_BEGIN("token")
589                 QLOG_BEGIN("raw")
590                     QLOG_BIN("data", hdr->token, hdr->token_len);
591                 QLOG_END()
592             QLOG_END()
593         }
594         /* TODO(QLOG): flags, length */
595     QLOG_END()
596     QLOG_U64("datagram_id", datagram_id);
597
598     if (ossl_quic_pkt_type_is_encrypted(hdr->type)) {
599         QLOG_BEGIN_ARRAY("frames")
600             log_frames(qlog_instance, iovec, num_iovec);
601         QLOG_END_ARRAY()
602     }
603 }
604
605 #endif
606
607 void ossl_qlog_event_transport_packet_sent(QLOG *qlog,
608                                            const QUIC_PKT_HDR *hdr,
609                                            QUIC_PN pn,
610                                            const OSSL_QTX_IOVEC *iovec,
611                                            size_t num_iovec,
612                                            uint64_t datagram_id)
613 {
614 #ifndef OPENSSL_NO_QLOG
615     QLOG_EVENT_BEGIN(qlog, transport, packet_sent)
616         log_packet(qlog, hdr, pn, iovec, num_iovec, datagram_id);
617     QLOG_EVENT_END()
618 #endif
619 }
620
621 void ossl_qlog_event_transport_packet_received(QLOG *qlog,
622                                                const QUIC_PKT_HDR *hdr,
623                                                QUIC_PN pn,
624                                                const OSSL_QTX_IOVEC *iovec,
625                                                size_t num_iovec,
626                                                uint64_t datagram_id)
627 {
628 #ifndef OPENSSL_NO_QLOG
629     QLOG_EVENT_BEGIN(qlog, transport, packet_received)
630         log_packet(qlog, hdr, pn, iovec, num_iovec, datagram_id);
631     QLOG_EVENT_END()
632 #endif
633 }