aioquic icon indicating copy to clipboard operation
aioquic copied to clipboard

Published 20 hours ago • verified publisher icon aiortc

The handshake time is particularly long in absence of session resumption

Open msoxzw opened this issue 2 years ago • 3 comments

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.

msoxzw avatar May 02 '22 19:05 msoxzw

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).

jlaine avatar May 09 '22 08:05 jlaine

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 avatar May 10 '22 21:05 msoxzw

As far as I know, https://github.com/pyca/cryptography/issues/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 avatar May 31 '22 21:05 msoxzw

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

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

msoxzw avatar Nov 02 '22 21:11 msoxzw

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[bot] avatar Mar 03 '23 04:03 github-actions[bot]