Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

The handshake time is particularly long in absence of session resumption #288

Closed
msoxzw opened this issue May 2, 2022 · 5 comments
Closed

The handshake time is particularly long in absence of session resumption #288

msoxzw opened this issue May 2, 2022 · 5 comments
Labels
stale

Comments

@msoxzw
Copy link
Contributor

msoxzw commented May 2, 2022

It is very strange for aioquic to take at least 500 ms to complete handshake, and the following code to illustrate this issue.

python examples/http3_client.py -v https://doh3.dns.nextdns.io/info

examples/http3_client.py:528: DeprecationWarning: There is no current event loop
  loop = asyncio.get_event_loop()
2022-05-02 18:28:08,973 DEBUG asyncio Using proactor: IocpProactor
2022-05-02 18:28:08,989 DEBUG quic [0caf078deba8e240] TLS State.CLIENT_HANDSHAKE_START -> State.CLIENT_EXPECT_SERVER_HELLO
2022-05-02 18:28:09,020 INFO quic [0caf078deba8e240] Retrying with token (98 bytes)
2022-05-02 18:28:09,020 DEBUG quic [0caf078deba8e240] TLS State.CLIENT_HANDSHAKE_START -> State.CLIENT_EXPECT_SERVER_HELLO
2022-05-02 18:28:09,058 DEBUG quic [0caf078deba8e240] QuicConnectionState.FIRSTFLIGHT -> QuicConnectionState.CONNECTED
2022-05-02 18:28:09,058 DEBUG quic [0caf078deba8e240] TLS State.CLIENT_EXPECT_SERVER_HELLO -> State.CLIENT_EXPECT_ENCRYPTED_EXTENSIONS
2022-05-02 18:28:09,058 DEBUG quic [0caf078deba8e240] TLS State.CLIENT_EXPECT_ENCRYPTED_EXTENSIONS -> State.CLIENT_EXPECT_CERTIFICATE_REQUEST_OR_CERTIFICATE
2022-05-02 18:28:09,058 DEBUG quic [0caf078deba8e240] Discarding epoch Epoch.INITIAL
2022-05-02 18:28:09,058 DEBUG quic [0caf078deba8e240] TLS State.CLIENT_EXPECT_CERTIFICATE_REQUEST_OR_CERTIFICATE -> State.CLIENT_EXPECT_CERTIFICATE_VERIFY
2022-05-02 18:28:09,528 DEBUG quic [0caf078deba8e240] TLS State.CLIENT_EXPECT_CERTIFICATE_VERIFY -> State.CLIENT_EXPECT_FINISHED
2022-05-02 18:28:09,528 DEBUG quic [0caf078deba8e240] TLS State.CLIENT_EXPECT_FINISHED -> State.CLIENT_POST_HANDSHAKE
2022-05-02 18:28:09,536 INFO quic [0caf078deba8e240] ALPN negotiated protocol h3

The round-trip time of "doh3.dns.nextdns.io" is 30 ms or so, which is seen from

2022-05-02 18:28:08,989 DEBUG quic [0caf078deba8e240] TLS State.CLIENT_HANDSHAKE_START -> State.CLIENT_EXPECT_SERVER_HELLO
2022-05-02 18:28:09,020 INFO quic [0caf078deba8e240] Retrying with token (98 bytes)

and further verified by


2022-05-02 18:28:09,020 DEBUG quic [0caf078deba8e240] TLS State.CLIENT_HANDSHAKE_START -> State.CLIENT_EXPECT_SERVER_HELLO
2022-05-02 18:28:09,058 DEBUG quic [0caf078deba8e240] QuicConnectionState.FIRSTFLIGHT -> QuicConnectionState.CONNECTED

However, in the following two lines, aioquic unexpectedly spends disproportionately approximately 500 ms to verify certificate, compared with 30 ms round-trip time.

2022-05-02 18:28:09,058 DEBUG quic [0caf078deba8e240] TLS State.CLIENT_EXPECT_CERTIFICATE_REQUEST_OR_CERTIFICATE -> State.CLIENT_EXPECT_CERTIFICATE_VERIFY
2022-05-02 18:28:09,528 DEBUG quic [0caf078deba8e240] TLS State.CLIENT_EXPECT_CERTIFICATE_VERIFY -> State.CLIENT_EXPECT_FINISHED

From my perspective, the connection time is bound by IO, and thus, it should be instant to verify certificate.
@jlaine
Copy link
Contributor

jlaine commented May 9, 2022

500ms sounds suspiciously like a retransmission, so I think to move forward we'd need a client-side QLOG file + a wireshark capture (with SSL keys).

@msoxzw
Copy link
Contributor Author

msoxzw commented May 10, 2022

