Mercurial > hg > nginx
comparison src/event/quic/ngx_event_quic.c @ 8998:308ac307b3e6 quic
QUIC: improved debug logging.
- wording in log->action is adjusted to match function names.
- connection close steps are made obvious and start with "quic close" prefix:
*1 quic close initiated rc:-4
*1 quic close silent drain:0 timedout:1
*1 quic close resumed rc:-1
*1 quic close resumed rc:-1
*1 quic close resumed rc:-4
*1 quic close completed
this makes it easy to understand if particular "close" record is an initial
cause or lasting process, or the final one.
- cases of close without quic connection now logged as "packet rejected":
*14 quic run
*14 quic packet rx long flags:ec version:1
*14 quic packet rx hs len:61
*14 quic packet rx dcid len:20 00000000000002c32f60e4aa2b90a64a39dc4228
*14 quic packet rx scid len:8 81190308612cd019
*14 quic expected initial, got handshake
*14 quic packet done rc:-1 level:hs decr:0 pn:0 perr:0
*14 quic packet rejected rc:-1, cleanup connection
*14 reusable connection: 0
this makes it easy to spot early packet rejection and avoid confuse with
quic connection closing (which in fact was not even created).
- packet processing summary now uses same prefix "quic packet done rc:"
- added debug to places where packet was rejected without any reason logged
author | Vladimir Homutov <vl@nginx.com> |
---|---|
date | Tue, 01 Feb 2022 15:43:56 +0300 |
parents | 430755fcdb61 |
children | 2dc4203d812c |
comparison
equal
deleted
inserted
replaced
8997:fab36e4abf83 | 8998:308ac307b3e6 |
---|---|
457 ngx_uint_t i; | 457 ngx_uint_t i; |
458 ngx_pool_t *pool; | 458 ngx_pool_t *pool; |
459 ngx_quic_send_ctx_t *ctx; | 459 ngx_quic_send_ctx_t *ctx; |
460 ngx_quic_connection_t *qc; | 460 ngx_quic_connection_t *qc; |
461 | 461 |
462 ngx_log_debug1(NGX_LOG_DEBUG_EVENT, c->log, 0, | |
463 "quic ngx_quic_close_connection rc:%i", rc); | |
464 | |
465 qc = ngx_quic_get_connection(c); | 462 qc = ngx_quic_get_connection(c); |
466 | 463 |
467 if (qc == NULL) { | 464 if (qc == NULL) { |
468 if (rc == NGX_ERROR) { | 465 ngx_log_debug1(NGX_LOG_DEBUG_EVENT, c->log, 0, |
469 ngx_log_debug0(NGX_LOG_DEBUG_EVENT, c->log, 0, | 466 "quic packet rejected rc:%i, cleanup connection", rc); |
470 "quic close connection early error"); | |
471 } | |
472 | |
473 goto quic_done; | 467 goto quic_done; |
474 } | 468 } |
469 | |
470 ngx_log_debug2(NGX_LOG_DEBUG_EVENT, c->log, 0, | |
471 "quic close %s rc:%i", | |
472 qc->closing ? "resumed": "initiated", rc); | |
475 | 473 |
476 if (!qc->closing) { | 474 if (!qc->closing) { |
477 | 475 |
478 /* drop packets from retransmit queues, no ack is expected */ | 476 /* drop packets from retransmit queues, no ack is expected */ |
479 for (i = 0; i < NGX_QUIC_SEND_CTX_LAST; i++) { | 477 for (i = 0; i < NGX_QUIC_SEND_CTX_LAST; i++) { |
488 * If a max_idle_timeout is specified by either endpoint in its | 486 * If a max_idle_timeout is specified by either endpoint in its |
489 * transport parameters (Section 18.2), the connection is silently | 487 * transport parameters (Section 18.2), the connection is silently |
490 * closed and its state is discarded when it remains idle | 488 * closed and its state is discarded when it remains idle |
491 */ | 489 */ |
492 | 490 |
493 ngx_log_debug1(NGX_LOG_DEBUG_EVENT, c->log, 0, | 491 /* this case also handles some errors from ngx_quic_run() */ |
494 "quic closing %s connection", | 492 |
495 qc->draining ? "drained" : "idle"); | 493 ngx_log_debug2(NGX_LOG_DEBUG_EVENT, c->log, 0, |
496 | 494 "quic close silent drain:%d timedout:%d", |
495 qc->draining, c->read->timedout); | |
497 } else { | 496 } else { |
498 | 497 |
499 /* | 498 /* |
500 * RFC 9000, 10.2. Immediate Close | 499 * RFC 9000, 10.2. Immediate Close |
501 * | 500 * |
506 qc->error_level = c->ssl ? SSL_quic_read_level(c->ssl->connection) | 505 qc->error_level = c->ssl ? SSL_quic_read_level(c->ssl->connection) |
507 : ssl_encryption_initial; | 506 : ssl_encryption_initial; |
508 | 507 |
509 if (rc == NGX_OK) { | 508 if (rc == NGX_OK) { |
510 ngx_log_debug1(NGX_LOG_DEBUG_EVENT, c->log, 0, | 509 ngx_log_debug1(NGX_LOG_DEBUG_EVENT, c->log, 0, |
511 "quic immediate close drain:%d", | 510 "quic close immediate drain:%d", |
512 qc->draining); | 511 qc->draining); |
513 | 512 |
514 qc->close.log = c->log; | 513 qc->close.log = c->log; |
515 qc->close.data = c; | 514 qc->close.data = c; |
516 qc->close.handler = ngx_quic_close_timer_handler; | 515 qc->close.handler = ngx_quic_close_timer_handler; |
526 if (qc->error == 0 && !qc->error_app) { | 525 if (qc->error == 0 && !qc->error_app) { |
527 qc->error = NGX_QUIC_ERR_INTERNAL_ERROR; | 526 qc->error = NGX_QUIC_ERR_INTERNAL_ERROR; |
528 } | 527 } |
529 | 528 |
530 ngx_log_debug3(NGX_LOG_DEBUG_EVENT, c->log, 0, | 529 ngx_log_debug3(NGX_LOG_DEBUG_EVENT, c->log, 0, |
531 "quic immediate close due to %s error: %ui %s", | 530 "quic close immediate due to %serror: %ui %s", |
532 qc->error_app ? "app " : "", qc->error, | 531 qc->error_app ? "app " : "", qc->error, |
533 qc->error_reason ? qc->error_reason : ""); | 532 qc->error_reason ? qc->error_reason : ""); |
534 } | 533 } |
535 | 534 |
536 (void) ngx_quic_send_cc(c); | 535 (void) ngx_quic_send_cc(c); |
574 return; | 573 return; |
575 } | 574 } |
576 | 575 |
577 ngx_quic_close_sockets(c); | 576 ngx_quic_close_sockets(c); |
578 | 577 |
579 ngx_log_debug0(NGX_LOG_DEBUG_EVENT, c->log, 0, | 578 ngx_log_debug0(NGX_LOG_DEBUG_EVENT, c->log, 0, "quic close completed"); |
580 "quic part of connection is terminated"); | |
581 | 579 |
582 /* may be tested from SSL callback during SSL shutdown */ | 580 /* may be tested from SSL callback during SSL shutdown */ |
583 c->udp = NULL; | 581 c->udp = NULL; |
584 | 582 |
585 quic_done: | 583 quic_done: |
683 rc = ngx_quic_handle_packet(c, conf, &pkt); | 681 rc = ngx_quic_handle_packet(c, conf, &pkt); |
684 | 682 |
685 #if (NGX_DEBUG) | 683 #if (NGX_DEBUG) |
686 if (pkt.parsed) { | 684 if (pkt.parsed) { |
687 ngx_log_debug5(NGX_LOG_DEBUG_EVENT, c->log, 0, | 685 ngx_log_debug5(NGX_LOG_DEBUG_EVENT, c->log, 0, |
688 "quic packet %s done decr:%d pn:%L perr:%ui rc:%i", | 686 "quic packet done rc:%i level:%s" |
689 ngx_quic_level_name(pkt.level), pkt.decrypted, | 687 " decr:%d pn:%L perr:%ui", |
690 pkt.pn, pkt.error, rc); | 688 rc, ngx_quic_level_name(pkt.level), |
689 pkt.decrypted, pkt.pn, pkt.error); | |
691 } else { | 690 } else { |
692 ngx_log_debug1(NGX_LOG_DEBUG_EVENT, c->log, 0, | 691 ngx_log_debug1(NGX_LOG_DEBUG_EVENT, c->log, 0, |
693 "quic packet done parse failed rc:%i", rc); | 692 "quic packet done rc:%i parse failed", rc); |
694 } | 693 } |
695 #endif | 694 #endif |
696 | 695 |
697 if (rc == NGX_ERROR || rc == NGX_DONE) { | 696 if (rc == NGX_ERROR || rc == NGX_DONE) { |
698 return rc; | 697 return rc; |
768 return NGX_DECLINED; | 767 return NGX_DECLINED; |
769 } | 768 } |
770 | 769 |
771 pkt->parsed = 1; | 770 pkt->parsed = 1; |
772 | 771 |
773 c->log->action = "processing quic packet"; | 772 c->log->action = "handling quic packet"; |
774 | 773 |
775 ngx_log_debug2(NGX_LOG_DEBUG_EVENT, c->log, 0, | 774 ngx_log_debug2(NGX_LOG_DEBUG_EVENT, c->log, 0, |
776 "quic packet rx dcid len:%uz %xV", | 775 "quic packet rx dcid len:%uz %xV", |
777 pkt->dcid.len, &pkt->dcid); | 776 pkt->dcid.len, &pkt->dcid); |
778 | 777 |
853 if (pkt->level == ssl_encryption_application) { | 852 if (pkt->level == ssl_encryption_application) { |
854 return ngx_quic_send_stateless_reset(c, conf, pkt); | 853 return ngx_quic_send_stateless_reset(c, conf, pkt); |
855 } | 854 } |
856 | 855 |
857 if (pkt->level != ssl_encryption_initial) { | 856 if (pkt->level != ssl_encryption_initial) { |
857 ngx_log_debug0(NGX_LOG_DEBUG_EVENT, c->log, 0, | |
858 "quic expected initial, got handshake"); | |
858 return NGX_ERROR; | 859 return NGX_ERROR; |
859 } | 860 } |
860 | 861 |
861 c->log->action = "processing initial packet"; | 862 c->log->action = "handling initial packet"; |
862 | 863 |
863 if (pkt->dcid.len < NGX_QUIC_CID_LEN_MIN) { | 864 if (pkt->dcid.len < NGX_QUIC_CID_LEN_MIN) { |
864 /* RFC 9000, 7.2. Negotiating Connection IDs */ | 865 /* RFC 9000, 7.2. Negotiating Connection IDs */ |
865 ngx_log_error(NGX_LOG_INFO, c->log, 0, | 866 ngx_log_error(NGX_LOG_INFO, c->log, 0, |
866 "quic too short dcid in initial" | 867 "quic too short dcid in initial" |