1 /*
2 * ngtcp2
3 *
4 * Copyright (c) 2018 ngtcp2 contributors
5 *
6 * Permission is hereby granted, free of charge, to any person obtaining
7 * a copy of this software and associated documentation files (the
8 * "Software"), to deal in the Software without restriction, including
9 * without limitation the rights to use, copy, modify, merge, publish,
10 * distribute, sublicense, and/or sell copies of the Software, and to
11 * permit persons to whom the Software is furnished to do so, subject to
12 * the following conditions:
13 *
14 * The above copyright notice and this permission notice shall be
15 * included in all copies or substantial portions of the Software.
16 *
17 * THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND,
18 * EXPRESS OR IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF
19 * MERCHANTABILITY, FITNESS FOR A PARTICULAR PURPOSE AND
20 * NONINFRINGEMENT. IN NO EVENT SHALL THE AUTHORS OR COPYRIGHT HOLDERS BE
21 * LIABLE FOR ANY CLAIM, DAMAGES OR OTHER LIABILITY, WHETHER IN AN ACTION
22 * OF CONTRACT, TORT OR OTHERWISE, ARISING FROM, OUT OF OR IN CONNECTION
23 * WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN THE SOFTWARE.
24 */
25 #include "ngtcp2_log.h"
26
27 #include <stdio.h>
28 #ifdef HAVE_UNISTD_H
29 # include <unistd.h>
30 #endif
31 #include <assert.h>
32 #include <string.h>
33
34 #include "ngtcp2_str.h"
35 #include "ngtcp2_vec.h"
36 #include "ngtcp2_macro.h"
37
ngtcp2_log_init(ngtcp2_log * log,const ngtcp2_cid * scid,ngtcp2_printf log_printf,ngtcp2_tstamp ts,void * user_data)38 void ngtcp2_log_init(ngtcp2_log *log, const ngtcp2_cid *scid,
39 ngtcp2_printf log_printf, ngtcp2_tstamp ts,
40 void *user_data) {
41 if (scid) {
42 ngtcp2_encode_hex(log->scid, scid->data, scid->datalen);
43 } else {
44 log->scid[0] = '\0';
45 }
46 log->log_printf = log_printf;
47 log->ts = log->last_ts = ts;
48 log->user_data = user_data;
49 }
50
51 /*
52 * # Log header
53 *
54 * <LEVEL><TIMESTAMP> <SCID> <EVENT>
55 *
56 * <LEVEL>:
57 * Log level. I=Info, W=Warning, E=Error
58 *
59 * <TIMESTAMP>:
60 * Timestamp relative to ngtcp2_log.ts field in milliseconds
61 * resolution.
62 *
63 * <SCID>:
64 * Source Connection ID in hex string.
65 *
66 * <EVENT>:
67 * Event. pkt=packet, frm=frame, rcv=recovery, cry=crypto,
68 * con=connection(catch all)
69 *
70 * # Frame event
71 *
72 * <DIR> <PKN> <PKTNAME>(<PKTTYPE>) <FRAMENAME>(<FRAMETYPE>)
73 *
74 * <DIR>:
75 * Flow direction. tx=transmission, rx=reception
76 *
77 * <PKN>:
78 * Packet number.
79 *
80 * <PKTNAME>:
81 * Packet name. (e.g., Initial, Handshake, S01)
82 *
83 * <PKTTYPE>:
84 * Packet type in hex string.
85 *
86 * <FRAMENAME>:
87 * Frame name. (e.g., STREAM, ACK, PING)
88 *
89 * <FRAMETYPE>:
90 * Frame type in hex string.
91 */
92
93 #define NGTCP2_LOG_BUFLEN 4096
94
95 /* TODO Split second and remaining fraction with comma */
96 #define NGTCP2_LOG_HD "I%08" PRIu64 " 0x%s %s"
97 #define NGTCP2_LOG_PKT NGTCP2_LOG_HD " %s %" PRId64 " %s(0x%02x)"
98 #define NGTCP2_LOG_TP NGTCP2_LOG_HD " remote transport_parameters"
99
100 #define NGTCP2_LOG_FRM_HD_FIELDS(DIR) \
101 timestamp_cast(log->last_ts - log->ts), (const char *)log->scid, "frm", \
102 (DIR), hd->pkt_num, strpkttype(hd), hd->type
103
104 #define NGTCP2_LOG_PKT_HD_FIELDS(DIR) \
105 timestamp_cast(log->last_ts - log->ts), (const char *)log->scid, "pkt", \
106 (DIR), hd->pkt_num, strpkttype(hd), hd->type
107
108 #define NGTCP2_LOG_TP_HD_FIELDS \
109 timestamp_cast(log->last_ts - log->ts), (const char *)log->scid, "cry"
110
strerrorcode(uint64_t error_code)111 static const char *strerrorcode(uint64_t error_code) {
112 switch (error_code) {
113 case NGTCP2_NO_ERROR:
114 return "NO_ERROR";
115 case NGTCP2_INTERNAL_ERROR:
116 return "INTERNAL_ERROR";
117 case NGTCP2_CONNECTION_REFUSED:
118 return "CONNECTION_REFUSED";
119 case NGTCP2_FLOW_CONTROL_ERROR:
120 return "FLOW_CONTROL_ERROR";
121 case NGTCP2_STREAM_LIMIT_ERROR:
122 return "STREAM_LIMIT_ERROR";
123 case NGTCP2_STREAM_STATE_ERROR:
124 return "STREAM_STATE_ERROR";
125 case NGTCP2_FINAL_SIZE_ERROR:
126 return "FINAL_SIZE_ERROR";
127 case NGTCP2_FRAME_ENCODING_ERROR:
128 return "FRAME_ENCODING_ERROR";
129 case NGTCP2_TRANSPORT_PARAMETER_ERROR:
130 return "TRANSPORT_PARAMETER_ERROR";
131 case NGTCP2_CONNECTION_ID_LIMIT_ERROR:
132 return "CONNECTION_ID_LIMIT_ERROR";
133 case NGTCP2_PROTOCOL_VIOLATION:
134 return "PROTOCOL_VIOLATION";
135 case NGTCP2_INVALID_TOKEN:
136 return "INVALID_TOKEN";
137 case NGTCP2_APPLICATION_ERROR:
138 return "APPLICATION_ERROR";
139 case NGTCP2_CRYPTO_BUFFER_EXCEEDED:
140 return "CRYPTO_BUFFER_EXCEEDED";
141 case NGTCP2_KEY_UPDATE_ERROR:
142 return "KEY_UPDATE_ERROR";
143 default:
144 if (0x100u <= error_code && error_code <= 0x1ffu) {
145 return "CRYPTO_ERROR";
146 }
147 return "(unknown)";
148 }
149 }
150
strapperrorcode(uint64_t app_error_code)151 static const char *strapperrorcode(uint64_t app_error_code) {
152 (void)app_error_code;
153 return "(unknown)";
154 }
155
strpkttype_long(uint8_t type)156 static const char *strpkttype_long(uint8_t type) {
157 switch (type) {
158 case NGTCP2_PKT_VERSION_NEGOTIATION:
159 return "VN";
160 case NGTCP2_PKT_STATELESS_RESET:
161 return "SR";
162 case NGTCP2_PKT_INITIAL:
163 return "Initial";
164 case NGTCP2_PKT_RETRY:
165 return "Retry";
166 case NGTCP2_PKT_HANDSHAKE:
167 return "Handshake";
168 case NGTCP2_PKT_0RTT:
169 return "0RTT";
170 default:
171 return "(unknown)";
172 }
173 }
174
strpkttype(const ngtcp2_pkt_hd * hd)175 static const char *strpkttype(const ngtcp2_pkt_hd *hd) {
176 if (hd->flags & NGTCP2_PKT_FLAG_LONG_FORM) {
177 return strpkttype_long(hd->type);
178 }
179 return "Short";
180 }
181
strevent(ngtcp2_log_event ev)182 static const char *strevent(ngtcp2_log_event ev) {
183 switch (ev) {
184 case NGTCP2_LOG_EVENT_CON:
185 return "con";
186 case NGTCP2_LOG_EVENT_PKT:
187 return "pkt";
188 case NGTCP2_LOG_EVENT_FRM:
189 return "frm";
190 case NGTCP2_LOG_EVENT_RCV:
191 return "rcv";
192 case NGTCP2_LOG_EVENT_CRY:
193 return "cry";
194 case NGTCP2_LOG_EVENT_PTV:
195 return "ptv";
196 case NGTCP2_LOG_EVENT_NONE:
197 default:
198 return "non";
199 }
200 }
201
timestamp_cast(uint64_t ns)202 static uint64_t timestamp_cast(uint64_t ns) { return ns / NGTCP2_MILLISECONDS; }
203
log_fr_stream(ngtcp2_log * log,const ngtcp2_pkt_hd * hd,const ngtcp2_stream * fr,const char * dir)204 static void log_fr_stream(ngtcp2_log *log, const ngtcp2_pkt_hd *hd,
205 const ngtcp2_stream *fr, const char *dir) {
206 log->log_printf(
207 log->user_data,
208 (NGTCP2_LOG_PKT " STREAM(0x%02x) id=0x%" PRIx64 " fin=%d offset=%" PRIu64
209 " len=%" PRIu64 " uni=%d"),
210 NGTCP2_LOG_FRM_HD_FIELDS(dir), fr->type | fr->flags, fr->stream_id,
211 fr->fin, fr->offset, ngtcp2_vec_len(fr->data, fr->datacnt),
212 (fr->stream_id & 0x2) != 0);
213 }
214
log_fr_ack(ngtcp2_log * log,const ngtcp2_pkt_hd * hd,const ngtcp2_ack * fr,const char * dir)215 static void log_fr_ack(ngtcp2_log *log, const ngtcp2_pkt_hd *hd,
216 const ngtcp2_ack *fr, const char *dir) {
217 int64_t largest_ack, min_ack;
218 size_t i;
219
220 log->log_printf(log->user_data,
221 (NGTCP2_LOG_PKT " ACK(0x%02x) largest_ack=%" PRId64
222 " ack_delay=%" PRIu64 "(%" PRIu64
223 ") ack_block_count=%zu"),
224 NGTCP2_LOG_FRM_HD_FIELDS(dir), fr->type, fr->largest_ack,
225 fr->ack_delay_unscaled / NGTCP2_MILLISECONDS, fr->ack_delay,
226 fr->num_blks);
227
228 largest_ack = fr->largest_ack;
229 min_ack = fr->largest_ack - (int64_t)fr->first_ack_blklen;
230
231 log->log_printf(log->user_data,
232 (NGTCP2_LOG_PKT " ACK(0x%02x) block=[%" PRId64 "..%" PRId64
233 "] block_count=%" PRIu64),
234 NGTCP2_LOG_FRM_HD_FIELDS(dir), fr->type, largest_ack, min_ack,
235 fr->first_ack_blklen);
236
237 for (i = 0; i < fr->num_blks; ++i) {
238 const ngtcp2_ack_blk *blk = &fr->blks[i];
239 largest_ack = min_ack - (int64_t)blk->gap - 2;
240 min_ack = largest_ack - (int64_t)blk->blklen;
241 log->log_printf(log->user_data,
242 (NGTCP2_LOG_PKT " ACK(0x%02x) block=[%" PRId64 "..%" PRId64
243 "] gap=%" PRIu64 " block_count=%" PRIu64),
244 NGTCP2_LOG_FRM_HD_FIELDS(dir), fr->type, largest_ack,
245 min_ack, blk->gap, blk->blklen);
246 }
247
248 if (fr->type == NGTCP2_FRAME_ACK_ECN) {
249 log->log_printf(log->user_data,
250 (NGTCP2_LOG_PKT " ACK(0x%02x) ect0=%" PRIu64
251 " ect1=%" PRIu64 " ce=%" PRIu64),
252 NGTCP2_LOG_FRM_HD_FIELDS(dir), fr->type, fr->ecn.ect0,
253 fr->ecn.ect1, fr->ecn.ce);
254 }
255 }
256
log_fr_padding(ngtcp2_log * log,const ngtcp2_pkt_hd * hd,const ngtcp2_padding * fr,const char * dir)257 static void log_fr_padding(ngtcp2_log *log, const ngtcp2_pkt_hd *hd,
258 const ngtcp2_padding *fr, const char *dir) {
259 log->log_printf(log->user_data, (NGTCP2_LOG_PKT " PADDING(0x%02x) len=%zu"),
260 NGTCP2_LOG_FRM_HD_FIELDS(dir), fr->type, fr->len);
261 }
262
log_fr_reset_stream(ngtcp2_log * log,const ngtcp2_pkt_hd * hd,const ngtcp2_reset_stream * fr,const char * dir)263 static void log_fr_reset_stream(ngtcp2_log *log, const ngtcp2_pkt_hd *hd,
264 const ngtcp2_reset_stream *fr,
265 const char *dir) {
266 log->log_printf(
267 log->user_data,
268 (NGTCP2_LOG_PKT " RESET_STREAM(0x%02x) id=0x%" PRIx64
269 " app_error_code=%s(0x%" PRIx64 ") final_size=%" PRIu64),
270 NGTCP2_LOG_FRM_HD_FIELDS(dir), fr->type, fr->stream_id,
271 strapperrorcode(fr->app_error_code), fr->app_error_code, fr->final_size);
272 }
273
log_fr_connection_close(ngtcp2_log * log,const ngtcp2_pkt_hd * hd,const ngtcp2_connection_close * fr,const char * dir)274 static void log_fr_connection_close(ngtcp2_log *log, const ngtcp2_pkt_hd *hd,
275 const ngtcp2_connection_close *fr,
276 const char *dir) {
277 char reason[256];
278 size_t reasonlen = ngtcp2_min(sizeof(reason) - 1, fr->reasonlen);
279
280 log->log_printf(log->user_data,
281 (NGTCP2_LOG_PKT
282 " CONNECTION_CLOSE(0x%02x) error_code=%s(0x%" PRIx64 ") "
283 "frame_type=%" PRIx64 " reason_len=%zu reason=[%s]"),
284 NGTCP2_LOG_FRM_HD_FIELDS(dir), fr->type,
285 fr->type == NGTCP2_FRAME_CONNECTION_CLOSE
286 ? strerrorcode(fr->error_code)
287 : strapperrorcode(fr->error_code),
288 fr->error_code, fr->frame_type, fr->reasonlen,
289 ngtcp2_encode_printable_ascii(reason, fr->reason, reasonlen));
290 }
291
log_fr_max_data(ngtcp2_log * log,const ngtcp2_pkt_hd * hd,const ngtcp2_max_data * fr,const char * dir)292 static void log_fr_max_data(ngtcp2_log *log, const ngtcp2_pkt_hd *hd,
293 const ngtcp2_max_data *fr, const char *dir) {
294 log->log_printf(log->user_data,
295 (NGTCP2_LOG_PKT " MAX_DATA(0x%02x) max_data=%" PRIu64),
296 NGTCP2_LOG_FRM_HD_FIELDS(dir), fr->type, fr->max_data);
297 }
298
log_fr_max_stream_data(ngtcp2_log * log,const ngtcp2_pkt_hd * hd,const ngtcp2_max_stream_data * fr,const char * dir)299 static void log_fr_max_stream_data(ngtcp2_log *log, const ngtcp2_pkt_hd *hd,
300 const ngtcp2_max_stream_data *fr,
301 const char *dir) {
302 log->log_printf(log->user_data,
303 (NGTCP2_LOG_PKT " MAX_STREAM_DATA(0x%02x) id=0x%" PRIx64
304 " max_stream_data=%" PRIu64),
305 NGTCP2_LOG_FRM_HD_FIELDS(dir), fr->type, fr->stream_id,
306 fr->max_stream_data);
307 }
308
log_fr_max_streams(ngtcp2_log * log,const ngtcp2_pkt_hd * hd,const ngtcp2_max_streams * fr,const char * dir)309 static void log_fr_max_streams(ngtcp2_log *log, const ngtcp2_pkt_hd *hd,
310 const ngtcp2_max_streams *fr, const char *dir) {
311 log->log_printf(log->user_data,
312 (NGTCP2_LOG_PKT " MAX_STREAMS(0x%02x) max_streams=%" PRIu64),
313 NGTCP2_LOG_FRM_HD_FIELDS(dir), fr->type, fr->max_streams);
314 }
315
log_fr_ping(ngtcp2_log * log,const ngtcp2_pkt_hd * hd,const ngtcp2_ping * fr,const char * dir)316 static void log_fr_ping(ngtcp2_log *log, const ngtcp2_pkt_hd *hd,
317 const ngtcp2_ping *fr, const char *dir) {
318 log->log_printf(log->user_data, (NGTCP2_LOG_PKT " PING(0x%02x)"),
319 NGTCP2_LOG_FRM_HD_FIELDS(dir), fr->type);
320 }
321
log_fr_data_blocked(ngtcp2_log * log,const ngtcp2_pkt_hd * hd,const ngtcp2_data_blocked * fr,const char * dir)322 static void log_fr_data_blocked(ngtcp2_log *log, const ngtcp2_pkt_hd *hd,
323 const ngtcp2_data_blocked *fr,
324 const char *dir) {
325 log->log_printf(log->user_data,
326 (NGTCP2_LOG_PKT " DATA_BLOCKED(0x%02x) offset=%" PRIu64),
327 NGTCP2_LOG_FRM_HD_FIELDS(dir), fr->type, fr->offset);
328 }
329
log_fr_stream_data_blocked(ngtcp2_log * log,const ngtcp2_pkt_hd * hd,const ngtcp2_stream_data_blocked * fr,const char * dir)330 static void log_fr_stream_data_blocked(ngtcp2_log *log, const ngtcp2_pkt_hd *hd,
331 const ngtcp2_stream_data_blocked *fr,
332 const char *dir) {
333 log->log_printf(log->user_data,
334 (NGTCP2_LOG_PKT " STREAM_DATA_BLOCKED(0x%02x) id=0x%" PRIx64
335 " offset=%" PRIu64),
336 NGTCP2_LOG_FRM_HD_FIELDS(dir), fr->type, fr->stream_id,
337 fr->offset);
338 }
339
log_fr_streams_blocked(ngtcp2_log * log,const ngtcp2_pkt_hd * hd,const ngtcp2_streams_blocked * fr,const char * dir)340 static void log_fr_streams_blocked(ngtcp2_log *log, const ngtcp2_pkt_hd *hd,
341 const ngtcp2_streams_blocked *fr,
342 const char *dir) {
343 log->log_printf(
344 log->user_data,
345 (NGTCP2_LOG_PKT " STREAMS_BLOCKED(0x%02x) max_streams=%" PRIu64),
346 NGTCP2_LOG_FRM_HD_FIELDS(dir), fr->type, fr->max_streams);
347 }
348
log_fr_new_connection_id(ngtcp2_log * log,const ngtcp2_pkt_hd * hd,const ngtcp2_new_connection_id * fr,const char * dir)349 static void log_fr_new_connection_id(ngtcp2_log *log, const ngtcp2_pkt_hd *hd,
350 const ngtcp2_new_connection_id *fr,
351 const char *dir) {
352 uint8_t buf[sizeof(fr->stateless_reset_token) * 2 + 1];
353 uint8_t cid[sizeof(fr->cid.data) * 2 + 1];
354
355 log->log_printf(
356 log->user_data,
357 (NGTCP2_LOG_PKT " NEW_CONNECTION_ID(0x%02x) seq=%" PRIu64
358 " cid=0x%s retire_prior_to=%" PRIu64
359 " stateless_reset_token=0x%s"),
360 NGTCP2_LOG_FRM_HD_FIELDS(dir), fr->type, fr->seq,
361 (const char *)ngtcp2_encode_hex(cid, fr->cid.data, fr->cid.datalen),
362 fr->retire_prior_to,
363 (const char *)ngtcp2_encode_hex(buf, fr->stateless_reset_token,
364 sizeof(fr->stateless_reset_token)));
365 }
366
log_fr_stop_sending(ngtcp2_log * log,const ngtcp2_pkt_hd * hd,const ngtcp2_stop_sending * fr,const char * dir)367 static void log_fr_stop_sending(ngtcp2_log *log, const ngtcp2_pkt_hd *hd,
368 const ngtcp2_stop_sending *fr,
369 const char *dir) {
370 log->log_printf(log->user_data,
371 (NGTCP2_LOG_PKT " STOP_SENDING(0x%02x) id=0x%" PRIx64
372 " app_error_code=%s(0x%" PRIx64 ")"),
373 NGTCP2_LOG_FRM_HD_FIELDS(dir), fr->type, fr->stream_id,
374 strapperrorcode(fr->app_error_code), fr->app_error_code);
375 }
376
log_fr_path_challenge(ngtcp2_log * log,const ngtcp2_pkt_hd * hd,const ngtcp2_path_challenge * fr,const char * dir)377 static void log_fr_path_challenge(ngtcp2_log *log, const ngtcp2_pkt_hd *hd,
378 const ngtcp2_path_challenge *fr,
379 const char *dir) {
380 uint8_t buf[sizeof(fr->data) * 2 + 1];
381
382 log->log_printf(
383 log->user_data, (NGTCP2_LOG_PKT " PATH_CHALLENGE(0x%02x) data=0x%s"),
384 NGTCP2_LOG_FRM_HD_FIELDS(dir), fr->type,
385 (const char *)ngtcp2_encode_hex(buf, fr->data, sizeof(fr->data)));
386 }
387
log_fr_path_response(ngtcp2_log * log,const ngtcp2_pkt_hd * hd,const ngtcp2_path_response * fr,const char * dir)388 static void log_fr_path_response(ngtcp2_log *log, const ngtcp2_pkt_hd *hd,
389 const ngtcp2_path_response *fr,
390 const char *dir) {
391 uint8_t buf[sizeof(fr->data) * 2 + 1];
392
393 log->log_printf(
394 log->user_data, (NGTCP2_LOG_PKT " PATH_RESPONSE(0x%02x) data=0x%s"),
395 NGTCP2_LOG_FRM_HD_FIELDS(dir), fr->type,
396 (const char *)ngtcp2_encode_hex(buf, fr->data, sizeof(fr->data)));
397 }
398
log_fr_crypto(ngtcp2_log * log,const ngtcp2_pkt_hd * hd,const ngtcp2_crypto * fr,const char * dir)399 static void log_fr_crypto(ngtcp2_log *log, const ngtcp2_pkt_hd *hd,
400 const ngtcp2_crypto *fr, const char *dir) {
401 size_t datalen = 0;
402 size_t i;
403
404 for (i = 0; i < fr->datacnt; ++i) {
405 datalen += fr->data[i].len;
406 }
407
408 log->log_printf(
409 log->user_data,
410 (NGTCP2_LOG_PKT " CRYPTO(0x%02x) offset=%" PRIu64 " len=%" PRIu64),
411 NGTCP2_LOG_FRM_HD_FIELDS(dir), fr->type, fr->offset, datalen);
412 }
413
log_fr_new_token(ngtcp2_log * log,const ngtcp2_pkt_hd * hd,const ngtcp2_new_token * fr,const char * dir)414 static void log_fr_new_token(ngtcp2_log *log, const ngtcp2_pkt_hd *hd,
415 const ngtcp2_new_token *fr, const char *dir) {
416 /* Show at most first 64 bytes of token. If token is longer than 64
417 bytes, log first 64 bytes and then append "*" */
418 uint8_t buf[128 + 1 + 1];
419 uint8_t *p;
420
421 if (fr->token.len > 64) {
422 p = ngtcp2_encode_hex(buf, fr->token.base, 64);
423 p[128] = '*';
424 p[129] = '\0';
425 } else {
426 p = ngtcp2_encode_hex(buf, fr->token.base, fr->token.len);
427 }
428 log->log_printf(
429 log->user_data, (NGTCP2_LOG_PKT " NEW_TOKEN(0x%02x) token=0x%s len=%zu"),
430 NGTCP2_LOG_FRM_HD_FIELDS(dir), fr->type, (const char *)p, fr->token.len);
431 }
432
log_fr_retire_connection_id(ngtcp2_log * log,const ngtcp2_pkt_hd * hd,const ngtcp2_retire_connection_id * fr,const char * dir)433 static void log_fr_retire_connection_id(ngtcp2_log *log,
434 const ngtcp2_pkt_hd *hd,
435 const ngtcp2_retire_connection_id *fr,
436 const char *dir) {
437 log->log_printf(log->user_data,
438 (NGTCP2_LOG_PKT " RETIRE_CONNECTION_ID(0x%02x) seq=%" PRIu64),
439 NGTCP2_LOG_FRM_HD_FIELDS(dir), fr->type, fr->seq);
440 }
441
log_fr_handshake_done(ngtcp2_log * log,const ngtcp2_pkt_hd * hd,const ngtcp2_handshake_done * fr,const char * dir)442 static void log_fr_handshake_done(ngtcp2_log *log, const ngtcp2_pkt_hd *hd,
443 const ngtcp2_handshake_done *fr,
444 const char *dir) {
445 log->log_printf(log->user_data, (NGTCP2_LOG_PKT " HANDSHAKE_DONE(0x%02x)"),
446 NGTCP2_LOG_FRM_HD_FIELDS(dir), fr->type);
447 }
448
log_fr_datagram(ngtcp2_log * log,const ngtcp2_pkt_hd * hd,const ngtcp2_datagram * fr,const char * dir)449 static void log_fr_datagram(ngtcp2_log *log, const ngtcp2_pkt_hd *hd,
450 const ngtcp2_datagram *fr, const char *dir) {
451 log->log_printf(log->user_data,
452 (NGTCP2_LOG_PKT " DATAGRAM(0x%02x) len=%" PRIu64),
453 NGTCP2_LOG_FRM_HD_FIELDS(dir), fr->type,
454 ngtcp2_vec_len(fr->data, fr->datacnt));
455 }
456
log_fr(ngtcp2_log * log,const ngtcp2_pkt_hd * hd,const ngtcp2_frame * fr,const char * dir)457 static void log_fr(ngtcp2_log *log, const ngtcp2_pkt_hd *hd,
458 const ngtcp2_frame *fr, const char *dir) {
459 switch (fr->type) {
460 case NGTCP2_FRAME_STREAM:
461 log_fr_stream(log, hd, &fr->stream, dir);
462 break;
463 case NGTCP2_FRAME_ACK:
464 case NGTCP2_FRAME_ACK_ECN:
465 log_fr_ack(log, hd, &fr->ack, dir);
466 break;
467 case NGTCP2_FRAME_PADDING:
468 log_fr_padding(log, hd, &fr->padding, dir);
469 break;
470 case NGTCP2_FRAME_RESET_STREAM:
471 log_fr_reset_stream(log, hd, &fr->reset_stream, dir);
472 break;
473 case NGTCP2_FRAME_CONNECTION_CLOSE:
474 case NGTCP2_FRAME_CONNECTION_CLOSE_APP:
475 log_fr_connection_close(log, hd, &fr->connection_close, dir);
476 break;
477 case NGTCP2_FRAME_MAX_DATA:
478 log_fr_max_data(log, hd, &fr->max_data, dir);
479 break;
480 case NGTCP2_FRAME_MAX_STREAM_DATA:
481 log_fr_max_stream_data(log, hd, &fr->max_stream_data, dir);
482 break;
483 case NGTCP2_FRAME_MAX_STREAMS_BIDI:
484 case NGTCP2_FRAME_MAX_STREAMS_UNI:
485 log_fr_max_streams(log, hd, &fr->max_streams, dir);
486 break;
487 case NGTCP2_FRAME_PING:
488 log_fr_ping(log, hd, &fr->ping, dir);
489 break;
490 case NGTCP2_FRAME_DATA_BLOCKED:
491 log_fr_data_blocked(log, hd, &fr->data_blocked, dir);
492 break;
493 case NGTCP2_FRAME_STREAM_DATA_BLOCKED:
494 log_fr_stream_data_blocked(log, hd, &fr->stream_data_blocked, dir);
495 break;
496 case NGTCP2_FRAME_STREAMS_BLOCKED_BIDI:
497 case NGTCP2_FRAME_STREAMS_BLOCKED_UNI:
498 log_fr_streams_blocked(log, hd, &fr->streams_blocked, dir);
499 break;
500 case NGTCP2_FRAME_NEW_CONNECTION_ID:
501 log_fr_new_connection_id(log, hd, &fr->new_connection_id, dir);
502 break;
503 case NGTCP2_FRAME_STOP_SENDING:
504 log_fr_stop_sending(log, hd, &fr->stop_sending, dir);
505 break;
506 case NGTCP2_FRAME_PATH_CHALLENGE:
507 log_fr_path_challenge(log, hd, &fr->path_challenge, dir);
508 break;
509 case NGTCP2_FRAME_PATH_RESPONSE:
510 log_fr_path_response(log, hd, &fr->path_response, dir);
511 break;
512 case NGTCP2_FRAME_CRYPTO:
513 log_fr_crypto(log, hd, &fr->crypto, dir);
514 break;
515 case NGTCP2_FRAME_NEW_TOKEN:
516 log_fr_new_token(log, hd, &fr->new_token, dir);
517 break;
518 case NGTCP2_FRAME_RETIRE_CONNECTION_ID:
519 log_fr_retire_connection_id(log, hd, &fr->retire_connection_id, dir);
520 break;
521 case NGTCP2_FRAME_HANDSHAKE_DONE:
522 log_fr_handshake_done(log, hd, &fr->handshake_done, dir);
523 break;
524 case NGTCP2_FRAME_DATAGRAM:
525 case NGTCP2_FRAME_DATAGRAM_LEN:
526 log_fr_datagram(log, hd, &fr->datagram, dir);
527 break;
528 default:
529 assert(0);
530 }
531 }
532
ngtcp2_log_rx_fr(ngtcp2_log * log,const ngtcp2_pkt_hd * hd,const ngtcp2_frame * fr)533 void ngtcp2_log_rx_fr(ngtcp2_log *log, const ngtcp2_pkt_hd *hd,
534 const ngtcp2_frame *fr) {
535 if (!log->log_printf) {
536 return;
537 }
538
539 log_fr(log, hd, fr, "rx");
540 }
541
ngtcp2_log_tx_fr(ngtcp2_log * log,const ngtcp2_pkt_hd * hd,const ngtcp2_frame * fr)542 void ngtcp2_log_tx_fr(ngtcp2_log *log, const ngtcp2_pkt_hd *hd,
543 const ngtcp2_frame *fr) {
544 if (!log->log_printf) {
545 return;
546 }
547
548 log_fr(log, hd, fr, "tx");
549 }
550
ngtcp2_log_rx_vn(ngtcp2_log * log,const ngtcp2_pkt_hd * hd,const uint32_t * sv,size_t nsv)551 void ngtcp2_log_rx_vn(ngtcp2_log *log, const ngtcp2_pkt_hd *hd,
552 const uint32_t *sv, size_t nsv) {
553 size_t i;
554
555 if (!log->log_printf) {
556 return;
557 }
558
559 for (i = 0; i < nsv; ++i) {
560 log->log_printf(log->user_data, (NGTCP2_LOG_PKT " v=0x%08x"),
561 NGTCP2_LOG_PKT_HD_FIELDS("rx"), sv[i]);
562 }
563 }
564
ngtcp2_log_rx_sr(ngtcp2_log * log,const ngtcp2_pkt_stateless_reset * sr)565 void ngtcp2_log_rx_sr(ngtcp2_log *log, const ngtcp2_pkt_stateless_reset *sr) {
566 uint8_t buf[sizeof(sr->stateless_reset_token) * 2 + 1];
567 ngtcp2_pkt_hd shd;
568 ngtcp2_pkt_hd *hd = &shd;
569
570 if (!log->log_printf) {
571 return;
572 }
573
574 memset(&shd, 0, sizeof(shd));
575
576 shd.flags = NGTCP2_PKT_FLAG_LONG_FORM;
577 shd.type = NGTCP2_PKT_STATELESS_RESET;
578
579 log->log_printf(
580 log->user_data, (NGTCP2_LOG_PKT " token=0x%s randlen=%zu"),
581 NGTCP2_LOG_PKT_HD_FIELDS("rx"),
582 (const char *)ngtcp2_encode_hex(buf, sr->stateless_reset_token,
583 sizeof(sr->stateless_reset_token)),
584 sr->randlen);
585 }
586
ngtcp2_log_remote_tp(ngtcp2_log * log,uint8_t exttype,const ngtcp2_transport_params * params)587 void ngtcp2_log_remote_tp(ngtcp2_log *log, uint8_t exttype,
588 const ngtcp2_transport_params *params) {
589 uint8_t token[NGTCP2_STATELESS_RESET_TOKENLEN * 2 + 1];
590 uint8_t addr[16 * 2 + 7 + 1];
591 uint8_t cid[NGTCP2_MAX_CIDLEN * 2 + 1];
592
593 if (!log->log_printf) {
594 return;
595 }
596
597 if (exttype == NGTCP2_TRANSPORT_PARAMS_TYPE_ENCRYPTED_EXTENSIONS) {
598 if (params->stateless_reset_token_present) {
599 log->log_printf(log->user_data,
600 (NGTCP2_LOG_TP " stateless_reset_token=0x%s"),
601 NGTCP2_LOG_TP_HD_FIELDS,
602 (const char *)ngtcp2_encode_hex(
603 token, params->stateless_reset_token,
604 sizeof(params->stateless_reset_token)));
605 }
606
607 if (params->preferred_address_present) {
608 log->log_printf(log->user_data,
609 (NGTCP2_LOG_TP " preferred_address.ipv4_addr=%s"),
610 NGTCP2_LOG_TP_HD_FIELDS,
611 (const char *)ngtcp2_encode_ipv4(
612 addr, params->preferred_address.ipv4_addr));
613 log->log_printf(
614 log->user_data, (NGTCP2_LOG_TP " preferred_address.ipv4_port=%u"),
615 NGTCP2_LOG_TP_HD_FIELDS, params->preferred_address.ipv4_port);
616
617 log->log_printf(log->user_data,
618 (NGTCP2_LOG_TP " preferred_address.ipv6_addr=%s"),
619 NGTCP2_LOG_TP_HD_FIELDS,
620 (const char *)ngtcp2_encode_ipv6(
621 addr, params->preferred_address.ipv6_addr));
622 log->log_printf(
623 log->user_data, (NGTCP2_LOG_TP " preferred_address.ipv6_port=%u"),
624 NGTCP2_LOG_TP_HD_FIELDS, params->preferred_address.ipv6_port);
625
626 log->log_printf(log->user_data,
627 (NGTCP2_LOG_TP " preferred_address.cid=0x%s"),
628 NGTCP2_LOG_TP_HD_FIELDS,
629 (const char *)ngtcp2_encode_hex(
630 cid, params->preferred_address.cid.data,
631 params->preferred_address.cid.datalen));
632 log->log_printf(
633 log->user_data,
634 (NGTCP2_LOG_TP " preferred_address.stateless_reset_token=0x%s"),
635 NGTCP2_LOG_TP_HD_FIELDS,
636 (const char *)ngtcp2_encode_hex(
637 token, params->preferred_address.stateless_reset_token,
638 sizeof(params->preferred_address.stateless_reset_token)));
639 }
640
641 log->log_printf(
642 log->user_data,
643 (NGTCP2_LOG_TP " original_destination_connection_id=0x%s"),
644 NGTCP2_LOG_TP_HD_FIELDS,
645 (const char *)ngtcp2_encode_hex(cid, params->original_dcid.data,
646 params->original_dcid.datalen));
647
648 if (params->retry_scid_present) {
649 log->log_printf(
650 log->user_data, (NGTCP2_LOG_TP " retry_source_connection_id=0x%s"),
651 NGTCP2_LOG_TP_HD_FIELDS,
652 (const char *)ngtcp2_encode_hex(cid, params->retry_scid.data,
653 params->retry_scid.datalen));
654 }
655 }
656
657 log->log_printf(
658 log->user_data, (NGTCP2_LOG_TP " initial_source_connection_id=0x%s"),
659 NGTCP2_LOG_TP_HD_FIELDS,
660 (const char *)ngtcp2_encode_hex(cid, params->initial_scid.data,
661 params->initial_scid.datalen));
662
663 log->log_printf(
664 log->user_data,
665 (NGTCP2_LOG_TP " initial_max_stream_data_bidi_local=%" PRIu64),
666 NGTCP2_LOG_TP_HD_FIELDS, params->initial_max_stream_data_bidi_local);
667 log->log_printf(
668 log->user_data,
669 (NGTCP2_LOG_TP " initial_max_stream_data_bidi_remote=%" PRIu64),
670 NGTCP2_LOG_TP_HD_FIELDS, params->initial_max_stream_data_bidi_remote);
671 log->log_printf(log->user_data,
672 (NGTCP2_LOG_TP " initial_max_stream_data_uni=%" PRIu64),
673 NGTCP2_LOG_TP_HD_FIELDS, params->initial_max_stream_data_uni);
674 log->log_printf(log->user_data, (NGTCP2_LOG_TP " initial_max_data=%" PRIu64),
675 NGTCP2_LOG_TP_HD_FIELDS, params->initial_max_data);
676 log->log_printf(log->user_data,
677 (NGTCP2_LOG_TP " initial_max_streams_bidi=%" PRIu64),
678 NGTCP2_LOG_TP_HD_FIELDS, params->initial_max_streams_bidi);
679 log->log_printf(log->user_data,
680 (NGTCP2_LOG_TP " initial_max_streams_uni=%" PRIu64),
681 NGTCP2_LOG_TP_HD_FIELDS, params->initial_max_streams_uni);
682 log->log_printf(log->user_data, (NGTCP2_LOG_TP " max_idle_timeout=%" PRIu64),
683 NGTCP2_LOG_TP_HD_FIELDS,
684 params->max_idle_timeout / NGTCP2_MILLISECONDS);
685 log->log_printf(log->user_data,
686 (NGTCP2_LOG_TP " max_udp_payload_size=%" PRIu64),
687 NGTCP2_LOG_TP_HD_FIELDS, params->max_udp_payload_size);
688 log->log_printf(log->user_data,
689 (NGTCP2_LOG_TP " ack_delay_exponent=%" PRIu64),
690 NGTCP2_LOG_TP_HD_FIELDS, params->ack_delay_exponent);
691 log->log_printf(log->user_data, (NGTCP2_LOG_TP " max_ack_delay=%" PRIu64),
692 NGTCP2_LOG_TP_HD_FIELDS,
693 params->max_ack_delay / NGTCP2_MILLISECONDS);
694 log->log_printf(log->user_data,
695 (NGTCP2_LOG_TP " active_connection_id_limit=%" PRIu64),
696 NGTCP2_LOG_TP_HD_FIELDS, params->active_connection_id_limit);
697 log->log_printf(log->user_data,
698 (NGTCP2_LOG_TP " disable_active_migration=%d"),
699 NGTCP2_LOG_TP_HD_FIELDS, params->disable_active_migration);
700 log->log_printf(log->user_data,
701 (NGTCP2_LOG_TP " max_datagram_frame_size=%" PRIu64),
702 NGTCP2_LOG_TP_HD_FIELDS, params->max_datagram_frame_size);
703 log->log_printf(log->user_data, (NGTCP2_LOG_TP " grease_quic_bit=%d"),
704 NGTCP2_LOG_TP_HD_FIELDS, params->grease_quic_bit);
705 }
706
ngtcp2_log_pkt_lost(ngtcp2_log * log,int64_t pkt_num,uint8_t type,uint8_t flags,ngtcp2_tstamp sent_ts)707 void ngtcp2_log_pkt_lost(ngtcp2_log *log, int64_t pkt_num, uint8_t type,
708 uint8_t flags, ngtcp2_tstamp sent_ts) {
709 if (!log->log_printf) {
710 return;
711 }
712
713 ngtcp2_log_info(
714 log, NGTCP2_LOG_EVENT_RCV,
715 "pkn=%" PRId64 " lost type=%s(0x%02x) sent_ts=%" PRIu64, pkt_num,
716 (flags & NGTCP2_PKT_FLAG_LONG_FORM) ? strpkttype_long(type) : "Short",
717 type, sent_ts);
718 }
719
log_pkt_hd(ngtcp2_log * log,const ngtcp2_pkt_hd * hd,const char * dir)720 static void log_pkt_hd(ngtcp2_log *log, const ngtcp2_pkt_hd *hd,
721 const char *dir) {
722 uint8_t dcid[sizeof(hd->dcid.data) * 2 + 1];
723 uint8_t scid[sizeof(hd->scid.data) * 2 + 1];
724
725 if (!log->log_printf) {
726 return;
727 }
728
729 ngtcp2_log_info(
730 log, NGTCP2_LOG_EVENT_PKT,
731 "%s pkn=%" PRId64 " dcid=0x%s scid=0x%s type=%s(0x%02x) len=%zu k=%d",
732 dir, hd->pkt_num,
733 (const char *)ngtcp2_encode_hex(dcid, hd->dcid.data, hd->dcid.datalen),
734 (const char *)ngtcp2_encode_hex(scid, hd->scid.data, hd->scid.datalen),
735 (hd->flags & NGTCP2_PKT_FLAG_LONG_FORM) ? strpkttype_long(hd->type)
736 : "Short",
737 hd->type, hd->len, (hd->flags & NGTCP2_PKT_FLAG_KEY_PHASE) != 0);
738 }
739
ngtcp2_log_rx_pkt_hd(ngtcp2_log * log,const ngtcp2_pkt_hd * hd)740 void ngtcp2_log_rx_pkt_hd(ngtcp2_log *log, const ngtcp2_pkt_hd *hd) {
741 log_pkt_hd(log, hd, "rx");
742 }
743
ngtcp2_log_tx_pkt_hd(ngtcp2_log * log,const ngtcp2_pkt_hd * hd)744 void ngtcp2_log_tx_pkt_hd(ngtcp2_log *log, const ngtcp2_pkt_hd *hd) {
745 log_pkt_hd(log, hd, "tx");
746 }
747
ngtcp2_log_info(ngtcp2_log * log,ngtcp2_log_event ev,const char * fmt,...)748 void ngtcp2_log_info(ngtcp2_log *log, ngtcp2_log_event ev, const char *fmt,
749 ...) {
750 va_list ap;
751 int n;
752 char buf[NGTCP2_LOG_BUFLEN];
753
754 if (!log->log_printf) {
755 return;
756 }
757
758 va_start(ap, fmt);
759 n = vsnprintf(buf, sizeof(buf), fmt, ap);
760 va_end(ap);
761
762 if (n < 0 || (size_t)n >= sizeof(buf)) {
763 return;
764 }
765
766 log->log_printf(log->user_data, (NGTCP2_LOG_HD " %s"),
767 timestamp_cast(log->last_ts - log->ts), log->scid,
768 strevent(ev), buf);
769 }
770
ngtcp2_log_tx_cancel(ngtcp2_log * log,const ngtcp2_pkt_hd * hd)771 void ngtcp2_log_tx_cancel(ngtcp2_log *log, const ngtcp2_pkt_hd *hd) {
772 ngtcp2_log_info(log, NGTCP2_LOG_EVENT_PKT,
773 "cancel tx pkn=%" PRId64 " type=%s(0x%02x)", hd->pkt_num,
774 strpkttype(hd), hd->type);
775 }
776