Mercurial > hg > nginx
comparison src/event/ngx_event_quic.c @ 8359:2f900ae486bc quic
Debug cleanup.
+ all dumps are moved under one of the following macros (undefined by default):
NGX_QUIC_DEBUG_PACKETS
NGX_QUIC_DEBUG_FRAMES
NGX_QUIC_DEBUG_FRAMES_ALLOC
NGX_QUIC_DEBUG_CRYPTO
+ all QUIC debug messages got "quic " prefix
+ all input frames are reported as "quic frame in FOO_FRAME bar:1 baz:2"
+ all outgoing frames re reported as "quic frame out foo bar baz"
+ all stream operations are prefixed with id, like: "quic stream id 0x33 recv"
+ all transport parameters are prefixed with "quic tp"
(hex dump is moved to caller, to avoid using ngx_cycle->log)
+ packet flags and some other debug messages are updated to
include packet type
author | Vladimir Homutov <vl@nginx.com> |
---|---|
date | Fri, 24 Apr 2020 10:11:47 +0300 |
parents | 42198f77ac85 |
children | f175006124d0 |
comparison
equal
deleted
inserted
replaced
8358:2a6e91a1691d | 8359:2f900ae486bc |
---|---|
249 ngx_connection_t *c; | 249 ngx_connection_t *c; |
250 ngx_quic_secrets_t *keys; | 250 ngx_quic_secrets_t *keys; |
251 | 251 |
252 c = ngx_ssl_get_connection((ngx_ssl_conn_t *) ssl_conn); | 252 c = ngx_ssl_get_connection((ngx_ssl_conn_t *) ssl_conn); |
253 | 253 |
254 #ifdef NGX_QUIC_DEBUG_CRYPTO | |
254 ngx_quic_hexdump(c->log, "level:%d read secret", | 255 ngx_quic_hexdump(c->log, "level:%d read secret", |
255 rsecret, secret_len, level); | 256 rsecret, secret_len, level); |
257 #endif | |
256 | 258 |
257 keys = &c->quic->keys[level]; | 259 keys = &c->quic->keys[level]; |
258 | 260 |
259 if (level == ssl_encryption_early_data) { | 261 if (level == ssl_encryption_early_data) { |
260 c->quic->state = NGX_QUIC_ST_EARLY_DATA; | 262 c->quic->state = NGX_QUIC_ST_EARLY_DATA; |
274 ngx_connection_t *c; | 276 ngx_connection_t *c; |
275 ngx_quic_secrets_t *keys; | 277 ngx_quic_secrets_t *keys; |
276 | 278 |
277 c = ngx_ssl_get_connection((ngx_ssl_conn_t *) ssl_conn); | 279 c = ngx_ssl_get_connection((ngx_ssl_conn_t *) ssl_conn); |
278 | 280 |
281 #ifdef NGX_QUIC_DEBUG_CRYPTO | |
279 ngx_quic_hexdump(c->log, "level:%d write secret", | 282 ngx_quic_hexdump(c->log, "level:%d write secret", |
280 wsecret, secret_len, level); | 283 wsecret, secret_len, level); |
284 #endif | |
281 | 285 |
282 keys = &c->quic->keys[level]; | 286 keys = &c->quic->keys[level]; |
283 | 287 |
284 return ngx_quic_set_encryption_secret(c->pool, ssl_conn, level, | 288 return ngx_quic_set_encryption_secret(c->pool, ssl_conn, level, |
285 wsecret, secret_len, | 289 wsecret, secret_len, |
297 ngx_connection_t *c; | 301 ngx_connection_t *c; |
298 ngx_quic_secrets_t *keys; | 302 ngx_quic_secrets_t *keys; |
299 | 303 |
300 c = ngx_ssl_get_connection((ngx_ssl_conn_t *) ssl_conn); | 304 c = ngx_ssl_get_connection((ngx_ssl_conn_t *) ssl_conn); |
301 | 305 |
306 #ifdef NGX_QUIC_DEBUG_CRYPTO | |
302 ngx_quic_hexdump(c->log, "level:%d read", rsecret, secret_len, level); | 307 ngx_quic_hexdump(c->log, "level:%d read", rsecret, secret_len, level); |
308 #endif | |
303 | 309 |
304 keys = &c->quic->keys[level]; | 310 keys = &c->quic->keys[level]; |
305 | 311 |
306 rc = ngx_quic_set_encryption_secret(c->pool, ssl_conn, level, | 312 rc = ngx_quic_set_encryption_secret(c->pool, ssl_conn, level, |
307 rsecret, secret_len, | 313 rsecret, secret_len, |
313 if (level == ssl_encryption_early_data) { | 319 if (level == ssl_encryption_early_data) { |
314 c->quic->state = NGX_QUIC_ST_EARLY_DATA; | 320 c->quic->state = NGX_QUIC_ST_EARLY_DATA; |
315 return 1; | 321 return 1; |
316 } | 322 } |
317 | 323 |
324 #ifdef NGX_QUIC_DEBUG_CRYPTO | |
318 ngx_quic_hexdump(c->log, "level:%d write", wsecret, secret_len, level); | 325 ngx_quic_hexdump(c->log, "level:%d write", wsecret, secret_len, level); |
326 #endif | |
319 | 327 |
320 return ngx_quic_set_encryption_secret(c->pool, ssl_conn, level, | 328 return ngx_quic_set_encryption_secret(c->pool, ssl_conn, level, |
321 wsecret, secret_len, | 329 wsecret, secret_len, |
322 &keys->server); | 330 &keys->server); |
323 } | 331 } |
339 | 347 |
340 c = ngx_ssl_get_connection((ngx_ssl_conn_t *) ssl_conn); | 348 c = ngx_ssl_get_connection((ngx_ssl_conn_t *) ssl_conn); |
341 qc = c->quic; | 349 qc = c->quic; |
342 | 350 |
343 ngx_log_debug0(NGX_LOG_DEBUG_EVENT, c->log, 0, | 351 ngx_log_debug0(NGX_LOG_DEBUG_EVENT, c->log, 0, |
344 "ngx_quic_add_handshake_data"); | 352 "quic ngx_quic_add_handshake_data"); |
345 | 353 |
346 /* XXX: obtain client parameters after the handshake? */ | 354 /* XXX: obtain client parameters after the handshake? */ |
347 if (!qc->client_tp_done) { | 355 if (!qc->client_tp_done) { |
348 | 356 |
349 SSL_get_peer_quic_transport_params(ssl_conn, &client_params, | 357 SSL_get_peer_quic_transport_params(ssl_conn, &client_params, |
350 &client_params_len); | 358 &client_params_len); |
351 | 359 |
352 ngx_log_debug1(NGX_LOG_DEBUG_EVENT, c->log, 0, | 360 ngx_log_debug1(NGX_LOG_DEBUG_EVENT, c->log, 0, |
353 "SSL_get_peer_quic_transport_params(): params_len %ui", | 361 "quic SSL_get_peer_quic_transport_params():" |
354 client_params_len); | 362 " params_len %ui", client_params_len); |
355 | 363 |
356 if (client_params_len != 0) { | 364 if (client_params_len != 0) { |
357 p = (u_char *) client_params; | 365 p = (u_char *) client_params; |
358 end = p + client_params_len; | 366 end = p + client_params_len; |
359 | 367 |
428 { | 436 { |
429 ngx_connection_t *c; | 437 ngx_connection_t *c; |
430 | 438 |
431 c = ngx_ssl_get_connection((ngx_ssl_conn_t *) ssl_conn); | 439 c = ngx_ssl_get_connection((ngx_ssl_conn_t *) ssl_conn); |
432 | 440 |
433 ngx_log_debug0(NGX_LOG_DEBUG_EVENT, c->log, 0, "ngx_quic_flush_flight()"); | 441 ngx_log_debug0(NGX_LOG_DEBUG_EVENT, c->log, 0, |
442 "quic ngx_quic_flush_flight()"); | |
434 | 443 |
435 return 1; | 444 return 1; |
436 } | 445 } |
437 | 446 |
438 | 447 |
443 ngx_connection_t *c; | 452 ngx_connection_t *c; |
444 | 453 |
445 c = ngx_ssl_get_connection((ngx_ssl_conn_t *) ssl_conn); | 454 c = ngx_ssl_get_connection((ngx_ssl_conn_t *) ssl_conn); |
446 | 455 |
447 ngx_log_debug2(NGX_LOG_DEBUG_EVENT, c->log, 0, | 456 ngx_log_debug2(NGX_LOG_DEBUG_EVENT, c->log, 0, |
448 "ngx_quic_send_alert(), lvl=%d, alert=%d", | 457 "quic ngx_quic_send_alert(), lvl=%d, alert=%d", |
449 (int) level, (int) alert); | 458 (int) level, (int) alert); |
450 | 459 |
451 if (c->quic == NULL) { | 460 if (c->quic == NULL) { |
452 return 1; | 461 return 1; |
453 } | 462 } |
664 len = ngx_quic_create_transport_params(p, p + len, &qc->tp); | 673 len = ngx_quic_create_transport_params(p, p + len, &qc->tp); |
665 if (len < 0) { | 674 if (len < 0) { |
666 return NGX_ERROR; | 675 return NGX_ERROR; |
667 } | 676 } |
668 | 677 |
678 #ifdef NGX_QUIC_DEBUG_PACKETS | |
679 ngx_quic_hexdump0(c->log, "quic transport parameters", p, len); | |
680 #endif | |
681 | |
669 if (SSL_set_quic_transport_params(ssl_conn, p, len) == 0) { | 682 if (SSL_set_quic_transport_params(ssl_conn, p, len) == 0) { |
670 ngx_log_error(NGX_LOG_INFO, c->log, 0, | 683 ngx_log_error(NGX_LOG_INFO, c->log, 0, |
671 "SSL_set_quic_transport_params() failed"); | 684 "SSL_set_quic_transport_params() failed"); |
672 return NGX_ERROR; | 685 return NGX_ERROR; |
673 } | 686 } |
675 qc->max_streams = qc->tp.initial_max_streams_bidi; | 688 qc->max_streams = qc->tp.initial_max_streams_bidi; |
676 qc->state = NGX_QUIC_ST_HANDSHAKE; | 689 qc->state = NGX_QUIC_ST_HANDSHAKE; |
677 | 690 |
678 n = SSL_do_handshake(ssl_conn); | 691 n = SSL_do_handshake(ssl_conn); |
679 | 692 |
680 ngx_log_debug1(NGX_LOG_DEBUG_EVENT, c->log, 0, "SSL_do_handshake: %d", n); | 693 ngx_log_debug1(NGX_LOG_DEBUG_EVENT, c->log, 0, |
694 "quic SSL_do_handshake: %d", n); | |
681 | 695 |
682 if (n == -1) { | 696 if (n == -1) { |
683 sslerr = SSL_get_error(ssl_conn, n); | 697 sslerr = SSL_get_error(ssl_conn, n); |
684 | 698 |
685 ngx_log_debug1(NGX_LOG_DEBUG_EVENT, c->log, 0, "SSL_get_error: %d", | 699 ngx_log_debug1(NGX_LOG_DEBUG_EVENT, c->log, 0, |
686 sslerr); | 700 "quic SSL_get_error: %d", sslerr); |
687 | 701 |
688 if (sslerr != SSL_ERROR_WANT_READ) { | 702 if (sslerr != SSL_ERROR_WANT_READ) { |
689 ngx_ssl_error(NGX_LOG_ERR, c->log, 0, "SSL_do_handshake() failed"); | 703 ngx_ssl_error(NGX_LOG_ERR, c->log, 0, "SSL_do_handshake() failed"); |
690 return NGX_ERROR; | 704 return NGX_ERROR; |
691 } | 705 } |
692 } | 706 } |
693 | 707 |
694 ngx_log_debug2(NGX_LOG_DEBUG_EVENT, c->log, 0, | 708 ngx_log_debug2(NGX_LOG_DEBUG_EVENT, c->log, 0, |
695 "SSL_quic_read_level: %d, SSL_quic_write_level: %d", | 709 "quic SSL_quic_read_level: %d, SSL_quic_write_level: %d", |
696 (int) SSL_quic_read_level(ssl_conn), | 710 (int) SSL_quic_read_level(ssl_conn), |
697 (int) SSL_quic_write_level(ssl_conn)); | 711 (int) SSL_quic_write_level(ssl_conn)); |
698 | 712 |
699 return NGX_OK; | 713 return NGX_OK; |
700 } | 714 } |
760 ngx_quic_close_connection(ngx_connection_t *c, ngx_int_t rc) | 774 ngx_quic_close_connection(ngx_connection_t *c, ngx_int_t rc) |
761 { | 775 { |
762 ngx_pool_t *pool; | 776 ngx_pool_t *pool; |
763 | 777 |
764 ngx_log_debug1(NGX_LOG_DEBUG_EVENT, c->log, 0, | 778 ngx_log_debug1(NGX_LOG_DEBUG_EVENT, c->log, 0, |
765 "close quic connection, rc: %i", rc); | 779 "quic ngx_quic_close_connection, rc: %i", rc); |
766 | 780 |
767 if (!c->quic) { | 781 if (!c->quic) { |
768 ngx_log_debug0(NGX_LOG_DEBUG_EVENT, c->log, 0, | 782 ngx_log_debug0(NGX_LOG_DEBUG_EVENT, c->log, 0, |
769 "close quic connection: early error"); | 783 "quic close connection early error"); |
770 | 784 |
771 } else if (ngx_quic_close_quic(c, rc) == NGX_AGAIN) { | 785 } else if (ngx_quic_close_quic(c, rc) == NGX_AGAIN) { |
772 return; | 786 return; |
773 } | 787 } |
774 | 788 |
904 static void | 918 static void |
905 ngx_quic_close_timer_handler(ngx_event_t *ev) | 919 ngx_quic_close_timer_handler(ngx_event_t *ev) |
906 { | 920 { |
907 ngx_connection_t *c; | 921 ngx_connection_t *c; |
908 | 922 |
909 ngx_log_debug0(NGX_LOG_DEBUG_EVENT, ev->log, 0, "close timer"); | 923 ngx_log_debug0(NGX_LOG_DEBUG_EVENT, ev->log, 0, "quic close timer"); |
910 | 924 |
911 c = ev->data; | 925 c = ev->data; |
912 ngx_quic_close_connection(c, NGX_DONE); | 926 ngx_quic_close_connection(c, NGX_DONE); |
913 } | 927 } |
914 | 928 |
1414 case NGX_QUIC_FT_PATH_RESPONSE: | 1428 case NGX_QUIC_FT_PATH_RESPONSE: |
1415 case NGX_QUIC_FT_MAX_STREAM_DATA: | 1429 case NGX_QUIC_FT_MAX_STREAM_DATA: |
1416 | 1430 |
1417 /* TODO: handle */ | 1431 /* TODO: handle */ |
1418 ngx_log_debug0(NGX_LOG_DEBUG_EVENT, c->log, 0, | 1432 ngx_log_debug0(NGX_LOG_DEBUG_EVENT, c->log, 0, |
1419 "frame handler not implemented"); | 1433 "quic frame handler not implemented"); |
1420 ack_this = 1; | 1434 ack_this = 1; |
1421 break; | 1435 break; |
1422 | 1436 |
1423 default: | 1437 default: |
1424 ngx_log_debug0(NGX_LOG_DEBUG_EVENT, c->log, 0, | 1438 ngx_log_debug0(NGX_LOG_DEBUG_EVENT, c->log, 0, |
1425 "missing frame handler"); | 1439 "quic missing frame handler"); |
1426 return NGX_ERROR; | 1440 return NGX_ERROR; |
1427 } | 1441 } |
1428 } | 1442 } |
1429 | 1443 |
1430 if (p != end) { | 1444 if (p != end) { |
1520 ngx_quic_send_ctx_t *ctx; | 1534 ngx_quic_send_ctx_t *ctx; |
1521 | 1535 |
1522 ctx = ngx_quic_get_send_ctx(c->quic, pkt->level); | 1536 ctx = ngx_quic_get_send_ctx(c->quic, pkt->level); |
1523 | 1537 |
1524 ngx_log_debug1(NGX_LOG_DEBUG_EVENT, c->log, 0, | 1538 ngx_log_debug1(NGX_LOG_DEBUG_EVENT, c->log, 0, |
1525 "ngx_quic_handle_ack_frame level %d", pkt->level); | 1539 "quic ngx_quic_handle_ack_frame level %d", pkt->level); |
1526 | 1540 |
1527 /* | 1541 /* |
1528 * TODO: If any computed packet number is negative, an endpoint MUST | 1542 * TODO: If any computed packet number is negative, an endpoint MUST |
1529 * generate a connection error of type FRAME_ENCODING_ERROR. | 1543 * generate a connection error of type FRAME_ENCODING_ERROR. |
1530 * (19.3.1) | 1544 * (19.3.1) |
1545 | 1559 |
1546 /* 13.2.3. Receiver Tracking of ACK Frames */ | 1560 /* 13.2.3. Receiver Tracking of ACK Frames */ |
1547 if (ctx->largest_ack < max) { | 1561 if (ctx->largest_ack < max) { |
1548 ctx->largest_ack = max; | 1562 ctx->largest_ack = max; |
1549 ngx_log_debug1(NGX_LOG_DEBUG_EVENT, c->log, 0, | 1563 ngx_log_debug1(NGX_LOG_DEBUG_EVENT, c->log, 0, |
1550 "updated largest received: %ui", max); | 1564 "quic updated largest received ack: %ui", max); |
1551 } | 1565 } |
1552 | 1566 |
1553 pos = ack->ranges_start; | 1567 pos = ack->ranges_start; |
1554 end = ack->ranges_end; | 1568 end = ack->ranges_end; |
1555 | 1569 |
1641 | 1655 |
1642 f = &frame->u.ord; | 1656 f = &frame->u.ord; |
1643 | 1657 |
1644 if (f->offset > fs->received) { | 1658 if (f->offset > fs->received) { |
1645 ngx_log_debug2(NGX_LOG_DEBUG_EVENT, c->log, 0, | 1659 ngx_log_debug2(NGX_LOG_DEBUG_EVENT, c->log, 0, |
1646 "out-of-order frame: expecting %ui got %ui", | 1660 "quic out-of-order frame: expecting %ui got %ui", |
1647 fs->received, f->offset); | 1661 fs->received, f->offset); |
1648 | 1662 |
1649 return ngx_quic_buffer_frame(c, fs, frame); | 1663 return ngx_quic_buffer_frame(c, fs, frame); |
1650 } | 1664 } |
1651 | 1665 |
1702 /* old/duplicate data range */ | 1716 /* old/duplicate data range */ |
1703 ngx_queue_remove(q); | 1717 ngx_queue_remove(q); |
1704 fs->total -= f->length; | 1718 fs->total -= f->length; |
1705 | 1719 |
1706 ngx_log_debug1(NGX_LOG_DEBUG_EVENT, c->log, 0, | 1720 ngx_log_debug1(NGX_LOG_DEBUG_EVENT, c->log, 0, |
1707 "skipped buffered frame, total %ui", fs->total); | 1721 "quic skipped buffered frame, total %ui", |
1722 fs->total); | |
1708 ngx_quic_free_frame(c, frame); | 1723 ngx_quic_free_frame(c, frame); |
1709 continue; | 1724 continue; |
1710 } | 1725 } |
1711 | 1726 |
1712 /* frame was adjusted, proceed to input */ | 1727 /* frame was adjusted, proceed to input */ |
1728 fs->total -= full_len; | 1743 fs->total -= full_len; |
1729 | 1744 |
1730 ngx_queue_remove(q); | 1745 ngx_queue_remove(q); |
1731 | 1746 |
1732 ngx_log_debug1(NGX_LOG_DEBUG_EVENT, c->log, 0, | 1747 ngx_log_debug1(NGX_LOG_DEBUG_EVENT, c->log, 0, |
1733 "consumed buffered frame, total %ui", fs->total); | 1748 "quic consumed buffered frame, total %ui", fs->total); |
1734 | 1749 |
1735 ngx_quic_free_frame(c, frame); | 1750 ngx_quic_free_frame(c, frame); |
1736 | 1751 |
1737 } while (1); | 1752 } while (1); |
1738 | 1753 |
1753 | 1768 |
1754 if (tail >= f->length) { | 1769 if (tail >= f->length) { |
1755 /* range preceeding already received data or duplicate, ignore */ | 1770 /* range preceeding already received data or duplicate, ignore */ |
1756 | 1771 |
1757 ngx_log_debug0(NGX_LOG_DEBUG_EVENT, c->log, 0, | 1772 ngx_log_debug0(NGX_LOG_DEBUG_EVENT, c->log, 0, |
1758 "old or duplicate data in ordered frame, ignored"); | 1773 "quic old or duplicate data in ordered frame, ignored"); |
1759 return NGX_DONE; | 1774 return NGX_DONE; |
1760 } | 1775 } |
1761 | 1776 |
1762 ngx_log_debug0(NGX_LOG_DEBUG_EVENT, c->log, 0, | 1777 ngx_log_debug0(NGX_LOG_DEBUG_EVENT, c->log, 0, |
1763 "adjusted ordered frame data start to expected offset"); | 1778 "quic adjusted ordered frame data start to expected offset"); |
1764 | 1779 |
1765 /* intersecting range: adjust data size */ | 1780 /* intersecting range: adjust data size */ |
1766 | 1781 |
1767 f->offset += tail; | 1782 f->offset += tail; |
1768 f->data += tail; | 1783 f->data += tail; |
1779 u_char *data; | 1794 u_char *data; |
1780 ngx_queue_t *q; | 1795 ngx_queue_t *q; |
1781 ngx_quic_frame_t *dst, *item; | 1796 ngx_quic_frame_t *dst, *item; |
1782 ngx_quic_ordered_frame_t *f, *df; | 1797 ngx_quic_ordered_frame_t *f, *df; |
1783 | 1798 |
1784 ngx_log_debug0(NGX_LOG_DEBUG_EVENT, c->log, 0, "ngx_quic_buffer_frame"); | 1799 ngx_log_debug0(NGX_LOG_DEBUG_EVENT, c->log, 0, |
1800 "quic ngx_quic_buffer_frame"); | |
1785 | 1801 |
1786 f = &frame->u.ord; | 1802 f = &frame->u.ord; |
1787 | 1803 |
1788 /* frame start offset is in the future, buffer it */ | 1804 /* frame start offset is in the future, buffer it */ |
1789 | 1805 |
1809 df->data = dst->data; | 1825 df->data = dst->data; |
1810 | 1826 |
1811 fs->total += f->length; | 1827 fs->total += f->length; |
1812 | 1828 |
1813 ngx_log_debug1(NGX_LOG_DEBUG_EVENT, c->log, 0, | 1829 ngx_log_debug1(NGX_LOG_DEBUG_EVENT, c->log, 0, |
1814 "ordered frame with unexpected offset: buffered, total %ui", | 1830 "quic ordered frame with unexpected offset:" |
1815 fs->total); | 1831 " buffered, total %ui", fs->total); |
1816 | 1832 |
1817 /* TODO: do we need some timeout for this queue ? */ | 1833 /* TODO: do we need some timeout for this queue ? */ |
1818 | 1834 |
1819 if (ngx_queue_empty(&fs->frames)) { | 1835 if (ngx_queue_empty(&fs->frames)) { |
1820 ngx_queue_insert_after(&fs->frames, &dst->queue); | 1836 ngx_queue_insert_after(&fs->frames, &dst->queue); |
1865 f = &frame->u.crypto; | 1881 f = &frame->u.crypto; |
1866 | 1882 |
1867 ssl_conn = c->ssl->connection; | 1883 ssl_conn = c->ssl->connection; |
1868 | 1884 |
1869 ngx_log_debug2(NGX_LOG_DEBUG_EVENT, c->log, 0, | 1885 ngx_log_debug2(NGX_LOG_DEBUG_EVENT, c->log, 0, |
1870 "SSL_quic_read_level: %d, SSL_quic_write_level: %d", | 1886 "quic SSL_quic_read_level: %d, SSL_quic_write_level: %d", |
1871 (int) SSL_quic_read_level(ssl_conn), | 1887 (int) SSL_quic_read_level(ssl_conn), |
1872 (int) SSL_quic_write_level(ssl_conn)); | 1888 (int) SSL_quic_write_level(ssl_conn)); |
1873 | 1889 |
1874 if (!SSL_provide_quic_data(ssl_conn, SSL_quic_read_level(ssl_conn), | 1890 if (!SSL_provide_quic_data(ssl_conn, SSL_quic_read_level(ssl_conn), |
1875 f->data, f->length)) | 1891 f->data, f->length)) |
1899 | 1915 |
1900 ngx_log_debug1(NGX_LOG_DEBUG_EVENT, c->log, 0, | 1916 ngx_log_debug1(NGX_LOG_DEBUG_EVENT, c->log, 0, |
1901 "quic ssl cipher: %s", SSL_get_cipher(ssl_conn)); | 1917 "quic ssl cipher: %s", SSL_get_cipher(ssl_conn)); |
1902 | 1918 |
1903 ngx_log_debug0(NGX_LOG_DEBUG_EVENT, c->log, 0, | 1919 ngx_log_debug0(NGX_LOG_DEBUG_EVENT, c->log, 0, |
1904 "handshake completed successfully"); | 1920 "quic handshake completed successfully"); |
1905 | 1921 |
1906 frame = ngx_quic_alloc_frame(c, 0); | 1922 frame = ngx_quic_alloc_frame(c, 0); |
1907 if (frame == NULL) { | 1923 if (frame == NULL) { |
1908 return NGX_ERROR; | 1924 return NGX_ERROR; |
1909 } | 1925 } |
1926 return NGX_ERROR; | 1942 return NGX_ERROR; |
1927 } | 1943 } |
1928 } | 1944 } |
1929 | 1945 |
1930 ngx_log_debug2(NGX_LOG_DEBUG_EVENT, c->log, 0, | 1946 ngx_log_debug2(NGX_LOG_DEBUG_EVENT, c->log, 0, |
1931 "SSL_quic_read_level: %d, SSL_quic_write_level: %d", | 1947 "quic SSL_quic_read_level: %d, SSL_quic_write_level: %d", |
1932 (int) SSL_quic_read_level(ssl_conn), | 1948 (int) SSL_quic_read_level(ssl_conn), |
1933 (int) SSL_quic_write_level(ssl_conn)); | 1949 (int) SSL_quic_write_level(ssl_conn)); |
1934 | 1950 |
1935 return NGX_OK; | 1951 return NGX_OK; |
1936 } | 1952 } |
1952 f = &frame->u.stream; | 1968 f = &frame->u.stream; |
1953 | 1969 |
1954 sn = ngx_quic_find_stream(&qc->streams.tree, f->stream_id); | 1970 sn = ngx_quic_find_stream(&qc->streams.tree, f->stream_id); |
1955 | 1971 |
1956 if (sn == NULL) { | 1972 if (sn == NULL) { |
1957 ngx_log_debug0(NGX_LOG_DEBUG_EVENT, c->log, 0, "stream is new"); | 1973 ngx_log_debug1(NGX_LOG_DEBUG_EVENT, c->log, 0, |
1974 "quic stream id 0x%xi is new", f->stream_id); | |
1958 | 1975 |
1959 n = (f->stream_id & NGX_QUIC_STREAM_UNIDIRECTIONAL) | 1976 n = (f->stream_id & NGX_QUIC_STREAM_UNIDIRECTIONAL) |
1960 ? qc->tp.initial_max_stream_data_uni | 1977 ? qc->tp.initial_max_stream_data_uni |
1961 : qc->tp.initial_max_stream_data_bidi_remote; | 1978 : qc->tp.initial_max_stream_data_bidi_remote; |
1962 | 1979 |
2040 // TODO: possible? | 2057 // TODO: possible? |
2041 // stream was deleted while in reordering queue ? | 2058 // stream was deleted while in reordering queue ? |
2042 return NGX_ERROR; | 2059 return NGX_ERROR; |
2043 } | 2060 } |
2044 | 2061 |
2045 ngx_log_debug0(NGX_LOG_DEBUG_EVENT, c->log, 0, "existing stream"); | 2062 ngx_log_debug0(NGX_LOG_DEBUG_EVENT, c->log, 0, "quic existing stream"); |
2046 | 2063 |
2047 b = sn->b; | 2064 b = sn->b; |
2048 | 2065 |
2049 if ((size_t) ((b->pos - b->start) + (b->end - b->last)) < f->length) { | 2066 if ((size_t) ((b->pos - b->start) + (b->end - b->last)) < f->length) { |
2050 ngx_log_error(NGX_LOG_INFO, c->log, 0, "no space in stream buffer"); | 2067 ngx_log_error(NGX_LOG_INFO, c->log, 0, "no space in stream buffer"); |
2348 ngx_quic_connection_t *qc; | 2365 ngx_quic_connection_t *qc; |
2349 static ngx_str_t initial_token = ngx_null_string; | 2366 static ngx_str_t initial_token = ngx_null_string; |
2350 static u_char src[NGX_QUIC_DEFAULT_MAX_PACKET_SIZE]; | 2367 static u_char src[NGX_QUIC_DEFAULT_MAX_PACKET_SIZE]; |
2351 static u_char dst[NGX_QUIC_DEFAULT_MAX_PACKET_SIZE]; | 2368 static u_char dst[NGX_QUIC_DEFAULT_MAX_PACKET_SIZE]; |
2352 | 2369 |
2353 ngx_log_debug0(NGX_LOG_DEBUG_EVENT, c->log, 0, "ngx_quic_send_frames"); | 2370 ngx_log_debug0(NGX_LOG_DEBUG_EVENT, c->log, 0, |
2371 "quic ngx_quic_send_frames"); | |
2354 | 2372 |
2355 q = ngx_queue_head(frames); | 2373 q = ngx_queue_head(frames); |
2356 start = ngx_queue_data(q, ngx_quic_frame_t, queue); | 2374 start = ngx_queue_data(q, ngx_quic_frame_t, queue); |
2357 | 2375 |
2358 ctx = ngx_quic_get_send_ctx(c->quic, start->level); | 2376 ctx = ngx_quic_get_send_ctx(c->quic, start->level); |
2366 q != ngx_queue_sentinel(frames); | 2384 q != ngx_queue_sentinel(frames); |
2367 q = ngx_queue_next(q)) | 2385 q = ngx_queue_next(q)) |
2368 { | 2386 { |
2369 f = ngx_queue_data(q, ngx_quic_frame_t, queue); | 2387 f = ngx_queue_data(q, ngx_quic_frame_t, queue); |
2370 | 2388 |
2371 ngx_log_debug1(NGX_LOG_DEBUG_EVENT, c->log, 0, "frame: %s", f->info); | 2389 ngx_log_debug1(NGX_LOG_DEBUG_EVENT, c->log, 0, |
2390 "quic frame out: %s", f->info); | |
2372 | 2391 |
2373 len = ngx_quic_create_frame(p, f); | 2392 len = ngx_quic_create_frame(p, f); |
2374 if (len == -1) { | 2393 if (len == -1) { |
2375 return NGX_ERROR; | 2394 return NGX_ERROR; |
2376 } | 2395 } |
2396 while (out.len < 4) { | 2415 while (out.len < 4) { |
2397 *p++ = NGX_QUIC_FT_PADDING; | 2416 *p++ = NGX_QUIC_FT_PADDING; |
2398 out.len++; | 2417 out.len++; |
2399 } | 2418 } |
2400 | 2419 |
2401 ngx_log_debug3(NGX_LOG_DEBUG_EVENT, c->log, 0, | |
2402 "packet ready: %ui bytes at level %d need_ack: %ui", | |
2403 out.len, start->level, pkt.need_ack); | |
2404 | |
2405 qc = c->quic; | 2420 qc = c->quic; |
2406 | 2421 |
2407 keys = &c->quic->keys[start->level]; | 2422 keys = &c->quic->keys[start->level]; |
2408 | 2423 |
2409 pkt.secret = &keys->server; | 2424 pkt.secret = &keys->server; |
2428 pkt.scid = qc->dcid; | 2443 pkt.scid = qc->dcid; |
2429 pkt.payload = out; | 2444 pkt.payload = out; |
2430 | 2445 |
2431 res.data = dst; | 2446 res.data = dst; |
2432 | 2447 |
2448 ngx_log_debug6(NGX_LOG_DEBUG_EVENT, c->log, 0, | |
2449 "quic packet ready: %ui bytes at level %d" | |
2450 " need_ack: %d number: %L encoded %d:0x%xD", | |
2451 out.len, start->level, pkt.need_ack, pkt.number, | |
2452 pkt.num_len, pkt.trunc); | |
2453 | |
2433 if (ngx_quic_encrypt(&pkt, c->ssl->connection, &res) != NGX_OK) { | 2454 if (ngx_quic_encrypt(&pkt, c->ssl->connection, &res) != NGX_OK) { |
2434 return NGX_ERROR; | 2455 return NGX_ERROR; |
2435 } | 2456 } |
2436 | 2457 |
2458 #ifdef NGX_QUIC_DEBUG_PACKETS | |
2437 ngx_quic_hexdump0(c->log, "packet to send", res.data, res.len); | 2459 ngx_quic_hexdump0(c->log, "packet to send", res.data, res.len); |
2460 #endif | |
2438 | 2461 |
2439 len = c->send(c, res.data, res.len); | 2462 len = c->send(c, res.data, res.len); |
2440 if (len == NGX_ERROR || (size_t) len != res.len) { | 2463 if (len == NGX_ERROR || (size_t) len != res.len) { |
2441 return NGX_ERROR; | 2464 return NGX_ERROR; |
2442 } | 2465 } |
2488 ngx_msec_t wait, nswait; | 2511 ngx_msec_t wait, nswait; |
2489 ngx_connection_t *c; | 2512 ngx_connection_t *c; |
2490 ngx_quic_connection_t *qc; | 2513 ngx_quic_connection_t *qc; |
2491 | 2514 |
2492 ngx_log_debug0(NGX_LOG_DEBUG_EVENT, ev->log, 0, | 2515 ngx_log_debug0(NGX_LOG_DEBUG_EVENT, ev->log, 0, |
2493 "retransmit timer"); | 2516 "quic retransmit timer"); |
2494 | 2517 |
2495 c = ev->data; | 2518 c = ev->data; |
2496 qc = c->quic; | 2519 qc = c->quic; |
2497 | 2520 |
2498 wait = 0; | 2521 wait = 0; |
2520 static void | 2543 static void |
2521 ngx_quic_push_handler(ngx_event_t *ev) | 2544 ngx_quic_push_handler(ngx_event_t *ev) |
2522 { | 2545 { |
2523 ngx_connection_t *c; | 2546 ngx_connection_t *c; |
2524 | 2547 |
2525 ngx_log_debug0(NGX_LOG_DEBUG_EVENT, ev->log, 0, "push timer"); | 2548 ngx_log_debug0(NGX_LOG_DEBUG_EVENT, ev->log, 0, "quic push timer"); |
2526 | 2549 |
2527 c = ev->data; | 2550 c = ev->data; |
2528 | 2551 |
2529 if (ngx_quic_output(c) != NGX_OK) { | 2552 if (ngx_quic_output(c) != NGX_OK) { |
2530 ngx_quic_close_connection(c, NGX_ERROR); | 2553 ngx_quic_close_connection(c, NGX_ERROR); |
2617 id = (qc->streams.id_counter << 2) | 2640 id = (qc->streams.id_counter << 2) |
2618 | NGX_QUIC_STREAM_SERVER_INITIATED | 2641 | NGX_QUIC_STREAM_SERVER_INITIATED |
2619 | NGX_QUIC_STREAM_UNIDIRECTIONAL; | 2642 | NGX_QUIC_STREAM_UNIDIRECTIONAL; |
2620 | 2643 |
2621 ngx_log_debug2(NGX_LOG_DEBUG_EVENT, c->log, 0, | 2644 ngx_log_debug2(NGX_LOG_DEBUG_EVENT, c->log, 0, |
2622 "creating server uni stream #%ui id %ui", | 2645 "quic creating server uni stream #%ui id %ui", |
2623 qc->streams.id_counter, id); | 2646 qc->streams.id_counter, id); |
2624 | 2647 |
2625 qc->streams.id_counter++; | 2648 qc->streams.id_counter++; |
2626 | 2649 |
2627 sn = ngx_quic_create_stream(qs->parent, id, 0); | 2650 sn = ngx_quic_create_stream(qs->parent, id, 0); |
2777 b = qs->b; | 2800 b = qs->b; |
2778 pc = qs->parent; | 2801 pc = qs->parent; |
2779 qc = pc->quic; | 2802 qc = pc->quic; |
2780 rev = c->read; | 2803 rev = c->read; |
2781 | 2804 |
2782 ngx_log_debug2(NGX_LOG_DEBUG_EVENT, c->log, 0, | 2805 ngx_log_debug3(NGX_LOG_DEBUG_EVENT, c->log, 0, |
2783 "quic recv: eof:%d, avail:%z", | 2806 "quic stream id 0x%xi recv: eof:%d, avail:%z", |
2784 rev->pending_eof, b->last - b->pos); | 2807 qs->id, rev->pending_eof, b->last - b->pos); |
2785 | 2808 |
2786 if (b->pos == b->last) { | 2809 if (b->pos == b->last) { |
2787 rev->ready = 0; | 2810 rev->ready = 0; |
2788 | 2811 |
2789 if (rev->pending_eof) { | 2812 if (rev->pending_eof) { |
2790 rev->eof = 1; | 2813 rev->eof = 1; |
2791 return 0; | 2814 return 0; |
2792 } | 2815 } |
2793 | 2816 |
2794 ngx_log_debug0(NGX_LOG_DEBUG_EVENT, c->log, 0, "quic recv() not ready"); | 2817 ngx_log_debug1(NGX_LOG_DEBUG_EVENT, c->log, 0, |
2818 "quic stream id 0x%xi recv() not ready", qs->id); | |
2795 return NGX_AGAIN; | 2819 return NGX_AGAIN; |
2796 } | 2820 } |
2797 | 2821 |
2798 len = ngx_min(b->last - b->pos, (ssize_t) size); | 2822 len = ngx_min(b->last - b->pos, (ssize_t) size); |
2799 | 2823 |
2806 b->pos = b->start; | 2830 b->pos = b->start; |
2807 b->last = b->start; | 2831 b->last = b->start; |
2808 rev->ready = rev->pending_eof; | 2832 rev->ready = rev->pending_eof; |
2809 } | 2833 } |
2810 | 2834 |
2811 ngx_log_debug2(NGX_LOG_DEBUG_EVENT, c->log, 0, | 2835 ngx_log_debug3(NGX_LOG_DEBUG_EVENT, c->log, 0, |
2812 "quic recv: %z of %uz", len, size); | 2836 "quic stream id 0x%xi recv: %z of %uz", qs->id, len, size); |
2813 | 2837 |
2814 if (!rev->pending_eof) { | 2838 if (!rev->pending_eof) { |
2815 frame = ngx_quic_alloc_frame(pc, 0); | 2839 frame = ngx_quic_alloc_frame(pc, 0); |
2816 if (frame == NULL) { | 2840 if (frame == NULL) { |
2817 return NGX_ERROR; | 2841 return NGX_ERROR; |
2848 ngx_sprintf(frame->info, "MAX_DATA max_data:%d level=%d on recv", | 2872 ngx_sprintf(frame->info, "MAX_DATA max_data:%d level=%d on recv", |
2849 (int) frame->u.max_data.max_data, frame->level); | 2873 (int) frame->u.max_data.max_data, frame->level); |
2850 | 2874 |
2851 ngx_quic_queue_frame(pc->quic, frame); | 2875 ngx_quic_queue_frame(pc->quic, frame); |
2852 | 2876 |
2853 ngx_log_debug1(NGX_LOG_DEBUG_EVENT, c->log, 0, | 2877 ngx_log_debug2(NGX_LOG_DEBUG_EVENT, c->log, 0, |
2854 "quic recv: increased max data: %ui", | 2878 "quic stream id 0x%xi recv: increased max data: %ui", |
2855 qc->streams.max_data); | 2879 qs->id, qc->streams.max_data); |
2856 } | 2880 } |
2857 | 2881 |
2858 return len; | 2882 return len; |
2859 } | 2883 } |
2860 | 2884 |
2875 | 2899 |
2876 if (qc->closing) { | 2900 if (qc->closing) { |
2877 return NGX_ERROR; | 2901 return NGX_ERROR; |
2878 } | 2902 } |
2879 | 2903 |
2880 ngx_log_debug1(NGX_LOG_DEBUG_EVENT, c->log, 0, "quic send: %uz", size); | 2904 ngx_log_debug2(NGX_LOG_DEBUG_EVENT, c->log, 0, |
2905 "quic stream id 0x%xi send: %uz", qs->id, size); | |
2881 | 2906 |
2882 /* | 2907 /* |
2883 * we need to fit at least 1 frame into a packet, thus account head/tail; | 2908 * we need to fit at least 1 frame into a packet, thus account head/tail; |
2884 * 25 = 1 + 8x3 is max header for STREAM frame, with 1 byte for frame type | 2909 * 25 = 1 + 8x3 is max header for STREAM frame, with 1 byte for frame type |
2885 */ | 2910 */ |
2913 frame->u.stream.data = frame->data; | 2938 frame->u.stream.data = frame->data; |
2914 | 2939 |
2915 c->sent += fsize; | 2940 c->sent += fsize; |
2916 p += fsize; | 2941 p += fsize; |
2917 | 2942 |
2918 ngx_sprintf(frame->info, "stream %xi len=%ui level=%d", | 2943 ngx_sprintf(frame->info, "stream 0x%xi len=%ui level=%d", |
2919 qs->id, fsize, frame->level); | 2944 qs->id, fsize, frame->level); |
2920 | 2945 |
2921 ngx_quic_queue_frame(qc, frame); | 2946 ngx_quic_queue_frame(qc, frame); |
2922 } | 2947 } |
2923 | 2948 |
2937 | 2962 |
2938 qs = c->qs; | 2963 qs = c->qs; |
2939 pc = qs->parent; | 2964 pc = qs->parent; |
2940 qc = pc->quic; | 2965 qc = pc->quic; |
2941 | 2966 |
2942 ngx_log_debug0(NGX_LOG_DEBUG_EVENT, c->log, 0, "quic stream cleanup"); | 2967 ngx_log_debug1(NGX_LOG_DEBUG_EVENT, c->log, 0, |
2968 "quic stream id 0x%xi cleanup", qs->id); | |
2943 | 2969 |
2944 ngx_rbtree_delete(&qc->streams.tree, &qs->node); | 2970 ngx_rbtree_delete(&qc->streams.tree, &qs->node); |
2945 ngx_quic_free_frames(pc, &qs->fs.frames); | 2971 ngx_quic_free_frames(pc, &qs->fs.frames); |
2946 | 2972 |
2947 if (qc->closing) { | 2973 if (qc->closing) { |
2953 if ((qs->id & 0x03) == NGX_QUIC_STREAM_UNIDIRECTIONAL) { | 2979 if ((qs->id & 0x03) == NGX_QUIC_STREAM_UNIDIRECTIONAL) { |
2954 /* do not send fin for client unidirectional streams */ | 2980 /* do not send fin for client unidirectional streams */ |
2955 return; | 2981 return; |
2956 } | 2982 } |
2957 | 2983 |
2958 ngx_log_debug0(NGX_LOG_DEBUG_EVENT, c->log, 0, "quic send fin"); | 2984 ngx_log_debug1(NGX_LOG_DEBUG_EVENT, c->log, 0, |
2985 "quic stream id 0x%xi send fin", qs->id); | |
2959 | 2986 |
2960 frame = ngx_quic_alloc_frame(pc, 0); | 2987 frame = ngx_quic_alloc_frame(pc, 0); |
2961 if (frame == NULL) { | 2988 if (frame == NULL) { |
2962 return; | 2989 return; |
2963 } | 2990 } |
2972 frame->u.stream.stream_id = qs->id; | 2999 frame->u.stream.stream_id = qs->id; |
2973 frame->u.stream.offset = c->sent; | 3000 frame->u.stream.offset = c->sent; |
2974 frame->u.stream.length = 0; | 3001 frame->u.stream.length = 0; |
2975 frame->u.stream.data = NULL; | 3002 frame->u.stream.data = NULL; |
2976 | 3003 |
2977 ngx_sprintf(frame->info, "stream %xi fin=1 level=%d", qs->id, frame->level); | 3004 ngx_sprintf(frame->info, "stream 0x%xi fin=1 level=%d", |
3005 qs->id, frame->level); | |
2978 | 3006 |
2979 ngx_quic_queue_frame(qc, frame); | 3007 ngx_quic_queue_frame(qc, frame); |
2980 | 3008 |
2981 (void) ngx_quic_output(pc); | 3009 (void) ngx_quic_output(pc); |
2982 } | 3010 } |
3049 q = ngx_queue_head(&qc->free_frames); | 3077 q = ngx_queue_head(&qc->free_frames); |
3050 frame = ngx_queue_data(q, ngx_quic_frame_t, queue); | 3078 frame = ngx_queue_data(q, ngx_quic_frame_t, queue); |
3051 | 3079 |
3052 ngx_queue_remove(&frame->queue); | 3080 ngx_queue_remove(&frame->queue); |
3053 | 3081 |
3082 #ifdef NGX_QUIC_DEBUG_FRAMES_ALLOC | |
3054 ngx_log_debug1(NGX_LOG_DEBUG_EVENT, c->log, 0, | 3083 ngx_log_debug1(NGX_LOG_DEBUG_EVENT, c->log, 0, |
3055 "reuse quic frame n:%ui", qc->nframes); | 3084 "quic reuse frame n:%ui", qc->nframes); |
3085 #endif | |
3056 | 3086 |
3057 } else { | 3087 } else { |
3058 frame = ngx_pcalloc(c->pool, sizeof(ngx_quic_frame_t)); | 3088 frame = ngx_pcalloc(c->pool, sizeof(ngx_quic_frame_t)); |
3059 if (frame == NULL) { | 3089 if (frame == NULL) { |
3060 ngx_free(p); | 3090 ngx_free(p); |
3063 | 3093 |
3064 #if (NGX_DEBUG) | 3094 #if (NGX_DEBUG) |
3065 ++qc->nframes; | 3095 ++qc->nframes; |
3066 #endif | 3096 #endif |
3067 | 3097 |
3098 #ifdef NGX_QUIC_DEBUG_FRAMES_ALLOC | |
3068 ngx_log_debug1(NGX_LOG_DEBUG_EVENT, c->log, 0, | 3099 ngx_log_debug1(NGX_LOG_DEBUG_EVENT, c->log, 0, |
3069 "alloc quic frame n:%ui", qc->nframes); | 3100 "quic alloc frame n:%ui", qc->nframes); |
3101 #endif | |
3070 } | 3102 } |
3071 | 3103 |
3072 ngx_memzero(frame, sizeof(ngx_quic_frame_t)); | 3104 ngx_memzero(frame, sizeof(ngx_quic_frame_t)); |
3073 | 3105 |
3074 frame->data = p; | 3106 frame->data = p; |
3088 ngx_free(frame->data); | 3120 ngx_free(frame->data); |
3089 } | 3121 } |
3090 | 3122 |
3091 ngx_queue_insert_head(&qc->free_frames, &frame->queue); | 3123 ngx_queue_insert_head(&qc->free_frames, &frame->queue); |
3092 | 3124 |
3125 #ifdef NGX_QUIC_DEBUG_FRAMES_ALLOC | |
3093 ngx_log_debug1(NGX_LOG_DEBUG_EVENT, c->log, 0, | 3126 ngx_log_debug1(NGX_LOG_DEBUG_EVENT, c->log, 0, |
3094 "free quic frame n:%ui", qc->nframes); | 3127 "quic free frame n:%ui", qc->nframes); |
3095 } | 3128 #endif |
3129 } |