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