python examples/http3_client.py -v https://doh3.dns.nextdns.io/info

examples/http3_client.py:528: DeprecationWarning: There is no current event loop
  loop = asyncio.get_event_loop()
2022-05-10 21:14:17,904 DEBUG asyncio Using proactor: IocpProactor
2022-05-10 21:14:17,919 DEBUG quic [1fcaf3316f954dff] TLS State.CLIENT_HANDSHAKE_START -> State.CLIENT_EXPECT_SERVER_HELLO
2022-05-10 21:14:17,951 INFO quic [1fcaf3316f954dff] Retrying with token (98 bytes)
2022-05-10 21:14:17,951 DEBUG quic [1fcaf3316f954dff] TLS State.CLIENT_HANDSHAKE_START -> State.CLIENT_EXPECT_SERVER_HELLO
2022-05-10 21:14:17,982 DEBUG quic [1fcaf3316f954dff] QuicConnectionState.FIRSTFLIGHT -> QuicConnectionState.CONNECTED
2022-05-10 21:14:17,982 DEBUG quic [1fcaf3316f954dff] TLS State.CLIENT_EXPECT_SERVER_HELLO -> State.CLIENT_EXPECT_ENCRYPTED_EXTENSIONS
2022-05-10 21:14:17,982 DEBUG quic [1fcaf3316f954dff] TLS State.CLIENT_EXPECT_ENCRYPTED_EXTENSIONS -> State.CLIENT_EXPECT_CERTIFICATE_REQUEST_OR_CERTIFICATE
2022-05-10 21:14:17,982 DEBUG quic [1fcaf3316f954dff] Discarding epoch Epoch.INITIAL
2022-05-10 21:14:17,982 DEBUG quic [1fcaf3316f954dff] TLS State.CLIENT_EXPECT_CERTIFICATE_REQUEST_OR_CERTIFICATE -> State.CLIENT_EXPECT_CERTIFICATE_VERIFY
2022-05-10 21:14:18,436 DEBUG quic [1fcaf3316f954dff] TLS State.CLIENT_EXPECT_CERTIFICATE_VERIFY -> State.CLIENT_EXPECT_FINISHED
2022-05-10 21:14:18,436 DEBUG quic [1fcaf3316f954dff] TLS State.CLIENT_EXPECT_FINISHED -> State.CLIENT_POST_HANDSHAKE
2022-05-10 21:14:18,436 INFO quic [1fcaf3316f954dff] ALPN negotiated protocol h3
2022-05-10 21:14:18,436 DEBUG quic [1fcaf3316f954dff] Stream 3 created by peer
2022-05-10 21:14:18,436 INFO quic [1fcaf3316f954dff] Duplicate CRYPTO data received for epoch Epoch.HANDSHAKE
2022-05-10 21:14:18,436 INFO quic [1fcaf3316f954dff] Duplicate CRYPTO data received for epoch Epoch.HANDSHAKE
2022-05-10 21:14:18,436 INFO quic [1fcaf3316f954dff] Duplicate CRYPTO data received for epoch Epoch.HANDSHAKE
2022-05-10 21:14:18,436 INFO quic [1fcaf3316f954dff] Duplicate CRYPTO data received for epoch Epoch.HANDSHAKE
2022-05-10 21:14:18,468 DEBUG quic [1fcaf3316f954dff] Peer retiring CID 20729bced00ac52b (0)
2022-05-10 21:14:18,468 DEBUG quic [1fcaf3316f954dff] Discarding epoch Epoch.HANDSHAKE
2022-05-10 21:14:18,468 INFO client New session ticket received
2022-05-10 21:14:18,468 DEBUG quic [1fcaf3316f954dff] Stream 0 discarded
2022-05-10 21:14:18,468 INFO client Response received for GET /info : 73 bytes in 0.0 s (0.019 Mbps)
2022-05-10 21:14:18,468 INFO quic [1fcaf3316f954dff] Connection close sent (code 0x0, reason )
2022-05-10 21:14:18,468 DEBUG quic [1fcaf3316f954dff] QuicConnectionState.CONNECTED -> QuicConnectionState.CLOSING
2022-05-10 21:14:18,740 DEBUG quic [1fcaf3316f954dff] Discarding epoch Epoch.ONE_RTT
2022-05-10 21:14:18,740 DEBUG quic [1fcaf3316f954dff] QuicConnectionState.CLOSING -> QuicConnectionState.TERMINATED

QLOG file: qlog.log

Please forgive me not to provide a complete wireshark capture against leaking possible personally identifiable information.

