Mercurial > hg > nginx-quic
comparison src/event/ngx_event_quic.c @ 8164:eed49b83e18f quic
QUIC: revised value separators in debug and error messages.
All values are prefixed with name and separated from it using colon.
Multiple values are listed without commas in between.
Rationale: this greatly simplifies log parsing for analysis.
author | Vladimir Homutov <vl@nginx.com> |
---|---|
date | Tue, 27 Oct 2020 14:12:31 +0300 |
parents | b3d9e57d0f62 |
children | c53761445a66 |
comparison
equal
deleted
inserted
replaced
8163:b3d9e57d0f62 | 8164:eed49b83e18f |
---|---|
697 SSL_get_peer_quic_transport_params(ssl_conn, &client_params, | 697 SSL_get_peer_quic_transport_params(ssl_conn, &client_params, |
698 &client_params_len); | 698 &client_params_len); |
699 | 699 |
700 ngx_log_debug1(NGX_LOG_DEBUG_EVENT, c->log, 0, | 700 ngx_log_debug1(NGX_LOG_DEBUG_EVENT, c->log, 0, |
701 "quic SSL_get_peer_quic_transport_params():" | 701 "quic SSL_get_peer_quic_transport_params():" |
702 " params_len %ui", client_params_len); | 702 " params_len:%ui", client_params_len); |
703 | 703 |
704 if (client_params_len == 0) { | 704 if (client_params_len == 0) { |
705 /* quic-tls 8.2 */ | 705 /* quic-tls 8.2 */ |
706 qc->error = NGX_QUIC_ERR_CRYPTO(SSL_AD_MISSING_EXTENSION); | 706 qc->error = NGX_QUIC_ERR_CRYPTO(SSL_AD_MISSING_EXTENSION); |
707 qc->error_reason = "missing transport parameters"; | 707 qc->error_reason = "missing transport parameters"; |
826 ngx_quic_connection_t *qc; | 826 ngx_quic_connection_t *qc; |
827 | 827 |
828 c = ngx_ssl_get_connection((ngx_ssl_conn_t *) ssl_conn); | 828 c = ngx_ssl_get_connection((ngx_ssl_conn_t *) ssl_conn); |
829 | 829 |
830 ngx_log_debug2(NGX_LOG_DEBUG_EVENT, c->log, 0, | 830 ngx_log_debug2(NGX_LOG_DEBUG_EVENT, c->log, 0, |
831 "quic ngx_quic_send_alert(), lvl=%d, alert=%d", | 831 "quic ngx_quic_send_alert() lvl:%d alert:%d", |
832 (int) level, (int) alert); | 832 (int) level, (int) alert); |
833 | 833 |
834 qc = c->quic; | 834 qc = c->quic; |
835 if (qc == NULL) { | 835 if (qc == NULL) { |
836 return 1; | 836 return 1; |
1580 ngx_quic_close_connection(ngx_connection_t *c, ngx_int_t rc) | 1580 ngx_quic_close_connection(ngx_connection_t *c, ngx_int_t rc) |
1581 { | 1581 { |
1582 ngx_pool_t *pool; | 1582 ngx_pool_t *pool; |
1583 | 1583 |
1584 ngx_log_debug1(NGX_LOG_DEBUG_EVENT, c->log, 0, | 1584 ngx_log_debug1(NGX_LOG_DEBUG_EVENT, c->log, 0, |
1585 "quic ngx_quic_close_connection, rc: %i", rc); | 1585 "quic ngx_quic_close_connection rc:%i", rc); |
1586 | 1586 |
1587 if (!c->quic) { | 1587 if (!c->quic) { |
1588 ngx_log_debug0(NGX_LOG_DEBUG_EVENT, c->log, 0, | 1588 ngx_log_debug0(NGX_LOG_DEBUG_EVENT, c->log, 0, |
1589 "quic close connection early error"); | 1589 "quic close connection early error"); |
1590 | 1590 |
1656 qc->error_level = c->ssl ? SSL_quic_read_level(c->ssl->connection) | 1656 qc->error_level = c->ssl ? SSL_quic_read_level(c->ssl->connection) |
1657 : ssl_encryption_initial; | 1657 : ssl_encryption_initial; |
1658 | 1658 |
1659 if (rc == NGX_OK) { | 1659 if (rc == NGX_OK) { |
1660 ngx_log_debug1(NGX_LOG_DEBUG_EVENT, c->log, 0, | 1660 ngx_log_debug1(NGX_LOG_DEBUG_EVENT, c->log, 0, |
1661 "quic immediate close, drain = %d", | 1661 "quic immediate close drain:%d", |
1662 qc->draining); | 1662 qc->draining); |
1663 | 1663 |
1664 qc->close.log = c->log; | 1664 qc->close.log = c->log; |
1665 qc->close.data = c; | 1665 qc->close.data = c; |
1666 qc->close.handler = ngx_quic_close_timer_handler; | 1666 qc->close.handler = ngx_quic_close_timer_handler; |
1676 if (qc->error == 0 && !qc->error_app) { | 1676 if (qc->error == 0 && !qc->error_app) { |
1677 qc->error = NGX_QUIC_ERR_INTERNAL_ERROR; | 1677 qc->error = NGX_QUIC_ERR_INTERNAL_ERROR; |
1678 } | 1678 } |
1679 | 1679 |
1680 ngx_log_debug3(NGX_LOG_DEBUG_EVENT, c->log, 0, | 1680 ngx_log_debug3(NGX_LOG_DEBUG_EVENT, c->log, 0, |
1681 "quic immediate close due to %serror: %ui %s", | 1681 "quic immediate close due to %s error: %ui %s", |
1682 qc->error_app ? "app " : "", qc->error, | 1682 qc->error_app ? "app " : "", qc->error, |
1683 qc->error_reason ? qc->error_reason : ""); | 1683 qc->error_reason ? qc->error_reason : ""); |
1684 } | 1684 } |
1685 | 1685 |
1686 (void) ngx_quic_send_cc(c); | 1686 (void) ngx_quic_send_cc(c); |
2017 | 2017 |
2018 if (pkt->dcid.len < NGX_QUIC_CID_LEN_MIN) { | 2018 if (pkt->dcid.len < NGX_QUIC_CID_LEN_MIN) { |
2019 /* 7.2. Negotiating Connection IDs */ | 2019 /* 7.2. Negotiating Connection IDs */ |
2020 ngx_log_error(NGX_LOG_INFO, c->log, 0, | 2020 ngx_log_error(NGX_LOG_INFO, c->log, 0, |
2021 "quic too short dcid in initial" | 2021 "quic too short dcid in initial" |
2022 " packet: length %i", pkt->dcid.len); | 2022 " packet: len:%i", pkt->dcid.len); |
2023 return NGX_ERROR; | 2023 return NGX_ERROR; |
2024 } | 2024 } |
2025 | 2025 |
2026 qc = ngx_quic_new_connection(c, conf, pkt); | 2026 qc = ngx_quic_new_connection(c, conf, pkt); |
2027 if (qc == NULL) { | 2027 if (qc == NULL) { |
2463 } | 2463 } |
2464 } | 2464 } |
2465 | 2465 |
2466 if (p != end) { | 2466 if (p != end) { |
2467 ngx_log_error(NGX_LOG_INFO, c->log, 0, | 2467 ngx_log_error(NGX_LOG_INFO, c->log, 0, |
2468 "quic trailing garbage in payload: %ui bytes", end - p); | 2468 "quic trailing garbage in payload:%ui bytes", end - p); |
2469 | 2469 |
2470 qc->error = NGX_QUIC_ERR_FRAME_ENCODING_ERROR; | 2470 qc->error = NGX_QUIC_ERR_FRAME_ENCODING_ERROR; |
2471 return NGX_ERROR; | 2471 return NGX_ERROR; |
2472 } | 2472 } |
2473 | 2473 |
2496 c->log->action = "preparing ack"; | 2496 c->log->action = "preparing ack"; |
2497 | 2497 |
2498 ctx = ngx_quic_get_send_ctx(c->quic, pkt->level); | 2498 ctx = ngx_quic_get_send_ctx(c->quic, pkt->level); |
2499 | 2499 |
2500 ngx_log_debug4(NGX_LOG_DEBUG_EVENT, c->log, 0, | 2500 ngx_log_debug4(NGX_LOG_DEBUG_EVENT, c->log, 0, |
2501 "quic ngx_quic_ack_packet pn %uL largest %uL" | 2501 "quic ngx_quic_ack_packet pn:%uL largest %uL fr:%uL" |
2502 " first %uL nranges %ui", pkt->pn, ctx->largest_range, | 2502 " nranges:%ui", pkt->pn, ctx->largest_range, |
2503 ctx->first_range, ctx->nranges); | 2503 ctx->first_range, ctx->nranges); |
2504 | 2504 |
2505 prev_pending = ctx->pending_ack; | 2505 prev_pending = ctx->pending_ack; |
2506 | 2506 |
2507 if (pkt->need_ack) { | 2507 if (pkt->need_ack) { |
2748 uint64_t base; | 2748 uint64_t base; |
2749 ngx_uint_t i, smallest, largest; | 2749 ngx_uint_t i, smallest, largest; |
2750 ngx_quic_ack_range_t *r; | 2750 ngx_quic_ack_range_t *r; |
2751 | 2751 |
2752 ngx_log_debug4(NGX_LOG_DEBUG_EVENT, c->log, 0, | 2752 ngx_log_debug4(NGX_LOG_DEBUG_EVENT, c->log, 0, |
2753 "quic ngx_quic_drop_ack_ranges pn %uL largest %uL" | 2753 "quic ngx_quic_drop_ack_ranges pn:%uL largest:%uL" |
2754 " first %uL nranges %ui", pn, ctx->largest_range, | 2754 " fr:%uL nranges:%ui", pn, ctx->largest_range, |
2755 ctx->first_range, ctx->nranges); | 2755 ctx->first_range, ctx->nranges); |
2756 | 2756 |
2757 base = ctx->largest_range; | 2757 base = ctx->largest_range; |
2758 | 2758 |
2759 if (base == NGX_QUIC_UNSET_PN) { | 2759 if (base == NGX_QUIC_UNSET_PN) { |
2934 qc = c->quic; | 2934 qc = c->quic; |
2935 | 2935 |
2936 ctx = ngx_quic_get_send_ctx(qc, pkt->level); | 2936 ctx = ngx_quic_get_send_ctx(qc, pkt->level); |
2937 | 2937 |
2938 ngx_log_debug1(NGX_LOG_DEBUG_EVENT, c->log, 0, | 2938 ngx_log_debug1(NGX_LOG_DEBUG_EVENT, c->log, 0, |
2939 "quic ngx_quic_handle_ack_frame level %d", pkt->level); | 2939 "quic ngx_quic_handle_ack_frame level:%d", pkt->level); |
2940 | 2940 |
2941 /* | 2941 /* |
2942 * If any computed packet number is negative, an endpoint MUST | 2942 * If any computed packet number is negative, an endpoint MUST |
2943 * generate a connection error of type FRAME_ENCODING_ERROR. | 2943 * generate a connection error of type FRAME_ENCODING_ERROR. |
2944 * (19.3.1) | 2944 * (19.3.1) |
2962 | 2962 |
2963 /* 13.2.3. Receiver Tracking of ACK Frames */ | 2963 /* 13.2.3. Receiver Tracking of ACK Frames */ |
2964 if (ctx->largest_ack < max || ctx->largest_ack == NGX_QUIC_UNSET_PN) { | 2964 if (ctx->largest_ack < max || ctx->largest_ack == NGX_QUIC_UNSET_PN) { |
2965 ctx->largest_ack = max; | 2965 ctx->largest_ack = max; |
2966 ngx_log_debug1(NGX_LOG_DEBUG_EVENT, c->log, 0, | 2966 ngx_log_debug1(NGX_LOG_DEBUG_EVENT, c->log, 0, |
2967 "quic updated largest received ack: %uL", max); | 2967 "quic updated largest received ack:%uL", max); |
2968 | 2968 |
2969 /* | 2969 /* |
2970 * An endpoint generates an RTT sample on receiving an | 2970 * An endpoint generates an RTT sample on receiving an |
2971 * ACK frame that meets the following two conditions: | 2971 * ACK frame that meets the following two conditions: |
2972 * | 2972 * |
2991 pos += n; | 2991 pos += n; |
2992 | 2992 |
2993 if (gap + 2 > min) { | 2993 if (gap + 2 > min) { |
2994 qc->error = NGX_QUIC_ERR_FRAME_ENCODING_ERROR; | 2994 qc->error = NGX_QUIC_ERR_FRAME_ENCODING_ERROR; |
2995 ngx_log_error(NGX_LOG_INFO, c->log, 0, | 2995 ngx_log_error(NGX_LOG_INFO, c->log, 0, |
2996 "quic invalid range %ui in ack frame", i); | 2996 "quic invalid range:%ui in ack frame", i); |
2997 return NGX_ERROR; | 2997 return NGX_ERROR; |
2998 } | 2998 } |
2999 | 2999 |
3000 max = min - gap - 2; | 3000 max = min - gap - 2; |
3001 | 3001 |
3002 if (range > max) { | 3002 if (range > max) { |
3003 qc->error = NGX_QUIC_ERR_FRAME_ENCODING_ERROR; | 3003 qc->error = NGX_QUIC_ERR_FRAME_ENCODING_ERROR; |
3004 ngx_log_error(NGX_LOG_INFO, c->log, 0, | 3004 ngx_log_error(NGX_LOG_INFO, c->log, 0, |
3005 "quic invalid range %ui in ack frame", i); | 3005 "quic invalid range:%ui in ack frame", i); |
3006 return NGX_ERROR; | 3006 return NGX_ERROR; |
3007 } | 3007 } |
3008 | 3008 |
3009 min = max - range; | 3009 min = max - range; |
3010 | 3010 |
3028 ngx_queue_t *q; | 3028 ngx_queue_t *q; |
3029 ngx_quic_frame_t *f; | 3029 ngx_quic_frame_t *f; |
3030 ngx_quic_connection_t *qc; | 3030 ngx_quic_connection_t *qc; |
3031 | 3031 |
3032 ngx_log_debug2(NGX_LOG_DEBUG_EVENT, c->log, 0, | 3032 ngx_log_debug2(NGX_LOG_DEBUG_EVENT, c->log, 0, |
3033 "quic handle ack range: min:%uL max:%uL", min, max); | 3033 "quic handle ack range min:%uL max:%uL", min, max); |
3034 | 3034 |
3035 qc = c->quic; | 3035 qc = c->quic; |
3036 | 3036 |
3037 *send_time = NGX_TIMER_INFINITE; | 3037 *send_time = NGX_TIMER_INFINITE; |
3038 found = 0; | 3038 found = 0; |
3143 rttvar_sample = ngx_abs((ngx_msec_int_t) (qc->avg_rtt - adjusted_rtt)); | 3143 rttvar_sample = ngx_abs((ngx_msec_int_t) (qc->avg_rtt - adjusted_rtt)); |
3144 qc->rttvar = 0.75 * qc->rttvar + 0.25 * rttvar_sample; | 3144 qc->rttvar = 0.75 * qc->rttvar + 0.25 * rttvar_sample; |
3145 } | 3145 } |
3146 | 3146 |
3147 ngx_log_debug4(NGX_LOG_DEBUG_EVENT, c->log, 0, | 3147 ngx_log_debug4(NGX_LOG_DEBUG_EVENT, c->log, 0, |
3148 "quic rtt sample: latest %M, min %M, avg %M, var %M", | 3148 "quic rtt sample latest:%M min:%M avg:%M var:%M", |
3149 latest_rtt, qc->min_rtt, qc->avg_rtt, qc->rttvar); | 3149 latest_rtt, qc->min_rtt, qc->avg_rtt, qc->rttvar); |
3150 } | 3150 } |
3151 | 3151 |
3152 | 3152 |
3153 static ngx_inline ngx_msec_t | 3153 static ngx_inline ngx_msec_t |
3203 } | 3203 } |
3204 | 3204 |
3205 sn->acked += f->u.stream.length; | 3205 sn->acked += f->u.stream.length; |
3206 | 3206 |
3207 ngx_log_debug3(NGX_LOG_DEBUG_EVENT, sn->c->log, 0, | 3207 ngx_log_debug3(NGX_LOG_DEBUG_EVENT, sn->c->log, 0, |
3208 "quic stream ack %uL acked:%uL, unacked:%uL", | 3208 "quic stream ack len:%uL acked:%uL unacked:%uL", |
3209 f->u.stream.length, sn->acked, sent - sn->acked); | 3209 f->u.stream.length, sn->acked, sent - sn->acked); |
3210 } | 3210 } |
3211 | 3211 |
3212 | 3212 |
3213 static ngx_int_t | 3213 static ngx_int_t |
3221 | 3221 |
3222 f = &frame->u.ord; | 3222 f = &frame->u.ord; |
3223 | 3223 |
3224 if (f->offset > fs->received) { | 3224 if (f->offset > fs->received) { |
3225 ngx_log_debug2(NGX_LOG_DEBUG_EVENT, c->log, 0, | 3225 ngx_log_debug2(NGX_LOG_DEBUG_EVENT, c->log, 0, |
3226 "quic out-of-order frame: expecting %uL got %uL", | 3226 "quic out-of-order frame: expecting:%uL got:%uL", |
3227 fs->received, f->offset); | 3227 fs->received, f->offset); |
3228 | 3228 |
3229 return ngx_quic_buffer_frame(c, fs, frame); | 3229 return ngx_quic_buffer_frame(c, fs, frame); |
3230 } | 3230 } |
3231 | 3231 |
3282 /* old/duplicate data range */ | 3282 /* old/duplicate data range */ |
3283 ngx_queue_remove(q); | 3283 ngx_queue_remove(q); |
3284 fs->total -= f->length; | 3284 fs->total -= f->length; |
3285 | 3285 |
3286 ngx_log_debug1(NGX_LOG_DEBUG_EVENT, c->log, 0, | 3286 ngx_log_debug1(NGX_LOG_DEBUG_EVENT, c->log, 0, |
3287 "quic skipped buffered frame, total %ui", | 3287 "quic skipped buffered frame, total:%ui", |
3288 fs->total); | 3288 fs->total); |
3289 ngx_quic_free_frame(c, frame); | 3289 ngx_quic_free_frame(c, frame); |
3290 continue; | 3290 continue; |
3291 } | 3291 } |
3292 | 3292 |
3309 fs->total -= full_len; | 3309 fs->total -= full_len; |
3310 | 3310 |
3311 ngx_queue_remove(q); | 3311 ngx_queue_remove(q); |
3312 | 3312 |
3313 ngx_log_debug1(NGX_LOG_DEBUG_EVENT, c->log, 0, | 3313 ngx_log_debug1(NGX_LOG_DEBUG_EVENT, c->log, 0, |
3314 "quic consumed buffered frame, total %ui", fs->total); | 3314 "quic consumed buffered frame, total:%ui", fs->total); |
3315 | 3315 |
3316 ngx_quic_free_frame(c, frame); | 3316 ngx_quic_free_frame(c, frame); |
3317 | 3317 |
3318 } while (1); | 3318 } while (1); |
3319 | 3319 |
3385 | 3385 |
3386 fs->total += f->length; | 3386 fs->total += f->length; |
3387 | 3387 |
3388 ngx_log_debug1(NGX_LOG_DEBUG_EVENT, c->log, 0, | 3388 ngx_log_debug1(NGX_LOG_DEBUG_EVENT, c->log, 0, |
3389 "quic ordered frame with unexpected offset:" | 3389 "quic ordered frame with unexpected offset:" |
3390 " buffered, total %ui", fs->total); | 3390 " buffered total:%ui", fs->total); |
3391 | 3391 |
3392 if (ngx_queue_empty(&fs->frames)) { | 3392 if (ngx_queue_empty(&fs->frames)) { |
3393 ngx_queue_insert_after(&fs->frames, &dst->queue); | 3393 ngx_queue_insert_after(&fs->frames, &dst->queue); |
3394 return NGX_OK; | 3394 return NGX_OK; |
3395 } | 3395 } |
3466 f = &frame->u.crypto; | 3466 f = &frame->u.crypto; |
3467 | 3467 |
3468 ssl_conn = c->ssl->connection; | 3468 ssl_conn = c->ssl->connection; |
3469 | 3469 |
3470 ngx_log_debug2(NGX_LOG_DEBUG_EVENT, c->log, 0, | 3470 ngx_log_debug2(NGX_LOG_DEBUG_EVENT, c->log, 0, |
3471 "quic SSL_quic_read_level: %d, SSL_quic_write_level: %d", | 3471 "quic SSL_quic_read_level:%d SSL_quic_write_level:%d", |
3472 (int) SSL_quic_read_level(ssl_conn), | 3472 (int) SSL_quic_read_level(ssl_conn), |
3473 (int) SSL_quic_write_level(ssl_conn)); | 3473 (int) SSL_quic_write_level(ssl_conn)); |
3474 | 3474 |
3475 if (!SSL_provide_quic_data(ssl_conn, SSL_quic_read_level(ssl_conn), | 3475 if (!SSL_provide_quic_data(ssl_conn, SSL_quic_read_level(ssl_conn), |
3476 f->data, f->length)) | 3476 f->data, f->length)) |
3496 } | 3496 } |
3497 | 3497 |
3498 } else if (n == 1 && !SSL_in_init(ssl_conn)) { | 3498 } else if (n == 1 && !SSL_in_init(ssl_conn)) { |
3499 | 3499 |
3500 ngx_log_debug1(NGX_LOG_DEBUG_EVENT, c->log, 0, | 3500 ngx_log_debug1(NGX_LOG_DEBUG_EVENT, c->log, 0, |
3501 "quic ssl cipher: %s", SSL_get_cipher(ssl_conn)); | 3501 "quic ssl cipher:%s", SSL_get_cipher(ssl_conn)); |
3502 | 3502 |
3503 ngx_log_debug0(NGX_LOG_DEBUG_EVENT, c->log, 0, | 3503 ngx_log_debug0(NGX_LOG_DEBUG_EVENT, c->log, 0, |
3504 "quic handshake completed successfully"); | 3504 "quic handshake completed successfully"); |
3505 | 3505 |
3506 c->ssl->handshaked = 1; | 3506 c->ssl->handshaked = 1; |
3538 */ | 3538 */ |
3539 ngx_quic_discard_ctx(c, ssl_encryption_handshake); | 3539 ngx_quic_discard_ctx(c, ssl_encryption_handshake); |
3540 } | 3540 } |
3541 | 3541 |
3542 ngx_log_debug2(NGX_LOG_DEBUG_EVENT, c->log, 0, | 3542 ngx_log_debug2(NGX_LOG_DEBUG_EVENT, c->log, 0, |
3543 "quic SSL_quic_read_level: %d, SSL_quic_write_level: %d", | 3543 "quic SSL_quic_read_level:%d SSL_quic_write_level:%d", |
3544 (int) SSL_quic_read_level(ssl_conn), | 3544 (int) SSL_quic_read_level(ssl_conn), |
3545 (int) SSL_quic_write_level(ssl_conn)); | 3545 (int) SSL_quic_write_level(ssl_conn)); |
3546 | 3546 |
3547 return NGX_OK; | 3547 return NGX_OK; |
3548 } | 3548 } |
4328 */ | 4328 */ |
4329 | 4329 |
4330 if (((c->sent + hlen + len + f->len) / 3) > qc->received) { | 4330 if (((c->sent + hlen + len + f->len) / 3) > qc->received) { |
4331 ngx_log_debug2(NGX_LOG_DEBUG_EVENT, c->log, 0, | 4331 ngx_log_debug2(NGX_LOG_DEBUG_EVENT, c->log, 0, |
4332 "quic hit amplification limit" | 4332 "quic hit amplification limit" |
4333 " received %uz sent %O", | 4333 " received:%uz sent:%O", |
4334 qc->received, c->sent); | 4334 qc->received, c->sent); |
4335 break; | 4335 break; |
4336 } | 4336 } |
4337 } | 4337 } |
4338 | 4338 |
4486 pkt.payload = out; | 4486 pkt.payload = out; |
4487 | 4487 |
4488 res.data = dst; | 4488 res.data = dst; |
4489 | 4489 |
4490 ngx_log_debug6(NGX_LOG_DEBUG_EVENT, c->log, 0, | 4490 ngx_log_debug6(NGX_LOG_DEBUG_EVENT, c->log, 0, |
4491 "quic packet ready: %ui bytes at level %d" | 4491 "quic packet ready bytes:%ui level:%d" |
4492 " need_ack: %d number: %L encoded %d:0x%xD", | 4492 " need_ack:%d number:%L encoded nl:%d trunc:0x%xD", |
4493 out.len, start->level, pkt.need_ack, pkt.number, | 4493 out.len, start->level, pkt.need_ack, pkt.number, |
4494 pkt.num_len, pkt.trunc); | 4494 pkt.num_len, pkt.trunc); |
4495 | 4495 |
4496 if (ngx_quic_encrypt(&pkt, ssl_conn, &res) != NGX_OK) { | 4496 if (ngx_quic_encrypt(&pkt, ssl_conn, &res) != NGX_OK) { |
4497 ngx_quic_free_frames(c, frames); | 4497 ngx_quic_free_frames(c, frames); |
4769 if (bidi) { | 4769 if (bidi) { |
4770 if (qc->streams.server_streams_bidi | 4770 if (qc->streams.server_streams_bidi |
4771 >= qc->streams.server_max_streams_bidi) | 4771 >= qc->streams.server_max_streams_bidi) |
4772 { | 4772 { |
4773 ngx_log_debug1(NGX_LOG_DEBUG_EVENT, c->log, 0, | 4773 ngx_log_debug1(NGX_LOG_DEBUG_EVENT, c->log, 0, |
4774 "quic too many server bidi streams: %uL", | 4774 "quic too many server bidi streams:%uL", |
4775 qc->streams.server_streams_bidi); | 4775 qc->streams.server_streams_bidi); |
4776 return NULL; | 4776 return NULL; |
4777 } | 4777 } |
4778 | 4778 |
4779 id = (qc->streams.server_streams_bidi << 2) | 4779 id = (qc->streams.server_streams_bidi << 2) |
4780 | NGX_QUIC_STREAM_SERVER_INITIATED; | 4780 | NGX_QUIC_STREAM_SERVER_INITIATED; |
4781 | 4781 |
4782 ngx_log_debug3(NGX_LOG_DEBUG_EVENT, c->log, 0, | 4782 ngx_log_debug3(NGX_LOG_DEBUG_EVENT, c->log, 0, |
4783 "quic creating server bidi stream %uL/%uL id:0x%xL", | 4783 "quic creating server bidi stream" |
4784 " streams:%uL max:%uL id:0x%xL", | |
4784 qc->streams.server_streams_bidi, | 4785 qc->streams.server_streams_bidi, |
4785 qc->streams.server_max_streams_bidi, id); | 4786 qc->streams.server_max_streams_bidi, id); |
4786 | 4787 |
4787 qc->streams.server_streams_bidi++; | 4788 qc->streams.server_streams_bidi++; |
4788 rcvbuf_size = qc->tp.initial_max_stream_data_bidi_local; | 4789 rcvbuf_size = qc->tp.initial_max_stream_data_bidi_local; |
4790 } else { | 4791 } else { |
4791 if (qc->streams.server_streams_uni | 4792 if (qc->streams.server_streams_uni |
4792 >= qc->streams.server_max_streams_uni) | 4793 >= qc->streams.server_max_streams_uni) |
4793 { | 4794 { |
4794 ngx_log_debug1(NGX_LOG_DEBUG_EVENT, c->log, 0, | 4795 ngx_log_debug1(NGX_LOG_DEBUG_EVENT, c->log, 0, |
4795 "quic too many server uni streams: %uL", | 4796 "quic too many server uni streams:%uL", |
4796 qc->streams.server_streams_uni); | 4797 qc->streams.server_streams_uni); |
4797 return NULL; | 4798 return NULL; |
4798 } | 4799 } |
4799 | 4800 |
4800 id = (qc->streams.server_streams_uni << 2) | 4801 id = (qc->streams.server_streams_uni << 2) |
4801 | NGX_QUIC_STREAM_SERVER_INITIATED | 4802 | NGX_QUIC_STREAM_SERVER_INITIATED |
4802 | NGX_QUIC_STREAM_UNIDIRECTIONAL; | 4803 | NGX_QUIC_STREAM_UNIDIRECTIONAL; |
4803 | 4804 |
4804 ngx_log_debug3(NGX_LOG_DEBUG_EVENT, c->log, 0, | 4805 ngx_log_debug3(NGX_LOG_DEBUG_EVENT, c->log, 0, |
4805 "quic creating server uni stream %uL/%uL id:0x%xL", | 4806 "quic creating server uni stream" |
4807 " streams:%uL max:%uL id:0x%xL", | |
4806 qc->streams.server_streams_uni, | 4808 qc->streams.server_streams_uni, |
4807 qc->streams.server_max_streams_uni, id); | 4809 qc->streams.server_max_streams_uni, id); |
4808 | 4810 |
4809 qc->streams.server_streams_uni++; | 4811 qc->streams.server_streams_uni++; |
4810 rcvbuf_size = 0; | 4812 rcvbuf_size = 0; |
4877 uint64_t min_id; | 4879 uint64_t min_id; |
4878 ngx_quic_stream_t *sn; | 4880 ngx_quic_stream_t *sn; |
4879 ngx_quic_connection_t *qc; | 4881 ngx_quic_connection_t *qc; |
4880 | 4882 |
4881 ngx_log_debug1(NGX_LOG_DEBUG_EVENT, c->log, 0, | 4883 ngx_log_debug1(NGX_LOG_DEBUG_EVENT, c->log, 0, |
4882 "quic stream id 0x%xL is new", id); | 4884 "quic stream id:0x%xL is new", id); |
4883 | 4885 |
4884 qc = c->quic; | 4886 qc = c->quic; |
4885 | 4887 |
4886 if (id & NGX_QUIC_STREAM_UNIDIRECTIONAL) { | 4888 if (id & NGX_QUIC_STREAM_UNIDIRECTIONAL) { |
4887 | 4889 |
4968 ngx_quic_stream_t *sn; | 4970 ngx_quic_stream_t *sn; |
4969 ngx_pool_cleanup_t *cln; | 4971 ngx_pool_cleanup_t *cln; |
4970 ngx_quic_connection_t *qc; | 4972 ngx_quic_connection_t *qc; |
4971 | 4973 |
4972 ngx_log_debug1(NGX_LOG_DEBUG_EVENT, c->log, 0, | 4974 ngx_log_debug1(NGX_LOG_DEBUG_EVENT, c->log, 0, |
4973 "quic stream id 0x%xL create", id); | 4975 "quic stream id:0x%xL create", id); |
4974 | 4976 |
4975 qc = c->quic; | 4977 qc = c->quic; |
4976 | 4978 |
4977 pool = ngx_create_pool(NGX_DEFAULT_POOL_SIZE, c->log); | 4979 pool = ngx_create_pool(NGX_DEFAULT_POOL_SIZE, c->log); |
4978 if (pool == NULL) { | 4980 if (pool == NULL) { |
5087 if (rev->error) { | 5089 if (rev->error) { |
5088 return NGX_ERROR; | 5090 return NGX_ERROR; |
5089 } | 5091 } |
5090 | 5092 |
5091 ngx_log_debug3(NGX_LOG_DEBUG_EVENT, c->log, 0, | 5093 ngx_log_debug3(NGX_LOG_DEBUG_EVENT, c->log, 0, |
5092 "quic stream id 0x%xL recv: eof:%d, avail:%z", | 5094 "quic stream recv id:0x%xL eof:%d avail:%z", |
5093 qs->id, rev->pending_eof, b->last - b->pos); | 5095 qs->id, rev->pending_eof, b->last - b->pos); |
5094 | 5096 |
5095 if (b->pos == b->last) { | 5097 if (b->pos == b->last) { |
5096 rev->ready = 0; | 5098 rev->ready = 0; |
5097 | 5099 |
5099 rev->eof = 1; | 5101 rev->eof = 1; |
5100 return 0; | 5102 return 0; |
5101 } | 5103 } |
5102 | 5104 |
5103 ngx_log_debug1(NGX_LOG_DEBUG_EVENT, c->log, 0, | 5105 ngx_log_debug1(NGX_LOG_DEBUG_EVENT, c->log, 0, |
5104 "quic stream id 0x%xL recv() not ready", qs->id); | 5106 "quic stream id:0x%xL recv() not ready", qs->id); |
5105 return NGX_AGAIN; | 5107 return NGX_AGAIN; |
5106 } | 5108 } |
5107 | 5109 |
5108 len = ngx_min(b->last - b->pos, (ssize_t) size); | 5110 len = ngx_min(b->last - b->pos, (ssize_t) size); |
5109 | 5111 |
5117 b->last = b->start; | 5119 b->last = b->start; |
5118 rev->ready = rev->pending_eof; | 5120 rev->ready = rev->pending_eof; |
5119 } | 5121 } |
5120 | 5122 |
5121 ngx_log_debug3(NGX_LOG_DEBUG_EVENT, c->log, 0, | 5123 ngx_log_debug3(NGX_LOG_DEBUG_EVENT, c->log, 0, |
5122 "quic stream id 0x%xL recv: %z of %uz", qs->id, len, size); | 5124 "quic stream id:0x%xL recv len:%z of size:%uz", |
5125 qs->id, len, size); | |
5123 | 5126 |
5124 if (!rev->pending_eof) { | 5127 if (!rev->pending_eof) { |
5125 frame = ngx_quic_alloc_frame(pc, 0); | 5128 frame = ngx_quic_alloc_frame(pc, 0); |
5126 if (frame == NULL) { | 5129 if (frame == NULL) { |
5127 return NGX_ERROR; | 5130 return NGX_ERROR; |
5151 frame->u.max_data.max_data = qc->streams.recv_max_data; | 5154 frame->u.max_data.max_data = qc->streams.recv_max_data; |
5152 | 5155 |
5153 ngx_quic_queue_frame(pc->quic, frame); | 5156 ngx_quic_queue_frame(pc->quic, frame); |
5154 | 5157 |
5155 ngx_log_debug2(NGX_LOG_DEBUG_EVENT, c->log, 0, | 5158 ngx_log_debug2(NGX_LOG_DEBUG_EVENT, c->log, 0, |
5156 "quic stream id 0x%xL recv: increased max data: %uL", | 5159 "quic stream id:0x%xL recv: increased max_data:%uL", |
5157 qs->id, qc->streams.recv_max_data); | 5160 qs->id, qc->streams.recv_max_data); |
5158 } | 5161 } |
5159 | 5162 |
5160 return len; | 5163 return len; |
5161 } | 5164 } |
5297 | 5300 |
5298 ngx_quic_queue_frame(qc, frame); | 5301 ngx_quic_queue_frame(qc, frame); |
5299 } | 5302 } |
5300 | 5303 |
5301 ngx_log_debug2(NGX_LOG_DEBUG_EVENT, c->log, 0, | 5304 ngx_log_debug2(NGX_LOG_DEBUG_EVENT, c->log, 0, |
5302 "quic send_chain sent:%uz, frames:%ui", sent, nframes); | 5305 "quic send_chain sent:%uz nframes:%ui", sent, nframes); |
5303 | 5306 |
5304 return in; | 5307 return in; |
5305 } | 5308 } |
5306 | 5309 |
5307 | 5310 |
5366 if (sent + size > qs->send_max_data) { | 5369 if (sent + size > qs->send_max_data) { |
5367 size = qs->send_max_data - sent; | 5370 size = qs->send_max_data - sent; |
5368 } | 5371 } |
5369 | 5372 |
5370 ngx_log_debug1(NGX_LOG_DEBUG_EVENT, c->log, 0, | 5373 ngx_log_debug1(NGX_LOG_DEBUG_EVENT, c->log, 0, |
5371 "quic send flow: %uz", size); | 5374 "quic send flow:%uz", size); |
5372 | 5375 |
5373 return size; | 5376 return size; |
5374 } | 5377 } |
5375 | 5378 |
5376 | 5379 |
5387 qs = c->qs; | 5390 qs = c->qs; |
5388 pc = qs->parent; | 5391 pc = qs->parent; |
5389 qc = pc->quic; | 5392 qc = pc->quic; |
5390 | 5393 |
5391 ngx_log_debug1(NGX_LOG_DEBUG_EVENT, c->log, 0, | 5394 ngx_log_debug1(NGX_LOG_DEBUG_EVENT, c->log, 0, |
5392 "quic stream id 0x%xL cleanup", qs->id); | 5395 "quic stream id:0x%xL cleanup", qs->id); |
5393 | 5396 |
5394 ngx_rbtree_delete(&qc->streams.tree, &qs->node); | 5397 ngx_rbtree_delete(&qc->streams.tree, &qs->node); |
5395 ngx_quic_free_frames(pc, &qs->fs.frames); | 5398 ngx_quic_free_frames(pc, &qs->fs.frames); |
5396 | 5399 |
5397 if (qc->closing) { | 5400 if (qc->closing) { |
5443 return; | 5446 return; |
5444 } | 5447 } |
5445 } | 5448 } |
5446 | 5449 |
5447 ngx_log_debug1(NGX_LOG_DEBUG_EVENT, c->log, 0, | 5450 ngx_log_debug1(NGX_LOG_DEBUG_EVENT, c->log, 0, |
5448 "quic stream id 0x%xL send fin", qs->id); | 5451 "quic stream id:0x%xL send fin", qs->id); |
5449 | 5452 |
5450 frame = ngx_quic_alloc_frame(pc, 0); | 5453 frame = ngx_quic_alloc_frame(pc, 0); |
5451 if (frame == NULL) { | 5454 if (frame == NULL) { |
5452 return; | 5455 return; |
5453 } | 5456 } |
5545 | 5548 |
5546 timer = f->last - cg->recovery_start; | 5549 timer = f->last - cg->recovery_start; |
5547 | 5550 |
5548 if ((ngx_msec_int_t) timer <= 0) { | 5551 if ((ngx_msec_int_t) timer <= 0) { |
5549 ngx_log_debug3(NGX_LOG_DEBUG_EVENT, c->log, 0, | 5552 ngx_log_debug3(NGX_LOG_DEBUG_EVENT, c->log, 0, |
5550 "quic congestion ack recovery win:%uz, ss:%uz, if:%uz", | 5553 "quic congestion ack recovery win:%uz ss:%uz if:%uz", |
5551 cg->window, cg->ssthresh, cg->in_flight); | 5554 cg->window, cg->ssthresh, cg->in_flight); |
5552 | 5555 |
5553 return; | 5556 return; |
5554 } | 5557 } |
5555 | 5558 |
5556 if (cg->window < cg->ssthresh) { | 5559 if (cg->window < cg->ssthresh) { |
5557 cg->window += f->plen; | 5560 cg->window += f->plen; |
5558 | 5561 |
5559 ngx_log_debug3(NGX_LOG_DEBUG_EVENT, c->log, 0, | 5562 ngx_log_debug3(NGX_LOG_DEBUG_EVENT, c->log, 0, |
5560 "quic congestion slow start win:%uz, ss:%uz, if:%uz", | 5563 "quic congestion slow start win:%uz ss:%uz if:%uz", |
5561 cg->window, cg->ssthresh, cg->in_flight); | 5564 cg->window, cg->ssthresh, cg->in_flight); |
5562 | 5565 |
5563 } else { | 5566 } else { |
5564 cg->window += qc->tp.max_udp_payload_size * f->plen / cg->window; | 5567 cg->window += qc->tp.max_udp_payload_size * f->plen / cg->window; |
5565 | 5568 |
5566 ngx_log_debug3(NGX_LOG_DEBUG_EVENT, c->log, 0, | 5569 ngx_log_debug3(NGX_LOG_DEBUG_EVENT, c->log, 0, |
5567 "quic congestion avoidance win:%uz, ss:%uz, if:%uz", | 5570 "quic congestion avoidance win:%uz ss:%uz if:%uz", |
5568 cg->window, cg->ssthresh, cg->in_flight); | 5571 cg->window, cg->ssthresh, cg->in_flight); |
5569 } | 5572 } |
5570 | 5573 |
5571 /* prevent recovery_start from wrapping */ | 5574 /* prevent recovery_start from wrapping */ |
5572 | 5575 |
5596 | 5599 |
5597 timer = f->last - cg->recovery_start; | 5600 timer = f->last - cg->recovery_start; |
5598 | 5601 |
5599 if ((ngx_msec_int_t) timer <= 0) { | 5602 if ((ngx_msec_int_t) timer <= 0) { |
5600 ngx_log_debug3(NGX_LOG_DEBUG_EVENT, c->log, 0, | 5603 ngx_log_debug3(NGX_LOG_DEBUG_EVENT, c->log, 0, |
5601 "quic congestion lost recovery win:%uz, ss:%uz, if:%uz", | 5604 "quic congestion lost recovery win:%uz ss:%uz if:%uz", |
5602 cg->window, cg->ssthresh, cg->in_flight); | 5605 cg->window, cg->ssthresh, cg->in_flight); |
5603 | 5606 |
5604 return; | 5607 return; |
5605 } | 5608 } |
5606 | 5609 |
5612 } | 5615 } |
5613 | 5616 |
5614 cg->ssthresh = cg->window; | 5617 cg->ssthresh = cg->window; |
5615 | 5618 |
5616 ngx_log_debug3(NGX_LOG_DEBUG_EVENT, c->log, 0, | 5619 ngx_log_debug3(NGX_LOG_DEBUG_EVENT, c->log, 0, |
5617 "quic congestion lost win:%uz, ss:%uz, if:%uz", | 5620 "quic congestion lost win:%uz ss:%uz if:%uz", |
5618 cg->window, cg->ssthresh, cg->in_flight); | 5621 cg->window, cg->ssthresh, cg->in_flight); |
5619 } | 5622 } |
5620 | 5623 |
5621 | 5624 |
5622 static void | 5625 static void |