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"