No.	Time				Source	Destination	Protocol	Length	Info
1	2022-05-10 21:14:17.924601	local	remote		QUIC		1322	Initial, DCID=1fcaf3316f954dff, SCID=20729bced00ac52b, PKN: 0, CRYPTO, PADDING
2	2022-05-10 21:14:17.953940	remote	local		QUIC		175	Retry, DCID=20729bced00ac52b, SCID=eee5aad4
3	2022-05-10 21:14:17.960158	local	remote		QUIC		1322	Initial, DCID=eee5aad4, SCID=20729bced00ac52b, PKN: 1, CRYPTO, PADDING
4	2022-05-10 21:14:17.990826	remote	local		QUIC		1294	Handshake, DCID=20729bced00ac52b, SCID=33a22577
5	2022-05-10 21:14:17.990826	remote	local		QUIC		1294	Handshake, DCID=20729bced00ac52b, SCID=33a22577
6	2022-05-10 21:14:17.990826	remote	local		QUIC		1173	Protected Payload (KP0), DCID=20729bced00ac52b
7	2022-05-10 21:14:17.990826	remote	local		QUIC		74	Protected Payload (KP0), DCID=20729bced00ac52b
8	2022-05-10 21:14:17.994903	local	remote		QUIC		232	Handshake, DCID=33a22577, SCID=20729bced00ac52b
9	2022-05-10 21:14:17.995443	local	remote		QUIC		86	Handshake, DCID=33a22577, SCID=20729bced00ac52b
10	2022-05-10 21:14:18.062945	remote	local		QUIC		1026	Handshake, DCID=20729bced00ac52b, SCID=33a22577
11	2022-05-10 21:14:18.063355	remote	local		QUIC		1026	Handshake, DCID=20729bced00ac52b, SCID=33a22577
12	2022-05-10 21:14:18.206917	remote	local		QUIC		1026	Handshake, DCID=20729bced00ac52b, SCID=33a22577
13	2022-05-10 21:14:18.206917	remote	local		QUIC		1026	Handshake, DCID=20729bced00ac52b, SCID=33a22577
14	2022-05-10 21:14:18.441259	local	remote		QUIC		273	Protected Payload (KP0), DCID=33a22577
15	2022-05-10 21:14:18.442315	local	remote		QUIC		86	Handshake, DCID=33a22577, SCID=20729bced00ac52b
16	2022-05-10 21:14:18.443105	local	remote		QUIC		115	Protected Payload (KP0), DCID=33a22577
17	2022-05-10 21:14:18.444177	local	remote		QUIC		97	Protected Payload (KP0), DCID=33a22577
18	2022-05-10 21:14:18.445045	local	remote		QUIC		86	Handshake, DCID=33a22577, SCID=20729bced00ac52b
19	2022-05-10 21:14:18.445163	local	remote		QUIC		86	Handshake, DCID=33a22577, SCID=20729bced00ac52b
20	2022-05-10 21:14:18.470597	remote	local		QUIC		86	Handshake, DCID=20729bced00ac52b, SCID=33a22577
21	2022-05-10 21:14:18.470597	remote	local		QUIC		74	Protected Payload (KP0), DCID=20729bced00ac52b
22	2022-05-10 21:14:18.470597	remote	local		QUIC		353	Protected Payload (KP0)
23	2022-05-10 21:14:18.473422	remote	local		QUIC		198	Protected Payload (KP0)
24	2022-05-10 21:14:18.474769	local	remote		QUIC		99	Protected Payload (KP0), DCID=33a22577
25	2022-05-10 21:14:18.477514	local	remote		QUIC		71	Protected Payload (KP0), DCID=33a22577
26	2022-05-10 21:14:18.479070	local	remote		QUIC		68	Protected Payload (KP0), DCID=33a22577
27	2022-05-10 21:14:18.503927	remote	local		QUIC		78	Protected Payload (KP0)
28	2022-05-10 21:14:18.506841	remote	local		QUIC		72	Protected Payload (KP0)

Moreover, the same issue occurs when connecting "https://cloudflare-dns.com/" and "https://dns.google/".

@msoxzw
Copy link
Contributor Author

msoxzw commented May 31, 2022

As far as I know, pyca/cryptography#7236 is responsible for this issue. Even though cryptography is downgraded to 36.0.2, it still takes about 30 ms to verify certificate.

@msoxzw msoxzw changed the title The first handshake time is particularly long The handshake time is particularly long in absence of session resumption Jul 7, 2022
@msoxzw
Copy link
Contributor Author

msoxzw commented Nov 2, 2022

Moreover, I prefer system CA certificates to "certifi".

import ssl
context = ssl.create_default_context()
system_certs = context.get_ca_certs(binary_form=True)

@github-actions
Copy link

github-actions bot commented Mar 3, 2023

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.

@github-actions github-actions bot added the stale label Mar 3, 2023
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
stale
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@jlaine @msoxzw