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

unable to connect after upgrading from 0.8.x to 0.9.3, #1472

Closed
neevek opened this issue Dec 22, 2022 · 8 comments
Closed

unable to connect after upgrading from 0.8.x to 0.9.3, #1472

neevek opened this issue Dec 22, 2022 · 8 comments

Comments

@neevek
Copy link

neevek commented Dec 22, 2022 •
edited
Loading

Hi,

My code using 0.8.x has been running smoothly for quite a long time, tonight I tried upgrading quinn to 0.9.3, with some small changes the code compile but the server and the client failed to pass the handshake phase.
The server hangs at awaiting on the accepted Connecting object:

while let Some(conn) = endpoint.accept().await {
    // this never returns
    let conn = conn.await?;
}

Logs from the server side:

2022-12-22 23:26:19.140 [server] [hs.rs:382] [D] decided upon suite TLS13_CHACHA20_POLY1305_SHA256

The client hangs at connecting to the server:

// this never returns
let conn = endpoint.connect(remote_addr, "localhost")?.await?;

Logs from the client side:

2022-12-22 23:44:02.687 [client] [hs.rs:55] [D] No cached session for DnsName(DnsName(DnsName("localhost")))
2022-12-22 23:44:02.688 [client] [hs.rs:127] [D] Not resuming any session

Those logs are from rustls, I tried upgrading rustls and rustc as well, but that doesn't make any difference.

What is the possible cause of the problem?
@Ralith
Copy link
Collaborator

Ralith commented Dec 22, 2022

Can you share trace-level logs from quinn and/or a pcap of a connection attempt and/or a standalone repro? It might also be interesting to try your upgraded client against your old 0.8-based server and vis versa.

@neevek
Copy link
Author

neevek commented Dec 23, 2022

Hi, Ralith

I tried the new version and the 0.8-based old version, this is the result:

new client -> old server works fine.
new client -> new server hangs.
old client -> new server hangs.

Trace logs of the server:

2022-12-23 23:06:50.303 [quinn_server] [quinn_server.rs:19] [I] will use 1 worker threads
2022-12-23 23:06:50.304 [quinn_server] [poll.rs:521] [T] registering event source with poller: token=Token(0), interests=READABLE
2022-12-23 23:06:50.306 [quinn_server] [poll.rs:521] [T] registering event source with poller: token=Token(1), interests=READABLE | WRITABLE
2022-12-23 23:06:50.306 [quinn_server] [server.rs:73] [I] server is bound to: 0.0.0.0:3515, idle_timeout: 40000
2022-12-23 23:07:03.816 [quinn_server] [hs.rs:456] [T] we got a clienthello ClientHelloPayload { client_version: TLSv1_2, random: 7a1eb7a09b6402f4c8b6bcef593adf158eb1df7cc43529dff8e275728f054dc1, session_id: , cipher_suites: [TLS13_AES_256_GCM_SHA384, TLS13_AES_128_GCM_SHA256, TLS13_CHACHA20_POLY1305_SHA256, TLS_ECDHE_ECDSA_WITH_AES_256_GCM_SHA384, TLS_ECDHE_ECDSA_WITH_AES_128_GCM_SHA256, TLS_ECDHE_ECDSA_WITH_CHACHA20_POLY1305_SHA256, TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384, TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256, TLS_ECDHE_RSA_WITH_CHACHA20_POLY1305_SHA256, TLS_EMPTY_RENEGOTIATION_INFO_SCSV], compression_methods: [Null], extensions: [SupportedVersions([TLSv1_3]), ECPointFormats([Uncompressed]), NamedGroups([X25519, secp256r1, secp384r1]), SignatureAlgorithms([ECDSA_NISTP384_SHA384, ECDSA_NISTP256_SHA256, ED25519, RSA_PSS_SHA512, RSA_PSS_SHA384, RSA_PSS_SHA256, RSA_PKCS1_SHA512, RSA_PKCS1_SHA384, RSA_PKCS1_SHA256]), ExtendedMasterSecretRequest, CertificateStatusRequest(OCSP(OCSPCertificateStatusRequest { responder_ids: [], extensions:  })), ServerName([ServerName { typ: HostName, payload: HostName((6c6f63616c686f7374, DnsName("localhost"))) }]), SignedCertificateTimestampRequest, KeyShare([KeyShareEntry { group: X25519, payload: 2f01bff7f49d40426014d687cf888e4782d778dc8ce351b585cf00a28173a04c }]), PresharedKeyModes([PSK_DHE_KE]), TransportParameters([1, 4, 128, 2, 73, 240, 3, 2, 69, 200, 4, 4, 128, 16, 0, 0, 5, 4, 128, 19, 18, 208, 6, 4, 128, 19, 18, 208, 7, 4, 128, 19, 18, 208, 8, 2, 68, 0, 9, 2, 64, 100, 14, 1, 5, 64, 182, 0, 32, 4, 128, 0, 255, 255, 15, 8, 254, 138, 178, 148, 45, 184, 172, 132, 106, 178, 0]), SessionTicket(Request)] }
2022-12-23 23:07:03.816 [quinn_server] [server_conn.rs:127] [T] sni Some(DnsName("localhost"))
2022-12-23 23:07:03.816 [quinn_server] [server_conn.rs:128] [T] sig schemes [ECDSA_NISTP384_SHA384, ECDSA_NISTP256_SHA256, ED25519, RSA_PSS_SHA512, RSA_PSS_SHA384, RSA_PSS_SHA256, RSA_PKCS1_SHA512, RSA_PKCS1_SHA384, RSA_PKCS1_SHA256]
2022-12-23 23:07:03.816 [quinn_server] [server_conn.rs:129] [T] alpn protocols None
2022-12-23 23:07:03.816 [quinn_server] [server_conn.rs:130] [T] cipher suites [TLS13_AES_256_GCM_SHA384, TLS13_AES_128_GCM_SHA256, TLS13_CHACHA20_POLY1305_SHA256, TLS_ECDHE_ECDSA_WITH_AES_256_GCM_SHA384, TLS_ECDHE_ECDSA_WITH_AES_128_GCM_SHA256, TLS_ECDHE_ECDSA_WITH_CHACHA20_POLY1305_SHA256, TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384, TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256, TLS_ECDHE_RSA_WITH_CHACHA20_POLY1305_SHA256, TLS_EMPTY_RENEGOTIATION_INFO_SCSV]
2022-12-23 23:07:03.816 [quinn_server] [hs.rs:382] [D] decided upon suite TLS13_CHACHA20_POLY1305_SHA256
2022-12-23 23:07:03.817 [quinn_server] [tls13.rs:499] [T] sending server hello Message { version: TLSv1_2, payload: Handshake { parsed: HandshakeMessagePayload { typ: ServerHello, payload: ServerHello(ServerHelloPayload { legacy_version: TLSv1_2, random: ec8b6adf60945baee79ff971b931d039a6a652db6d759f6d9a4310740efa946f, session_id: , cipher_suite: TLS13_CHACHA20_POLY1305_SHA256, compression_method: Null, extensions: [KeyShare(KeyShareEntry { group: X25519, payload: 25f9e1d48bcb2a25acd3b4fc547f105c4591a71375521322f2771df42f51733c }), SupportedVersions(TLSv1_3)] }) }, encoded: 020000560303ec8b6adf60945baee79ff971b931d039a6a652db6d759f6d9a4310740efa946f00130300002e00330024001d002025f9e1d48bcb2a25acd3b4fc547f105c4591a71375521322f2771df42f51733c002b00020304 } }
2022-12-23 23:07:03.817 [quinn_server] [tls13.rs:697] [T] sending encrypted extensions Message { version: TLSv1_3, payload: Handshake { parsed: HandshakeMessagePayload { typ: EncryptedExtensions, payload: EncryptedExtensions([ServerNameAck, TransportParameters([1, 4, 128, 0, 156, 64, 3, 2, 69, 200, 4, 4, 128, 16, 0, 0, 5, 4, 128, 19, 18, 208, 6, 4, 128, 19, 18, 208, 7, 4, 128, 19, 18, 208, 8, 2, 68, 0, 9, 2, 64, 100, 14, 1, 5, 64, 182, 0, 2, 16, 98, 64, 156, 207, 207, 67, 217, 126, 203, 123, 14, 158, 141, 114, 163, 181, 32, 4, 128, 0, 255, 255, 0, 20, 57, 98, 87, 235, 248, 51, 168, 241, 49, 76, 191, 123, 198, 193, 58, 165, 13, 65, 36, 46, 15, 8, 252, 168, 92, 169, 68, 205, 99, 155, 106, 178, 0])]) }, encoded: 080000750073000000000039006b010480009c40030245c80404801000000504801312d00604801312d00704801312d008024400090240640e010540b600021062409ccfcf43d97ecb7b0e9e8d72a3b520048000ffff0014396257ebf833a8f1314cbf7bc6c13aa50d41242e0f08fca85ca944cd639b6ab200 } }
2022-12-23 23:07:03.817 [quinn_server] [tls13.rs:796] [T] sending certificate Message { version: TLSv1_3, payload: Handshake { parsed: HandshakeMessagePayload { typ: Certificate, payload: CertificateTLS13(CertificatePayloadTLS13 { context: , entries: [CertificateEntry { cert: Certificate(b"0\x82\x05\xc30\x82\x03\xab\xa0\x03\x02\x01\x02\x02\x14R,\xef\xa0\x8f%P\xde\xa26XW\x89\x1d\xdf\xb0\xeb,\xa3\xd90\r\x06\t*\x86H\x86\xf7\r\x01\x01\x0b\x05\00q1\x0b0\t\x06\x03U\x04\x06\x13\x02CN1\x0b0\t\x06\x03U\x04\x08\x0c\x02GD1\x0b0\t\x06\x03U\x04\x07\x0c\x02GZ1\x110\x0f\x06\x03U\x04\n\x0c\x08PERSONAL1\x0b0\t\x06\x03U\x04\x0b\x0c\x02IT1\x0c0\n\x06\x03U\x04\x03\x0c\x03NVK1\x1a0\x18\x06\t*\x86H\x86\xf7\r\x01\t\x01\x16\x0babc@abc.com0\x1e\x17\r211016162007Z\x17\r311014162007Z0q1\x0b0\t\x06\x03U\x04\x06\x13\x02CN1\x0b0\t\x06\x03U\x04\x08\x0c\x02GD1\x0b0\t\x06\x03U\x04\x07\x0c\x02GZ1\x110\x0f\x06\x03U\x04\n\x0c\x08PERSONAL1\x0b0\t\x06\x03U\x04\x0b\x0c\x02IT1\x0c0\n\x06\x03U\x04\x03\x0c\x03NVK1\x1a0\x18\x06\t*\x86H\x86\xf7\r\x01\t\x01\x16\x0babc@abc.com0\x82\x02\"0\r\x06\t*\x86H\x86\xf7\r\x01\x01\x01\x05\0\x03\x82\x02\x0f\00\x82\x02\n\x02\x82\x02\x01\0\xd0`\x18\xad2s\x02c\xf9\x0f\xeeR>\xc1\x91_/\xaf\x97`\xf5\x01c2\xa3\x99\x94\x12\xd2;Ju\x02\x19\x12\x8d\x11\xdaq\xed\xf6Z>,\xd9\x9e4J\xa384ON\xf9G\xb7\xc2\xbdL\x83\x8c\xf9\xab\x0b\xfc\xd1zWgZ\xbbu\")8qP\xaa\xd9\xa9\xc3\x90\xbav\x1b\xf3\xc8W\xa1f\xce\xd0\xae\xb3\xa4\xcf\x1d\xf0my['\xa7\"\xe4\xc0\x1ek\x95kK\xe85X\xde\xd9Z\xab\xc5\x89{\xef,S\xacB\x11A\x92\x122\xff\xc6\x80\x96\xc0XX\x19~{\xb8\x98\xd2\x13\x192\xc6\x15\x8d\xf1z'\x949\x02\xe2q\x1f\xf7\x1d\xa3\x1d\x82\x1f\xecE\x18\xf1\n\xfc\x18]/\xaf(\xc3\xb6\xc4bH\xc8F\x9eTCT\xe6\xbd3\x1a2\x83a\n-\xaf\xe9\xa9\x99$\xeaUy\x96\x01'\xfa\xb7F\xd5c\xf1\x88\x025\xe3\x93\xadd\xbd\xc3\xfe\xe8H\xa6\xa2\x83\xfc\xa0\x08\xbe\x1a\x93\xcc\xc76\xd6\xde\xb5dv\xc6\xea\x1a\x93\x04p\x84\x1df\xb1m\xa5\x98\xe4\x1b\x7f\x842V\x8cP\xdf\x8di|\xd5\xb7*:D\xed`\xf9\xda\xad\xbf\xde@l\xfe\xd0l=\x02\xd1FO6\x1dxA\x90\xab\xfb\x81dE\xd9\x01|\x04\xb4]\x83k\xaag\xf7\xe0MEpv@\x0c\xc6x\xe8\xbf\xd0\xb6@\xed\xdbR\x06\xc7F\xd4\xaeK\xe3n$\x14\xa2%g&\x91tz`\"\x1bN\xefD\xeb\xa4\xca/W\x15l\xe1\xd7\x8d\x9frE\xb0\x8bu>,\xb0\x7fk \xc6\xb0P\xea\rU\x96\x91d\x901\x1d\x84n\xaa3O\n\xe9\xadrsD\t\xc7\xcfP\xf1\xed\x10]\xe7Z\x1c/,\xd8a\x9d\x01\xe5\xb0\xff[\xa8\x8d/\x86\xde\x10bQOw\xed\xf8\xf5\x1b\xa5\xe4\xdc\\\x8a>\x96|\xc19B\x05\xf7\xd5\xf6\xa0\x1f\xc9~\x9e\xb4\xeaH\x02\xfbz\xcf\xef\xa50U\xf1\xc5\xd3\xa0\xb4\xbf\x90\xbc\xb3O\xe50\x04/\xe9\x86\x97z\t\x94\x8b?\xbdB\xa5\xcf\xac\xe4\xf4I\x15\x06#\x05\xd7%\xeb\xcc\x89:\xad\x15&\xd1qb\x08I^\x0b'\x02\x03\x01\0\x01\xa3S0Q0\x1d\x06\x03U\x1d\x0e\x04\x16\x04\x14C2\x11w\xba\xb9\x0c\xae)\x8c\xe9\xc2\xae\x1ey\xfe\xf7\x7f\xae\xff0\x1f\x06\x03U\x1d#\x04\x180\x16\x80\x14C2\x11w\xba\xb9\x0c\xae)\x8c\xe9\xc2\xae\x1ey\xfe\xf7\x7f\xae\xff0\x0f\x06\x03U\x1d\x13\x01\x01\xff\x04\x050\x03\x01\x01\xff0\r\x06\t*\x86H\x86\xf7\r\x01\x01\x0b\x05\0\x03\x82\x02\x01\0\x97\x01\xb1\xb8\x06\x80\x10\x8a%6\t\x18\xf6\xd26\xbet\xb6n\xda\xb7\x14\xb28\xc0)\xc3\x0eo\xbf\xef.E\xc6k\x0e\x1e*\xa5\x8d\xe3\xd9\xed\xad\xa6\xbe\xc4\xd9\xad\x9c0\xa9LuJ\x1b\xaez\xc2\xc9\0\x91\x10E\x81\xcbK\x95O\xf3\xfc|\x05J\xf5_e\xa7On\xe5yK\xae\xb5\x1f\xacc3J\x10\x176\xea\xfa\x9d\xd1\n\x01-\xe0\x12&8D\x11*\xc7\x04\xf7\x99\xaf}\xc5Yp\x868\x90\xdf2\xedp^\xf4\"0:\xb0\x81A\xd6\xf7M\xc9\xdfh\xf9\xd2\xe6PN\x83\xf9\n\xfcO\x18\xd4\xc2#\xdbX.J#\xc6\\&\xd6m0\xb9\x93\xc8\xca\x80\x8e\xbfD\xcf\x9a6\x94\xd8F\x8a\xe7\xaf\x82\xc2\x8e\xa5\xad\x98\x9d\x0f\xd3IF\xcb\xba5MI\xe4\xb5\xa1\xf1=\xc2d\xc7\xc28\xbc&ZL\x11\\\x86\xe0\x10p.\xe9\xf6w\xf4\xe9\xfc#>\xf6M\xaf\x8f\xfb\x10@zA%R_\x16\xa4\xbd\xaeN\xbdl\xc9\xd368\xb6\xaf\xa5\x7f\x94\x8d\x1e\x0e\xfew\xd4\xce4\xba\xb9vx\xe9\x9f\xcaI4X#\xbe\x8bb\xf6\08\x9c\xf1?\x08\xe1}\xadl\x8a\xbc\xcaj\x08v\x03\x82*\xe7\xf2N\xffB\x82/\xdb\x0c\xfc#F\x87\x16\xf5\xedQ\x89|\x8b\x9c\x1c\x87\xa7\xf3\x834B\x02\xc7\xc44P \xb4M\xfd ?\xf7\xc9]c_\x17\xb9\xfd\xcbX\xd7\x9f\x18\xdf\xaae\xe0\xdf\xe0\"\xcc\xb9\xa9\x06\xb2\x16\x9f\xf2\x91kS\xe4o\xdfx3)\x17\xa6\x8c!\xff\x87U ~u:\xb1<\xa9c\xaf\x1a2\xad-m\x18\x0fo\x89\xc5\xc0\xe9\x06\x19\x19/4\xeb#\xc2z\xccr\xc4\xa4v$[\xda6w\xc6\xe4\xf3\xd1\xad4\xdbE\xda\0\t\x0cd}\x03\x182}\xfd\xa5\xecy\x97\x04.\xe6\xdeA\\3X\x01\x9e^\"\x14Qygr\xf3x;y\xfd\xac-\xaf\xd4&X5o\x8fe\xdd&b\xc0J\xb5\x9b\x95\x08\x8eX?\xe0\xd0\xad\x99~T\xfah\xf4\xbb\"\xbe\xce\xa0\x9a\x1fNcX\xe7;\xdc\x1c5\xc3\x03\x14\xa0"), exts: [] }] }) }, encoded: 0b0005d0000005cc0005c7308205c3308203aba0030201020214522cefa08f2550dea2365857891ddfb0eb2ca3d9300d06092a864886f70d01010b05003071310b300906035504061302434e310b300906035504080c024744310b300906035504070c02475a3111300f060355040a0c08504552534f4e414c310b3009060355040b0c024954310c300a06035504030c034e564b311a301806092a864886f70d010901160b616263406162632e636f6d301e170d3231313031363136323030375a170d3331313031343136323030375a3071310b300906035504061302434e310b300906035504080c024744310b300906035504070c02475a3111300f060355040a0c08504552534f4e414c310b3009060355040b0c024954310c300a06035504030c034e564b311a301806092a864886f70d010901160b616263406162632e636f6d30820222300d06092a864886f70d01010105000382020f003082020a0282020100d06018ad32730263f90fee523ec1915f2faf9760f5016332a3999412d23b4a750219128d11da71edf65a3e2cd99e344aa338344f4ef947b7c2bd4c838cf9ab0bfcd17a57675abb752229387150aad9a9c390ba761bf3c857a166ced0aeb3a4cf1df06d795b27a722e4c01e6b956b4be83558ded95aabc5897bef2c53ac421141921232ffc68096c05858197e7bb898d2131932c6158df17a27943902e2711ff71da31d821fec4518f10afc185d2faf28c3b6c46248c8469e544354e6bd331a3283610a2dafe9a99924ea5579960127fab746d563f1880235e393ad64bdc3fee848a6a283fca008be1a93ccc736d6deb56476c6ea1a930470841d66b16da598e41b7f8432568c50df8d697cd5b72a3a44ed60f9daadbfde406cfed06c3d02d1464f361d784190abfb816445d9017c04b45d836baa67f7e04d457076400cc678e8bfd0b640eddb5206c746d4ae4be36e2414a225672691747a60221b4eef44eba4ca2f57156ce1d78d9f7245b08b753e2cb07f6b20c6b050ea0d5596916490311d846eaa334f0ae9ad72734409c7cf50f1ed105de75a1c2f2cd8619d01e5b0ff5ba88d2f86de1062514f77edf8f51ba5e4dc5c8a3e967cc1394205f7d5f6a01fc97e9eb4ea4802fb7acfefa53055f1c5d3a0b4bf90bcb34fe530042fe986977a09948b3fbd42a5cface4f44915062305d725ebcc893aad1526d1716208495e0b270203010001a3533051301d0603551d0e0416041443321177bab90cae298ce9c2ae1e79fef77faeff301f0603551d2304183016801443321177bab90cae298ce9c2ae1e79fef77faeff300f0603551d130101ff040530030101ff300d06092a864886f70d01010b050003820201009701b1b80680108a25360918f6d236be74b66edab714b238c029c30e6fbfef2e45c66b0e1e2aa58de3d9edada6bec4d9ad9c30a94c754a1bae7ac2c90091104581cb4b954ff3fc7c054af55f65a74f6ee5794baeb51fac63334a101736eafa9dd10a012de012263844112ac704f799af7dc55970863890df32ed705ef422303ab08141d6f74dc9df68f9d2e6504e83f90afc4f18d4c223db582e4a23c65c26d66d30b993c8ca808ebf44cf9a3694d8468ae7af82c28ea5ad989d0fd34946cbba354d49e4b5a1f13dc264c7c238bc265a4c115c86e010702ee9f677f4e9fc233ef64daf8ffb10407a4125525f16a4bdae4ebd6cc9d33638b6afa57f948d1e0efe77d4ce34bab97678e99fca49345823be8b62f600389cf13f08e17dad6c8abcca6a087603822ae7f24eff42822fdb0cfc23468716f5ed51897c8b9c1c87a7f383344202c7c4345020b44dfd203ff7c95d635f17b9fdcb58d79f18dfaa65e0dfe022ccb9a906b2169ff2916b53e46fdf78332917a68c21ff8755207e753ab13ca963af1a32ad2d6d180f6f89c5c0e90619192f34eb23c27acc72c4a476245bda3677c6e4f3d1ad34db45da00090c647d0318327dfda5ec7997042ee6de415c3358019e5e221451796772f3783b79fdac2dafd42658356f8f65dd2662c04ab59b95088e583fe0d0ad997e54fa68f4bb22becea09a1f4e6358e73bdc1c35c30314a00000 } }
2022-12-23 23:07:03.825 [quinn_server] [tls13.rs:826] [T] sending certificate-verify Message { version: TLSv1_3, payload: Handshake { parsed: HandshakeMessagePayload { typ: CertificateVerify, payload: CertificateVerify(DigitallySignedStruct { scheme: RSA_PSS_SHA512, sig: 6d23ec3046d3ea9ddaf3d76aaa39d7c4ef5b227147d5847e32b51006bf1e6840e992e08612c4fb28720edde8937e82dbc959c05532d385851ac6f45bf8509b5a851b1292fe2135a7c32cd4b01162053f4b3ba3021f332a1a82c5b00637f1e800d8a6686d376de4811b42a345bb08cd71b8336083f963a8984917f86a6a92b00c8bdc5d06921f8ab22b8d2a92cdfb7e9cfaadae019bc48ffd4e0ead06526dac9d3a6001b480e11189258f8890aa32719f3f3d2d275d3367a6600afb825c3b8e7cd6cadd2b275c0ea0df06f4966f5ef50d45ae86383b2b96dae69cdc7426aebd10eecf28eb7ab604f49436162d054a400cdc2c336df2997f26d1c7fd290c1209d0ba6edcab568caaffdf2f7d55528d8e54a619fe48a6f26ad843ad5c2d50bb6fcf5c0f1b343fa11d7d2bd6f0fb045f85a4c62d279aa925578966aa80e0e561335fe5eab2bcdd32bca1a75257ab5fad7d30cc5db472f2bb34cce05d86f34e8eab6d71c3a931108f4576e576cef387698effb9eae6eca6b976d68727bdfc0cbcd79bab76d1524c5eea456ec35abccdee6b0d112455a5c7030c02edcdce6ad4e4e1e7df45d07621818c9bba9367d6c67cb3304e71c883c76995423aa03cb6c94fcb8803d1f832ca0abcdac47feb1a0f0822bed192c205e130809e7a949f5d53ef81c05fc8d2b90686b69c9d9cada822dfbcc1cfd68e89d9f86ab9665ea704d386abdf }) }, encoded: 0f000204080602006d23ec3046d3ea9ddaf3d76aaa39d7c4ef5b227147d5847e32b51006bf1e6840e992e08612c4fb28720edde8937e82dbc959c05532d385851ac6f45bf8509b5a851b1292fe2135a7c32cd4b01162053f4b3ba3021f332a1a82c5b00637f1e800d8a6686d376de4811b42a345bb08cd71b8336083f963a8984917f86a6a92b00c8bdc5d06921f8ab22b8d2a92cdfb7e9cfaadae019bc48ffd4e0ead06526dac9d3a6001b480e11189258f8890aa32719f3f3d2d275d3367a6600afb825c3b8e7cd6cadd2b275c0ea0df06f4966f5ef50d45ae86383b2b96dae69cdc7426aebd10eecf28eb7ab604f49436162d054a400cdc2c336df2997f26d1c7fd290c1209d0ba6edcab568caaffdf2f7d55528d8e54a619fe48a6f26ad843ad5c2d50bb6fcf5c0f1b343fa11d7d2bd6f0fb045f85a4c62d279aa925578966aa80e0e561335fe5eab2bcdd32bca1a75257ab5fad7d30cc5db472f2bb34cce05d86f34e8eab6d71c3a931108f4576e576cef387698effb9eae6eca6b976d68727bdfc0cbcd79bab76d1524c5eea456ec35abccdee6b0d112455a5c7030c02edcdce6ad4e4e1e7df45d07621818c9bba9367d6c67cb3304e71c883c76995423aa03cb6c94fcb8803d1f832ca0abcdac47feb1a0f0822bed192c205e130809e7a949f5d53ef81c05fc8d2b90686b69c9d9cada822dfbcc1cfd68e89d9f86ab9665ea704d386abdf } }
2022-12-23 23:07:03.825 [quinn_server] [tls13.rs:852] [T] sending finished Message { version: TLSv1_3, payload: Handshake { parsed: HandshakeMessagePayload { typ: Finished, payload: Finished(c728894d48bfd1294ad226f941d3992bd9dd01735fd41ea20597c0160a863cd8) }, encoded: 14000020c728894d48bfd1294ad226f941d3992bd9dd01735fd41ea20597c0160a863cd8 } }

Trace logs of the client:

2022-12-23 23:07:03.807 [quinn_client] [client.rs:83] [I] connecting, idle_timeout:150000, retry_timeout:5000, threads:1
2022-12-23 23:07:03.808 [quinn_client] [client.rs:480] [I] preparing...
2022-12-23 23:07:03.808 [quinn_client] [client.rs:492] [I] client state: Preparing
2022-12-23 23:07:03.808 [quinn_client] [poll.rs:521] [T] registering event source with poller: token=Token(0), interests=READABLE
2022-12-23 23:07:03.809 [quinn_client] [client.rs:480] [I] starting access server for [TunnelOut] tunneling: 0.0.0.0:9911
2022-12-23 23:07:03.809 [quinn_client] [access_server.rs:30] [I] starting access server, addr: 0.0.0.0:9911
2022-12-23 23:07:03.809 [quinn_client] [poll.rs:521] [T] registering event source with poller: token=Token(1), interests=READABLE | WRITABLE
2022-12-23 23:07:03.809 [quinn_client] [access_server.rs:32] [I] started access server, addr: 0.0.0.0:9911
2022-12-23 23:07:03.809 [quinn_client] [client.rs:492] [I] client state: Connecting
2022-12-23 23:07:03.810 [quinn_client] [poll.rs:521] [T] registering event source with poller: token=Token(2), interests=READABLE | WRITABLE
2022-12-23 23:07:03.810 [quinn_client] [client.rs:480] [I] connecting to 0.0.0.0:3515, local_addr: 0.0.0.0:59239
2022-12-23 23:07:03.811 [quinn_client] [hs.rs:55] [D] No cached session for DnsName(DnsName(DnsName("localhost")))
2022-12-23 23:07:03.811 [quinn_client] [hs.rs:127] [D] Not resuming any session
2022-12-23 23:07:03.811 [quinn_client] [hs.rs:377] [T] Sending ClientHello Message {
    version: TLSv1_0,
    payload: Handshake {
        parsed: HandshakeMessagePayload {
            typ: ClientHello,
            payload: ClientHello(
                ClientHelloPayload {
                    client_version: TLSv1_2,
                    random: 7a1eb7a09b6402f4c8b6bcef593adf158eb1df7cc43529dff8e275728f054dc1,
                    session_id: ,
                    cipher_suites: [
                        TLS13_AES_256_GCM_SHA384,
                        TLS13_AES_128_GCM_SHA256,
                        TLS13_CHACHA20_POLY1305_SHA256,
                        TLS_ECDHE_ECDSA_WITH_AES_256_GCM_SHA384,
                        TLS_ECDHE_ECDSA_WITH_AES_128_GCM_SHA256,
                        TLS_ECDHE_ECDSA_WITH_CHACHA20_POLY1305_SHA256,
                        TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384,
                        TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256,
                        TLS_ECDHE_RSA_WITH_CHACHA20_POLY1305_SHA256,
                        TLS_EMPTY_RENEGOTIATION_INFO_SCSV,
                    ],
                    compression_methods: [
                        Null,
                    ],
                    extensions: [
                        SupportedVersions(
                            [
                                TLSv1_3,
                            ],
                        ),
                        ECPointFormats(
                            [
                                Uncompressed,
                            ],
                        ),
                        NamedGroups(
                            [
                                X25519,
                                secp256r1,
                                secp384r1,
                            ],
                        ),
                        SignatureAlgorithms(
                            [
                                ECDSA_NISTP384_SHA384,
                                ECDSA_NISTP256_SHA256,
                                ED25519,
                                RSA_PSS_SHA512,
                                RSA_PSS_SHA384,
                                RSA_PSS_SHA256,
                                RSA_PKCS1_SHA512,
                                RSA_PKCS1_SHA384,
                                RSA_PKCS1_SHA256,
                            ],
                        ),
                        ExtendedMasterSecretRequest,
                        CertificateStatusRequest(
                            OCSP(
                                OCSPCertificateStatusRequest {
                                    responder_ids: [],
                                    extensions: ,
                                },
                            ),
                        ),
                        ServerName(
                            [
                                ServerName {
                                    typ: HostName,
                                    payload: HostName(
                                        (
                                            6c6f63616c686f7374,
                                            DnsName(
                                                "localhost",
                                            ),
                                        ),
                                    ),
                                },
                            ],
                        ),
                        SignedCertificateTimestampRequest,
                        KeyShare(
                            [
                                KeyShareEntry {
                                    group: X25519,
                                    payload: 2f01bff7f49d40426014d687cf888e4782d778dc8ce351b585cf00a28173a04c,
                                },
                            ],
                        ),
                        PresharedKeyModes(
                            [
                                PSK_DHE_KE,
                            ],
                        ),
                        TransportParameters(
                            [
                                1,
                                4,
                                128,
                                2,
                                73,
                                240,
                                3,
                                2,
                                69,
                                200,
                                4,
                                4,
                                128,
                                16,
                                0,
                                0,
                                5,
                                4,
                                128,
                                19,
                                18,
                                208,
                                6,
                                4,
                                128,
                                19,
                                18,
                                208,
                                7,
                                4,
                                128,
                                19,
                                18,
                                208,
                                8,
                                2,
                                68,
                                0,
                                9,
                                2,
                                64,
                                100,
                                14,
                                1,
                                5,
                                64,
                                182,
                                0,
                                32,
                                4,
                                128,
                                0,
                                255,
                                255,
                                15,
                                8,
                                254,
                                138,
                                178,
                                148,
                                45,
                                184,
                                172,
                                132,
                                106,
                                178,
                                0,
                            ],
                        ),
                        SessionTicket(
                            Request,
                        ),
                    ],
                },
            ),
        },
        encoded: 0100010c03037a1eb7a09b6402f4c8b6bcef593adf158eb1df7cc43529dff8e275728f054dc1000014130213011303c02cc02bcca9c030c02fcca800ff010000cf002b0003020304000b00020100000a00080006001d00170018000d00140012050304030807080608050804060105010401001700000005000501000000000000000e000c0000096c6f63616c686f737400120000003300260024001d00202f01bff7f49d40426014d687cf888e4782d778dc8ce351b585cf00a28173a04c002d00020101003900430104800249f0030245c80404801000000504801312d00604801312d00704801312d008024400090240640e010540b60020048000ffff0f08fe8ab2942db8ac846ab20000230000,
    },
}

And here is the pcap file:
quinn-wont-connect.pcap.zip

@Ralith
Copy link
Collaborator

Ralith commented Dec 23, 2022

Thanks! From the pcap, it looks like the server is responding to the client's connection attempt, but the client is not acting on that response.

Those trace logs don't have the logs from quinn itself. I'll need that (or a repro) to diagnose further. Quinn logs via tracing, so make sure you have that hooked up to whatever log sink you're using. If you're currently using log crate based infrastructure, you could e.g. enable the log feature on tracing (https://docs.rs/tracing/latest/tracing/#crate-feature-flags). Maybe we should be doing that ourselves by default...

@Ralith Ralith mentioned this issue Dec 23, 2022
Merged
@dzvon
Copy link
Contributor

dzvon commented Dec 24, 2022 •
edited
Loading

@neevek Does your client and server both run locally? We should first rule out any network infrastructure issues.

@neevek
Copy link
Author

neevek commented Dec 24, 2022 •
edited
Loading

@dzvon @Ralith
Thank you for the reply.
I tested the client and server in different network setup, either run locally or the server runs remotely, but still can't get them connected.

But this time I see some different result when I change the IP used to connect to the server, the following are the logs of two connect attempts using different server IP, 0.0.0.0 and 127.0.0.1:

When both the client and server run locally, server listens on 0.0.0.0, that client connects to it using 0.0.0.0 hangs without passing the handshake phase.

When connecting to the server using 127.0.0.1, handshake succeeds, a connection is created and a stream is opened, the client successfully sends a message to the server, the server calls RecvStream::read_exact() to read first 4 bytes as the message length, but never returns (Note the message is guaranteed to be longer than 4 bytes and this code works with the old version).

With server IP 0.0.0.0:

>>>>>>>>>> Logs from the client <<<<<<<<<<<

2022-12-24T03:03:55.362113Z  INFO rstun::client: connecting, idle_timeout:150000, retry_timeout:5000, threads:1
2022-12-24T03:03:55.362157Z  INFO rstun::client: preparing...
2022-12-24T03:03:55.363434Z  INFO rstun::client: client state: Preparing
2022-12-24T03:03:55.365296Z TRACE mio::poll: registering event source with poller: token=Token(0), interests=READABLE
2022-12-24T03:03:55.365749Z  INFO rstun::client: starting access server for [TunnelOut] tunneling: 0.0.0.0:9911
2022-12-24T03:03:55.366140Z  INFO rstun::access_server: starting access server, addr: 0.0.0.0:9911
2022-12-24T03:03:55.366801Z TRACE mio::poll: registering event source with poller: token=Token(1), interests=READABLE | WRITABLE
2022-12-24T03:03:55.366843Z  INFO rstun::access_server: started access server, addr: 0.0.0.0:9911
2022-12-24T03:03:55.367048Z  INFO rstun::client: client state: Connecting
2022-12-24T03:03:55.370791Z TRACE mio::poll: registering event source with poller: token=Token(2), interests=READABLE | WRITABLE
2022-12-24T03:03:55.370998Z  INFO rstun::client: connecting to 0.0.0.0:3515, local_addr: 0.0.0.0:64363
2022-12-24T03:03:55.371063Z TRACE quinn_proto::endpoint: initial_dcid=67c132df24a5dd12af026b3f59e38630c80e7012
2022-12-24T03:03:55.371421Z DEBUG rustls::client::hs: No cached session for DnsName(DnsName(DnsName("localhost")))
2022-12-24T03:03:55.371607Z DEBUG rustls::client::hs: Not resuming any session
2022-12-24T03:03:55.371877Z TRACE rustls::client::hs: Sending ClientHello Message {
    version: TLSv1_0,
    payload: Handshake {
        parsed: HandshakeMessagePayload {
            typ: ClientHello,
            payload: ClientHello(
                ClientHelloPayload {
                    client_version: TLSv1_2,
                    random: cd09acea34c0d012bdd5dcdad974e741d70d5cc83a12adbe9d104b0278c8f180,
                    session_id: ,
                    cipher_suites: [
                        TLS13_AES_256_GCM_SHA384,
                        TLS13_AES_128_GCM_SHA256,
                        TLS13_CHACHA20_POLY1305_SHA256,
                        TLS_ECDHE_ECDSA_WITH_AES_256_GCM_SHA384,
                        TLS_ECDHE_ECDSA_WITH_AES_128_GCM_SHA256,
                        TLS_ECDHE_ECDSA_WITH_CHACHA20_POLY1305_SHA256,
                        TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384,
                        TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256,
                        TLS_ECDHE_RSA_WITH_CHACHA20_POLY1305_SHA256,
                        TLS_EMPTY_RENEGOTIATION_INFO_SCSV,
                    ],
                    compression_methods: [
                        Null,
                    ],
                    extensions: [
                        SupportedVersions(
                            [
                                TLSv1_3,
                            ],
                        ),
                        ECPointFormats(
                            [
                                Uncompressed,
                            ],
                        ),
                        NamedGroups(
                            [
                                X25519,
                                secp256r1,
                                secp384r1,
                            ],
                        ),
                        SignatureAlgorithms(
                            [
                                ECDSA_NISTP384_SHA384,
                                ECDSA_NISTP256_SHA256,
                                ED25519,
                                RSA_PSS_SHA512,
                                RSA_PSS_SHA384,
                                RSA_PSS_SHA256,
                                RSA_PKCS1_SHA512,
                                RSA_PKCS1_SHA384,
                                RSA_PKCS1_SHA256,
                            ],
                        ),
                        ExtendedMasterSecretRequest,
                        CertificateStatusRequest(
                            OCSP(
                                OCSPCertificateStatusRequest {
                                    responder_ids: [],
                                    extensions: ,
                                },
                            ),
                        ),
                        ServerName(
                            [
                                ServerName {
                                    typ: HostName,
                                    payload: HostName(
                                        (
                                            6c6f63616c686f7374,
                                            DnsName(
                                                "localhost",
                                            ),
                                        ),
                                    ),
                                },
                            ],
                        ),
                        SignedCertificateTimestampRequest,
                        KeyShare(
                            [
                                KeyShareEntry {
                                    group: X25519,
                                    payload: 942f689ef33de8eef6760f8802e6e6e37990395820ee5afeb64f9fe7a9d87236,
                                },
                            ],
                        ),
                        PresharedKeyModes(
                            [
                                PSK_DHE_KE,
                            ],
                        ),
                        TransportParameters(
                            [
                                1,
                                4,
                                128,
                                2,
                                73,
                                240,
                                3,
                                2,
                                69,
                                200,
                                4,
                                4,
                                128,
                                16,
                                0,
                                0,
                                5,
                                4,
                                128,
                                19,
                                18,
                                208,
                                6,
                                4,
                                128,
                                19,
                                18,
                                208,
                                7,
                                4,
                                128,
                                19,
                                18,
                                208,
                                8,
                                2,
                                68,
                                0,
                                9,
                                2,
                                64,
                                100,
                                14,
                                1,
                                5,
                                64,
                                182,
                                0,
                                32,
                                4,
                                128,
                                0,
                                255,
                                255,
                                15,
                                8,
                                97,
                                158,
                                197,
                                143,
                                42,
                                5,
                                129,
                                59,
                                106,
                                178,
                                0,
                            ],
                        ),
                        SessionTicket(
                            Request,
                        ),
                    ],
                },
            ),
        },
        encoded: 0100010c0303cd09acea34c0d012bdd5dcdad974e741d70d5cc83a12adbe9d104b0278c8f180000014130213011303c02cc02bcca9c030c02fcca800ff010000cf002b0003020304000b00020100000a00080006001d00170018000d00140012050304030807080608050804060105010401001700000005000501000000000000000e000c0000096c6f63616c686f737400120000003300260024001d0020942f689ef33de8eef6760f8802e6e6e37990395820ee5afeb64f9fe7a9d87236002d00020101003900430104800249f0030245c80404801000000504801312d00604801312d00704801312d008024400090240640e010540b60020048000ffff0f08619ec58f2a05813b6ab20000230000,
    },
}
2022-12-24T03:03:55.374054Z TRACE quinn_proto::connection: wrote 272 Initial CRYPTO bytes
2022-12-24T03:03:55.374225Z TRACE drive{id=0}:send{space=Initial pn=0}: quinn_proto::connection: CRYPTO: off 0 len 272
2022-12-24T03:03:55.374251Z TRACE drive{id=0}:send{space=Initial pn=0}: quinn_proto::connection::packet_builder: PADDING * 869
2022-12-24T03:03:55.374339Z TRACE drive{id=0}: quinn_proto::connection: sending 1200 bytes in 1 datagrams
2022-12-24T03:03:55.387250Z TRACE drive{id=0}: quinn_proto::connection: discarding packet from unrecognized peer 127.0.0.1:3515
2022-12-24T03:03:55.387324Z TRACE drive{id=0}: quinn_proto::connection: discarding packet from unrecognized peer 127.0.0.1:3515
2022-12-24T03:03:55.387369Z TRACE drive{id=0}: quinn_proto::connection: discarding packet from unrecognized peer 127.0.0.1:3515
2022-12-24T03:03:55.387408Z TRACE drive{id=0}: quinn_proto::connection: discarding packet from unrecognized peer 127.0.0.1:3515
2022-12-24T03:03:56.375128Z TRACE drive{id=0}: quinn_proto::connection: timeout timer=LossDetection
2022-12-24T03:03:56.375320Z TRACE drive{id=0}: quinn_proto::connection: PTO fired in_flight=1200 count=0 space=Initial
2022-12-24T03:03:56.375893Z TRACE drive{id=0}:send{space=Initial pn=1}: quinn_proto::connection: CRYPTO: off 0 len 272
2022-12-24T03:03:56.376041Z TRACE drive{id=0}:send{space=Initial pn=1}: quinn_proto::connection::packet_builder: PADDING * 869
2022-12-24T03:03:56.376392Z TRACE drive{id=0}: quinn_proto::connection: sending 1200 bytes in 1 datagrams
2022-12-24T03:03:56.376567Z TRACE drive{id=0}:send{space=Initial pn=2}: quinn_proto::connection: CRYPTO: off 0 len 272
2022-12-24T03:03:56.376673Z TRACE drive{id=0}:send{space=Initial pn=2}: quinn_proto::connection::packet_builder: PADDING * 869
2022-12-24T03:03:56.386437Z TRACE drive{id=0}: quinn_proto::connection: sending 1200 bytes in 1 datagrams
2022-12-24T03:03:56.387690Z TRACE drive{id=0}: quinn_proto::connection: discarding packet from unrecognized peer 127.0.0.1:3515
2022-12-24T03:03:56.387748Z TRACE drive{id=0}: quinn_proto::connection: discarding packet from unrecognized peer 127.0.0.1:3515
2022-12-24T03:03:56.387842Z TRACE drive{id=0}: quinn_proto::connection: discarding packet from unrecognized peer 127.0.0.1:3515
2022-12-24T03:03:57.387374Z TRACE drive{id=0}: quinn_proto::connection: discarding packet from unrecognized peer 127.0.0.1:3515
2022-12-24T03:03:57.387598Z TRACE drive{id=0}: quinn_proto::connection: discarding packet from unrecognized peer 127.0.0.1:3515
2022-12-24T03:03:58.375035Z TRACE drive{id=0}: quinn_proto::connection: timeout timer=LossDetection
2022-12-24T03:03:58.375184Z TRACE drive{id=0}: quinn_proto::connection: PTO fired in_flight=3600 count=1 space=Initial
2022-12-24T03:03:58.375564Z TRACE drive{id=0}:send{space=Initial pn=3}: quinn_proto::connection: CRYPTO: off 0 len 272
2022-12-24T03:03:58.375686Z TRACE drive{id=0}:send{space=Initial pn=3}: quinn_proto::connection::packet_builder: PADDING * 869
2022-12-24T03:03:58.376030Z TRACE drive{id=0}: quinn_proto::connection: sending 1200 bytes in 1 datagrams
2022-12-24T03:03:58.376204Z TRACE drive{id=0}:send{space=Initial pn=4}: quinn_proto::connection: CRYPTO: off 0 len 272
2022-12-24T03:03:58.376309Z TRACE drive{id=0}:send{space=Initial pn=4}: quinn_proto::connection::packet_builder: PADDING * 869
2022-12-24T03:03:58.376624Z TRACE drive{id=0}: quinn_proto::connection: sending 1200 bytes in 1 datagrams
2022-12-24T03:03:58.379609Z TRACE drive{id=0}: quinn_proto::connection: discarding packet from unrecognized peer 127.0.0.1:3515
2022-12-24T03:03:58.380527Z TRACE drive{id=0}: quinn_proto::connection: discarding packet from unrecognized peer 127.0.0.1:3515
2022-12-24T03:04:00.387266Z TRACE drive{id=0}: quinn_proto::connection: discarding packet from unrecognized peer 127.0.0.1:3515
2022-12-24T03:04:00.387574Z TRACE drive{id=0}: quinn_proto::connection: discarding packet from unrecognized peer 127.0.0.1:3515
2022-12-24T03:04:02.374304Z TRACE drive{id=0}: quinn_proto::connection: timeout timer=LossDetection
2022-12-24T03:04:02.374492Z TRACE drive{id=0}: quinn_proto::connection: PTO fired in_flight=6000 count=2 space=Initial
2022-12-24T03:04:02.374916Z TRACE drive{id=0}:send{space=Initial pn=5}: quinn_proto::connection: CRYPTO: off 0 len 272
2022-12-24T03:04:02.375075Z TRACE drive{id=0}:send{space=Initial pn=5}: quinn_proto::connection::packet_builder: PADDING * 869
2022-12-24T03:04:02.375414Z TRACE drive{id=0}: quinn_proto::connection: sending 1200 bytes in 1 datagrams
2022-12-24T03:04:02.375598Z TRACE drive{id=0}:send{space=Initial pn=6}: quinn_proto::connection: CRYPTO: off 0 len 272
2022-12-24T03:04:02.375704Z TRACE drive{id=0}:send{space=Initial pn=6}: quinn_proto::connection::packet_builder: PADDING * 869
2022-12-24T03:04:02.376328Z TRACE drive{id=0}: quinn_proto::connection: sending 1200 bytes in 1 datagrams
2022-12-24T03:04:02.378989Z TRACE drive{id=0}: quinn_proto::connection: discarding packet from unrecognized peer 127.0.0.1:3515
2022-12-24T03:04:02.379977Z TRACE drive{id=0}: quinn_proto::connection: discarding packet from unrecognized peer 127.0.0.1:3515
2022-12-24T03:04:05.382104Z TRACE drive{id=0}: quinn_proto::connection: discarding packet from unrecognized peer 127.0.0.1:3515
2022-12-24T03:04:05.382364Z TRACE drive{id=0}: quinn_proto::connection: discarding packet from unrecognized peer 127.0.0.1:3515
2022-12-24T03:04:10.368994Z TRACE drive{id=0}: quinn_proto::connection: timeout timer=LossDetection
2022-12-24T03:04:10.369190Z TRACE drive{id=0}: quinn_proto::connection: PTO fired in_flight=8400 count=3 space=Initial
2022-12-24T03:04:10.369620Z TRACE drive{id=0}:send{space=Initial pn=7}: quinn_proto::connection: CRYPTO: off 0 len 272
2022-12-24T03:04:10.369751Z TRACE drive{id=0}:send{space=Initial pn=7}: quinn_proto::connection::packet_builder: PADDING * 869
2022-12-24T03:04:10.370103Z TRACE drive{id=0}: quinn_proto::connection: sending 1200 bytes in 1 datagrams
2022-12-24T03:04:10.370288Z TRACE drive{id=0}:send{space=Initial pn=8}: quinn_proto::connection: CRYPTO: off 0 len 272
2022-12-24T03:04:10.370394Z TRACE drive{id=0}:send{space=Initial pn=8}: quinn_proto::connection::packet_builder: PADDING * 869
2022-12-24T03:04:10.371230Z TRACE drive{id=0}: quinn_proto::connection: sending 1200 bytes in 1 datagrams
2022-12-24T03:04:10.374595Z TRACE drive{id=0}: quinn_proto::connection: discarding packet from unrecognized peer 127.0.0.1:3515
2022-12-24T03:04:10.374968Z TRACE drive{id=0}: quinn_proto::connection: discarding packet from unrecognized peer 127.0.0.1:3515


>>>>>>>>>> Logs from the server <<<<<<<<<<<

2022-12-24T03:03:46.168416Z TRACE mio::poll: registering event source with poller: token=Token(0), interests=READABLE
2022-12-24T03:03:46.174016Z TRACE mio::poll: registering event source with poller: token=Token(1), interests=READABLE | WRITABLE
2022-12-24T03:03:46.174318Z  INFO rstun::server: server is bound to: 0.0.0.0:3515, idle_timeout: 40000
2022-12-24T03:03:55.376812Z TRACE first recv:frame{ty=CRYPTO}: quinn_proto::connection: consumed 272 CRYPTO bytes
2022-12-24T03:03:55.376965Z TRACE first recv:frame{ty=CRYPTO}: rustls::server::hs: we got a clienthello ClientHelloPayload { client_version: TLSv1_2, random: cd09acea34c0d012bdd5dcdad974e741d70d5cc83a12adbe9d104b0278c8f180, session_id: , cipher_suites: [TLS13_AES_256_GCM_SHA384, TLS13_AES_128_GCM_SHA256, TLS13_CHACHA20_POLY1305_SHA256, TLS_ECDHE_ECDSA_WITH_AES_256_GCM_SHA384, TLS_ECDHE_ECDSA_WITH_AES_128_GCM_SHA256, TLS_ECDHE_ECDSA_WITH_CHACHA20_POLY1305_SHA256, TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384, TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256, TLS_ECDHE_RSA_WITH_CHACHA20_POLY1305_SHA256, TLS_EMPTY_RENEGOTIATION_INFO_SCSV], compression_methods: [Null], extensions: [SupportedVersions([TLSv1_3]), ECPointFormats([Uncompressed]), NamedGroups([X25519, secp256r1, secp384r1]), SignatureAlgorithms([ECDSA_NISTP384_SHA384, ECDSA_NISTP256_SHA256, ED25519, RSA_PSS_SHA512, RSA_PSS_SHA384, RSA_PSS_SHA256, RSA_PKCS1_SHA512, RSA_PKCS1_SHA384, RSA_PKCS1_SHA256]), ExtendedMasterSecretRequest, CertificateStatusRequest(OCSP(OCSPCertificateStatusRequest { responder_ids: [], extensions:  })), ServerName([ServerName { typ: HostName, payload: HostName((6c6f63616c686f7374, DnsName("localhost"))) }]), SignedCertificateTimestampRequest, KeyShare([KeyShareEntry { group: X25519, payload: 942f689ef33de8eef6760f8802e6e6e37990395820ee5afeb64f9fe7a9d87236 }]), PresharedKeyModes([PSK_DHE_KE]), TransportParameters([1, 4, 128, 2, 73, 240, 3, 2, 69, 200, 4, 4, 128, 16, 0, 0, 5, 4, 128, 19, 18, 208, 6, 4, 128, 19, 18, 208, 7, 4, 128, 19, 18, 208, 8, 2, 68, 0, 9, 2, 64, 100, 14, 1, 5, 64, 182, 0, 32, 4, 128, 0, 255, 255, 15, 8, 97, 158, 197, 143, 42, 5, 129, 59, 106, 178, 0]), SessionTicket(Request)] }
2022-12-24T03:03:55.377080Z TRACE first recv:frame{ty=CRYPTO}: rustls::server::server_conn: sni Some(DnsName("localhost"))
2022-12-24T03:03:55.377098Z TRACE first recv:frame{ty=CRYPTO}: rustls::server::server_conn: sig schemes [ECDSA_NISTP384_SHA384, ECDSA_NISTP256_SHA256, ED25519, RSA_PSS_SHA512, RSA_PSS_SHA384, RSA_PSS_SHA256, RSA_PKCS1_SHA512, RSA_PKCS1_SHA384, RSA_PKCS1_SHA256]
2022-12-24T03:03:55.377115Z TRACE first recv:frame{ty=CRYPTO}: rustls::server::server_conn: alpn protocols None
2022-12-24T03:03:55.377129Z TRACE first recv:frame{ty=CRYPTO}: rustls::server::server_conn: cipher suites [TLS13_AES_256_GCM_SHA384, TLS13_AES_128_GCM_SHA256, TLS13_CHACHA20_POLY1305_SHA256, TLS_ECDHE_ECDSA_WITH_AES_256_GCM_SHA384, TLS_ECDHE_ECDSA_WITH_AES_128_GCM_SHA256, TLS_ECDHE_ECDSA_WITH_CHACHA20_POLY1305_SHA256, TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384, TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256, TLS_ECDHE_RSA_WITH_CHACHA20_POLY1305_SHA256, TLS_EMPTY_RENEGOTIATION_INFO_SCSV]   
2022-12-24T03:03:55.377152Z DEBUG first recv:frame{ty=CRYPTO}: rustls::server::hs: decided upon suite TLS13_CHACHA20_POLY1305_SHA256
2022-12-24T03:03:55.377327Z TRACE first recv:frame{ty=CRYPTO}: rustls::server::tls13::client_hello: sending server hello Message { version: TLSv1_2, payload: Handshake { parsed: HandshakeMessagePayload { typ: ServerHello, payload: ServerHello(ServerHelloPayload { legacy_version: TLSv1_2, random: 6c923797eff52fc4af1b673c3dd011324982f426f7ecd49f7adc62433e2298d9, session_id: , cipher_suite: TLS13_CHACHA20_POLY1305_SHA256, compression_method: Null, extensions: [KeyShare(KeyShareEntry { group: X25519, payload: 02282e2eff32ed7ea61a7089583f79be70ca4ca1ad27cd71cb10e138fc877208 }), SupportedVersions(TLSv1_3)] }) }, encoded: 0200005603036c923797eff52fc4af1b673c3dd011324982f426f7ecd49f7adc62433e2298d900130300002e00330024001d002002282e2eff32ed7ea61a7089583f79be70ca4ca1ad27cd71cb10e138fc877208002b00020304 } }
2022-12-24T03:03:55.377586Z TRACE first recv:frame{ty=CRYPTO}: rustls::server::tls13::client_hello: sending encrypted extensions Message { version: TLSv1_3, payload: Handshake { parsed: HandshakeMessagePayload { typ: EncryptedExtensions, payload: EncryptedExtensions([ServerNameAck, TransportParameters([1, 4, 128, 0, 156, 64, 3, 2, 69, 200, 4, 4, 128, 16, 0, 0, 5, 4, 128, 19, 18, 208, 6, 4, 128, 19, 18, 208, 7, 4, 128, 19, 18, 208, 8, 2, 68, 0, 9, 2, 64, 100, 14, 1, 5, 64, 182, 0, 2, 16, 79, 160, 214, 212, 231, 58, 70, 33, 83, 249, 188, 39, 200, 47, 235, 230, 32, 4, 128, 0, 255, 255, 0, 20, 103, 193, 50, 223, 36, 165, 221, 18, 175, 2, 107, 63, 89, 227, 134, 48, 200, 14, 112, 18, 15, 8, 47, 0, 49, 140, 103, 117, 11, 104, 106, 178, 0])]) }, encoded: 080000750073000000000039006b010480009c40030245c80404801000000504801312d00604801312d00704801312d008024400090240640e010540b60002104fa0d6d4e73a462153f9bc27c82febe620048000ffff001467c132df24a5dd12af026b3f59e38630c80e70120f082f00318c67750b686ab200 } }
2022-12-24T03:03:55.377650Z TRACE first recv:frame{ty=CRYPTO}: rustls::server::tls13::client_hello: sending certificate Message { version: TLSv1_3, payload: Handshake { parsed: HandshakeMessagePayload { typ: Certificate, payload: CertificateTLS13(CertificatePayloadTLS13 { context: , entries: [CertificateEntry { cert: Certificate(b"0\x82\x05\xc30\x82\x03\xab\xa0\x03\x02\x01\x02\x02\x14R,\xef\xa0\x8f%P\xde\xa26XW\x89\x1d\xdf\xb0\xeb,\xa3\xd90\r\x06\t*\x86H\x86\xf7\r\x01\x01\x0b\x05\00q1\x0b0\t\x06\x03U\x04\x06\x13\x02CN1\x0b0\t\x06\x03U\x04\x08\x0c\x02GD1\x0b0\t\x06\x03U\x04\x07\x0c\x02GZ1\x110\x0f\x06\x03U\x04\n\x0c\x08PERSONAL1\x0b0\t\x06\x03U\x04\x0b\x0c\x02IT1\x0c0\n\x06\x03U\x04\x03\x0c\x03NVK1\x1a0\x18\x06\t*\x86H\x86\xf7\r\x01\t\x01\x16\x0babc@abc.com0\x1e\x17\r211016162007Z\x17\r311014162007Z0q1\x0b0\t\x06\x03U\x04\x06\x13\x02CN1\x0b0\t\x06\x03U\x04\x08\x0c\x02GD1\x0b0\t\x06\x03U\x04\x07\x0c\x02GZ1\x110\x0f\x06\x03U\x04\n\x0c\x08PERSONAL1\x0b0\t\x06\x03U\x04\x0b\x0c\x02IT1\x0c0\n\x06\x03U\x04\x03\x0c\x03NVK1\x1a0\x18\x06\t*\x86H\x86\xf7\r\x01\t\x01\x16\x0babc@abc.com0\x82\x02\"0\r\x06\t*\x86H\x86\xf7\r\x01\x01\x01\x05\0\x03\x82\x02\x0f\00\x82\x02\n\x02\x82\x02\x01\0\xd0`\x18\xad2s\x02c\xf9\x0f\xeeR>\xc1\x91_/\xaf\x97`\xf5\x01c2\xa3\x99\x94\x12\xd2;Ju\x02\x19\x12\x8d\x11\xdaq\xed\xf6Z>,\xd9\x9e4J\xa384ON\xf9G\xb7\xc2\xbdL\x83\x8c\xf9\xab\x0b\xfc\xd1zWgZ\xbbu\")8qP\xaa\xd9\xa9\xc3\x90\xbav\x1b\xf3\xc8W\xa1f\xce\xd0\xae\xb3\xa4\xcf\x1d\xf0my['\xa7\"\xe4\xc0\x1ek\x95kK\xe85X\xde\xd9Z\xab\xc5\x89{\xef,S\xacB\x11A\x92\x122\xff\xc6\x80\x96\xc0XX\x19~{\xb8\x98\xd2\x13\x192\xc6\x15\x8d\xf1z'\x949\x02\xe2q\x1f\xf7\x1d\xa3\x1d\x82\x1f\xecE\x18\xf1\n\xfc\x18]/\xaf(\xc3\xb6\xc4bH\xc8F\x9eTCT\xe6\xbd3\x1a2\x83a\n-\xaf\xe9\xa9\x99$\xeaUy\x96\x01'\xfa\xb7F\xd5c\xf1\x88\x025\xe3\x93\xadd\xbd\xc3\xfe\xe8H\xa6\xa2\x83\xfc\xa0\x08\xbe\x1a\x93\xcc\xc76\xd6\xde\xb5dv\xc6\xea\x1a\x93\x04p\x84\x1df\xb1m\xa5\x98\xe4\x1b\x7f\x842V\x8cP\xdf\x8di|\xd5\xb7*:D\xed`\xf9\xda\xad\xbf\xde@l\xfe\xd0l=\x02\xd1FO6\x1dxA\x90\xab\xfb\x81dE\xd9\x01|\x04\xb4]\x83k\xaag\xf7\xe0MEpv@\x0c\xc6x\xe8\xbf\xd0\xb6@\xed\xdbR\x06\xc7F\xd4\xaeK\xe3n$\x14\xa2%g&\x91tz`\"\x1bN\xefD\xeb\xa4\xca/W\x15l\xe1\xd7\x8d\x9frE\xb0\x8bu>,\xb0\x7fk \xc6\xb0P\xea\rU\x96\x91d\x901\x1d\x84n\xaa3O\n\xe9\xadrsD\t\xc7\xcfP\xf1\xed\x10]\xe7Z\x1c/,\xd8a\x9d\x01\xe5\xb0\xff[\xa8\x8d/\x86\xde\x10bQOw\xed\xf8\xf5\x1b\xa5\xe4\xdc\\\x8a>\x96|\xc19B\x05\xf7\xd5\xf6\xa0\x1f\xc9~\x9e\xb4\xeaH\x02\xfbz\xcf\xef\xa50U\xf1\xc5\xd3\xa0\xb4\xbf\x90\xbc\xb3O\xe50\x04/\xe9\x86\x97z\t\x94\x8b?\xbdB\xa5\xcf\xac\xe4\xf4I\x15\x06#\x05\xd7%\xeb\xcc\x89:\xad\x15&\xd1qb\x08I^\x0b'\x02\x03\x01\0\x01\xa3S0Q0\x1d\x06\x03U\x1d\x0e\x04\x16\x04\x14C2\x11w\xba\xb9\x0c\xae)\x8c\xe9\xc2\xae\x1ey\xfe\xf7\x7f\xae\xff0\x1f\x06\x03U\x1d#\x04\x180\x16\x80\x14C2\x11w\xba\xb9\x0c\xae)\x8c\xe9\xc2\xae\x1ey\xfe\xf7\x7f\xae\xff0\x0f\x06\x03U\x1d\x13\x01\x01\xff\x04\x050\x03\x01\x01\xff0\r\x06\t*\x86H\x86\xf7\r\x01\x01\x0b\x05\0\x03\x82\x02\x01\0\x97\x01\xb1\xb8\x06\x80\x10\x8a%6\t\x18\xf6\xd26\xbet\xb6n\xda\xb7\x14\xb28\xc0)\xc3\x0eo\xbf\xef.E\xc6k\x0e\x1e*\xa5\x8d\xe3\xd9\xed\xad\xa6\xbe\xc4\xd9\xad\x9c0\xa9LuJ\x1b\xaez\xc2\xc9\0\x91\x10E\x81\xcbK\x95O\xf3\xfc|\x05J\xf5_e\xa7On\xe5yK\xae\xb5\x1f\xacc3J\x10\x176\xea\xfa\x9d\xd1\n\x01-\xe0\x12&8D\x11*\xc7\x04\xf7\x99\xaf}\xc5Yp\x868\x90\xdf2\xedp^\xf4\"0:\xb0\x81A\xd6\xf7M\xc9\xdfh\xf9\xd2\xe6PN\x83\xf9\n\xfcO\x18\xd4\xc2#\xdbX.J#\xc6\\&\xd6m0\xb9\x93\xc8\xca\x80\x8e\xbfD\xcf\x9a6\x94\xd8F\x8a\xe7\xaf\x82\xc2\x8e\xa5\xad\x98\x9d\x0f\xd3IF\xcb\xba5MI\xe4\xb5\xa1\xf1=\xc2d\xc7\xc28\xbc&ZL\x11\\\x86\xe0\x10p.\xe9\xf6w\xf4\xe9\xfc#>\xf6M\xaf\x8f\xfb\x10@zA%R_\x16\xa4\xbd\xaeN\xbdl\xc9\xd368\xb6\xaf\xa5\x7f\x94\x8d\x1e\x0e\xfew\xd4\xce4\xba\xb9vx\xe9\x9f\xcaI4X#\xbe\x8bb\xf6\08\x9c\xf1?\x08\xe1}\xadl\x8a\xbc\xcaj\x08v\x03\x82*\xe7\xf2N\xffB\x82/\xdb\x0c\xfc#F\x87\x16\xf5\xedQ\x89|\x8b\x9c\x1c\x87\xa7\xf3\x834B\x02\xc7\xc44P \xb4M\xfd ?\xf7\xc9]c_\x17\xb9\xfd\xcbX\xd7\x9f\x18\xdf\xaae\xe0\xdf\xe0\"\xcc\xb9\xa9\x06\xb2\x16\x9f\xf2\x91kS\xe4o\xdfx3)\x17\xa6\x8c!\xff\x87U ~u:\xb1<\xa9c\xaf\x1a2\xad-m\x18\x0fo\x89\xc5\xc0\xe9\x06\x19\x19/4\xeb#\xc2z\xccr\xc4\xa4v$[\xda6w\xc6\xe4\xf3\xd1\xad4\xdbE\xda\0\t\x0cd}\x03\x182}\xfd\xa5\xecy\x97\x04.\xe6\xdeA\\3X\x01\x9e^\"\x14Qygr\xf3x;y\xfd\xac-\xaf\xd4&X5o\x8fe\xdd&b\xc0J\xb5\x9b\x95\x08\x8eX?\xe0\xd0\xad\x99~T\xfah\xf4\xbb\"\xbe\xce\xa0\x9a\x1fNcX\xe7;\xdc\x1c5\xc3\x03\x14\xa0"), exts: [] }] }) }, encoded: 0b0005d0000005cc0005c7308205c3308203aba0030201020214522cefa08f2550dea2365857891ddfb0eb2ca3d9300d06092a864886f70d01010b05003071310b300906035504061302434e310b300906035504080c024744310b300906035504070c02475a3111300f060355040a0c08504552534f4e414c310b3009060355040b0c024954310c300a06035504030c034e564b311a301806092a864886f70d010901160b616263406162632e636f6d301e170d3231313031363136323030375a170d3331313031343136323030375a3071310b300906035504061302434e310b300906035504080c024744310b300906035504070c02475a3111300f060355040a0c08504552534f4e414c310b3009060355040b0c024954310c300a06035504030c034e564b311a301806092a864886f70d010901160b616263406162632e636f6d30820222300d06092a864886f70d01010105000382020f003082020a0282020100d06018ad32730263f90fee523ec1915f2faf9760f5016332a3999412d23b4a750219128d11da71edf65a3e2cd99e344aa338344f4ef947b7c2bd4c838cf9ab0bfcd17a57675abb752229387150aad9a9c390ba761bf3c857a166ced0aeb3a4cf1df06d795b27a722e4c01e6b956b4be83558ded95aabc5897bef2c53ac421141921232ffc68096c05858197e7bb898d2131932c6158df17a27943902e2711ff71da31d821fec4518f10afc185d2faf28c3b6c46248c8469e544354e6bd331a3283610a2dafe9a99924ea5579960127fab746d563f1880235e393ad64bdc3fee848a6a283fca008be1a93ccc736d6deb56476c6ea1a930470841d66b16da598e41b7f8432568c50df8d697cd5b72a3a44ed60f9daadbfde406cfed06c3d02d1464f361d784190abfb816445d9017c04b45d836baa67f7e04d457076400cc678e8bfd0b640eddb5206c746d4ae4be36e2414a225672691747a60221b4eef44eba4ca2f57156ce1d78d9f7245b08b753e2cb07f6b20c6b050ea0d5596916490311d846eaa334f0ae9ad72734409c7cf50f1ed105de75a1c2f2cd8619d01e5b0ff5ba88d2f86de1062514f77edf8f51ba5e4dc5c8a3e967cc1394205f7d5f6a01fc97e9eb4ea4802fb7acfefa53055f1c5d3a0b4bf90bcb34fe530042fe986977a09948b3fbd42a5cface4f44915062305d725ebcc893aad1526d1716208495e0b270203010001a3533051301d0603551d0e0416041443321177bab90cae298ce9c2ae1e79fef77faeff301f0603551d2304183016801443321177bab90cae298ce9c2ae1e79fef77faeff300f0603551d130101ff040530030101ff300d06092a864886f70d01010b050003820201009701b1b80680108a25360918f6d236be74b66edab714b238c029c30e6fbfef2e45c66b0e1e2aa58de3d9edada6bec4d9ad9c30a94c754a1bae7ac2c90091104581cb4b954ff3fc7c054af55f65a74f6ee5794baeb51fac63334a101736eafa9dd10a012de012263844112ac704f799af7dc55970863890df32ed705ef422303ab08141d6f74dc9df68f9d2e6504e83f90afc4f18d4c223db582e4a23c65c26d66d30b993c8ca808ebf44cf9a3694d8468ae7af82c28ea5ad989d0fd34946cbba354d49e4b5a1f13dc264c7c238bc265a4c115c86e010702ee9f677f4e9fc233ef64daf8ffb10407a4125525f16a4bdae4ebd6cc9d33638b6afa57f948d1e0efe77d4ce34bab97678e99fca49345823be8b62f600389cf13f08e17dad6c8abcca6a087603822ae7f24eff42822fdb0cfc23468716f5ed51897c8b9c1c87a7f383344202c7c4345020b44dfd203ff7c95d635f17b9fdcb58d79f18dfaa65e0dfe022ccb9a906b2169ff2916b53e46fdf78332917a68c21ff8755207e753ab13ca963af1a32ad2d6d180f6f89c5c0e90619192f34eb23c27acc72c4a476245bda3677c6e4f3d1ad34db45da00090c647d0318327dfda5ec7997042ee6de415c3358019e5e221451796772f3783b79fdac2dafd42658356f8f65dd2662c04ab59b95088e583fe0d0ad997e54fa68f4bb22becea09a1f4e6358e73bdc1c35c30314a00000 } }
2022-12-24T03:03:55.385239Z TRACE first recv:frame{ty=CRYPTO}: rustls::server::tls13::client_hello: sending certificate-verify Message { version: TLSv1_3, payload: Handshake { parsed: HandshakeMessagePayload { typ: CertificateVerify, payload: CertificateVerify(DigitallySignedStruct { scheme: RSA_PSS_SHA512, sig: 7ba2675d8124a38e3b3b4e6d6d2ae65f5f9b4402e35ec7cc2527937e50256e8f3aced7ac85dd0f503df8712c6d32edbc021d45a854084256cc0973bca5452864fd927c775a1e155b78d2da08c6d55ee5eb8080e89cd9c32e4cd314cc09823e2f6de312bafd64d797c25d3c6b76fa99a910679e1a9261ad142fe47bd1c643df3a06d286c16f242d9309b92151f719ca9fb5a9eb788279a612ff7cce371cc6bfa212a7b87cd24cbd7ac2dddd87bc77bb3d45ce6cfc5ed44a33bdf40239d7c202151369ab56f64312da4061555e2f0018d07ad4101bb9b24930a0209d990eae8c3986f1c21e7ac10d5369546db19dc4d353402bcfc72a5e78ec8f13adc722560012f2a277ed1edd729b7663dc8111551cf96e60a114dd428074eab160c6ed462b7e6cce62b29fcf2e849930b8604b40de3939db06bc3f91930852a14cf06c6d4c8db1f573040e9d889d579e491be79c82155c1b32c726824bc4843ab97ec54223f33076dbc371d563cfa58350d0e97b84a7e0200046f96d665dd3ffee1c9364896d5d126b6fca0b1ac10cf8c114b38a29212de683c9443bd8baea465804688ef70cd1a784b790ea393519aef0877c310d52ae8104cf0651ea6232b605970b2f02a24481230465a60155a9a7e195a9fe2bfa570ec22f6c3ba021c3689feddbddcd8036599572c7781484aba97780dae7f92cf9c9619d72e7ccca796d8d8a26257df9 }) }, encoded: 0f000204080602007ba2675d8124a38e3b3b4e6d6d2ae65f5f9b4402e35ec7cc2527937e50256e8f3aced7ac85dd0f503df8712c6d32edbc021d45a854084256cc0973bca5452864fd927c775a1e155b78d2da08c6d55ee5eb8080e89cd9c32e4cd314cc09823e2f6de312bafd64d797c25d3c6b76fa99a910679e1a9261ad142fe47bd1c643df3a06d286c16f242d9309b92151f719ca9fb5a9eb788279a612ff7cce371cc6bfa212a7b87cd24cbd7ac2dddd87bc77bb3d45ce6cfc5ed44a33bdf40239d7c202151369ab56f64312da4061555e2f0018d07ad4101bb9b24930a0209d990eae8c3986f1c21e7ac10d5369546db19dc4d353402bcfc72a5e78ec8f13adc722560012f2a277ed1edd729b7663dc8111551cf96e60a114dd428074eab160c6ed462b7e6cce62b29fcf2e849930b8604b40de3939db06bc3f91930852a14cf06c6d4c8db1f573040e9d889d579e491be79c82155c1b32c726824bc4843ab97ec54223f33076dbc371d563cfa58350d0e97b84a7e0200046f96d665dd3ffee1c9364896d5d126b6fca0b1ac10cf8c114b38a29212de683c9443bd8baea465804688ef70cd1a784b790ea393519aef0877c310d52ae8104cf0651ea6232b605970b2f02a24481230465a60155a9a7e195a9fe2bfa570ec22f6c3ba021c3689feddbddcd8036599572c7781484aba97780dae7f92cf9c9619d72e7ccca796d8d8a26257df9 } }  
2022-12-24T03:03:55.385472Z TRACE first recv:frame{ty=CRYPTO}: rustls::server::tls13::client_hello: sending finished Message { version: TLSv1_3, payload: Handshake { parsed: HandshakeMessagePayload { typ: Finished, payload: Finished(98d36950dd2d2f84901644a3cc27c8085e2132c8849e9a60608524597beb9d5c) }, encoded: 1400002098d36950dd2d2f84901644a3cc27c8085e2132c8849e9a60608524597beb9d5c } }
2022-12-24T03:03:55.385708Z TRACE first recv: quinn_proto::connection: Handshake keys ready
2022-12-24T03:03:55.385726Z TRACE first recv: quinn_proto::connection: wrote 90 Initial CRYPTO bytes
2022-12-24T03:03:55.385764Z TRACE first recv: quinn_proto::connection: Data keys ready
2022-12-24T03:03:55.385794Z TRACE first recv: quinn_proto::connection: wrote 2169 Handshake CRYPTO bytes
2022-12-24T03:03:55.386091Z TRACE quinn_proto::endpoint: connection incoming id=0 icid=67c132df24a5dd12af026b3f59e38630c80e7012
2022-12-24T03:03:55.386285Z TRACE drive{id=0}:send{space=Initial pn=0}: quinn_proto::connection: ACK ArrayRangeSet([0..1]), Delay = 0us
2022-12-24T03:03:55.386311Z TRACE drive{id=0}:send{space=Initial pn=0}: quinn_proto::connection: CRYPTO: off 0 len 90
2022-12-24T03:03:55.386589Z TRACE drive{id=0}:send{space=Handshake pn=0}: quinn_proto::connection: CRYPTO: off 0 len 1009
2022-12-24T03:03:55.386635Z TRACE drive{id=0}: quinn_proto::connection: sending 1200 bytes in 1 datagrams
2022-12-24T03:03:55.386666Z TRACE drive{id=0}:send{space=Handshake pn=1}: quinn_proto::connection: CRYPTO: off 1009 len 1153
2022-12-24T03:03:55.386721Z TRACE drive{id=0}: quinn_proto::connection: sending 1200 bytes in 1 datagrams
2022-12-24T03:03:55.386746Z TRACE drive{id=0}:send{space=Handshake pn=2}: quinn_proto::connection: CRYPTO: off 2162 len 7
2022-12-24T03:03:55.386790Z TRACE drive{id=0}: quinn_proto::connection: sending 53 bytes in 1 datagrams
2022-12-24T03:03:55.387023Z TRACE drive{id=0}:send{space=Data pn=0}: quinn_proto::connection: NEW_CONNECTION_ID sequence=1 id=2ddb3f3225404842
2022-12-24T03:03:55.387045Z TRACE drive{id=0}:send{space=Data pn=0}: quinn_proto::connection: NEW_CONNECTION_ID sequence=2 id=f45cf8ec57cffe44
2022-12-24T03:03:55.387064Z TRACE drive{id=0}:send{space=Data pn=0}: quinn_proto::connection: NEW_CONNECTION_ID sequence=3 id=b14bb5e008bc4f0e
2022-12-24T03:03:55.387082Z TRACE drive{id=0}:send{space=Data pn=0}: quinn_proto::connection: NEW_CONNECTION_ID sequence=4 id=1bb52df052b9514c
2022-12-24T03:03:55.387111Z TRACE drive{id=0}: quinn_proto::connection: sending 138 bytes in 1 datagrams
2022-12-24T03:03:56.386906Z TRACE drive{id=0}: quinn_proto::connection: timeout timer=LossDetection
2022-12-24T03:03:56.386935Z TRACE drive{id=0}: quinn_proto::connection: PTO fired in_flight=2591 count=0 space=Initial
2022-12-24T03:03:56.387064Z TRACE drive{id=0}: quinn_proto::connection: got Initial packet (1200 bytes) from 127.0.0.1:64363 using id 67c132df24a5dd12af026b3f59e38630c80e7012
2022-12-24T03:03:56.387319Z TRACE drive{id=0}:send{space=Initial pn=1}: quinn_proto::connection: ACK ArrayRangeSet([0..2]), Delay = 0us
2022-12-24T03:03:56.387341Z TRACE drive{id=0}:send{space=Initial pn=1}: quinn_proto::connection: CRYPTO: off 0 len 90
2022-12-24T03:03:56.387364Z TRACE drive{id=0}:send{space=Initial pn=1}: quinn_proto::connection::packet_builder: PADDING * 1055
2022-12-24T03:03:56.387408Z TRACE drive{id=0}: quinn_proto::connection: sending 1200 bytes in 1 datagrams
2022-12-24T03:03:56.387437Z TRACE drive{id=0}:send{space=Initial pn=2}: quinn_proto::connection: CRYPTO: off 0 len 90
2022-12-24T03:03:56.387455Z TRACE drive{id=0}:send{space=Initial pn=2}: quinn_proto::connection::packet_builder: PADDING * 1063
2022-12-24T03:03:56.387492Z TRACE drive{id=0}: quinn_proto::connection: sending 1200 bytes in 1 datagrams
2022-12-24T03:03:56.387563Z TRACE drive{id=0}: quinn_proto::connection: got Initial packet (1200 bytes) from 127.0.0.1:64363 using id 67c132df24a5dd12af026b3f59e38630c80e7012
2022-12-24T03:03:56.387726Z TRACE drive{id=0}:send{space=Initial pn=3}: quinn_proto::connection: ACK ArrayRangeSet([0..3]), Delay = 0us
2022-12-24T03:03:56.387753Z TRACE drive{id=0}: quinn_proto::connection: sending 51 bytes in 1 datagrams
2022-12-24T03:03:57.385473Z TRACE drive{id=0}: quinn_proto::connection: timeout timer=LossDetection
2022-12-24T03:03:57.385619Z TRACE drive{id=0}: quinn_proto::connection: PTO fired in_flight=4991 count=1 space=Handshake
2022-12-24T03:03:57.386021Z TRACE drive{id=0}:send{space=Handshake pn=3}: quinn_proto::connection: CRYPTO: off 0 len 1009
2022-12-24T03:03:57.386314Z TRACE drive{id=0}: quinn_proto::connection: sending 1055 bytes in 1 datagrams
2022-12-24T03:03:57.386490Z TRACE drive{id=0}:send{space=Handshake pn=4}: quinn_proto::connection: CRYPTO: off 1009 len 1153
2022-12-24T03:03:57.386690Z TRACE drive{id=0}: quinn_proto::connection: sending 1200 bytes in 1 datagrams
2022-12-24T03:03:58.377613Z TRACE drive{id=0}: quinn_proto::connection: got Initial packet (1200 bytes) from 127.0.0.1:64363 using id 67c132df24a5dd12af026b3f59e38630c80e7012
2022-12-24T03:03:58.379086Z TRACE drive{id=0}:send{space=Initial pn=4}: quinn_proto::connection: ACK ArrayRangeSet([0..4]), Delay = 0us
2022-12-24T03:03:58.379203Z TRACE drive{id=0}: quinn_proto::connection: sending 51 bytes in 1 datagrams
2022-12-24T03:03:58.379392Z TRACE drive{id=0}: quinn_proto::connection: got Initial packet (1200 bytes) from 127.0.0.1:64363 using id 67c132df24a5dd12af026b3f59e38630c80e7012
2022-12-24T03:03:58.380059Z TRACE drive{id=0}:send{space=Initial pn=5}: quinn_proto::connection: ACK ArrayRangeSet([0..5]), Delay = 0us
2022-12-24T03:03:58.380156Z TRACE drive{id=0}: quinn_proto::connection: sending 51 bytes in 1 datagrams
2022-12-24T03:04:00.385010Z TRACE drive{id=0}: quinn_proto::connection: timeout timer=LossDetection
2022-12-24T03:04:00.385158Z TRACE drive{id=0}: quinn_proto::connection: PTO fired in_flight=7246 count=2 space=Initial
2022-12-24T03:04:00.385540Z TRACE drive{id=0}:send{space=Initial pn=6}: quinn_proto::connection: CRYPTO: off 0 len 90
2022-12-24T03:04:00.385685Z TRACE drive{id=0}:send{space=Initial pn=6}: quinn_proto::connection::packet_builder: PADDING * 1063
2022-12-24T03:04:00.386025Z TRACE drive{id=0}: quinn_proto::connection: sending 1200 bytes in 1 datagrams
2022-12-24T03:04:00.386205Z TRACE drive{id=0}:send{space=Initial pn=7}: quinn_proto::connection: CRYPTO: off 0 len 90
2022-12-24T03:04:00.386319Z TRACE drive{id=0}:send{space=Initial pn=7}: quinn_proto::connection::packet_builder: PADDING * 1063
2022-12-24T03:04:00.386591Z TRACE drive{id=0}: quinn_proto::connection: sending 1200 bytes in 1 datagrams
2022-12-24T03:04:02.377187Z TRACE drive{id=0}: quinn_proto::connection: got Initial packet (1200 bytes) from 127.0.0.1:64363 using id 67c132df24a5dd12af026b3f59e38630c80e7012
2022-12-24T03:04:02.378363Z TRACE drive{id=0}:send{space=Initial pn=8}: quinn_proto::connection: ACK ArrayRangeSet([0..6]), Delay = 0us
2022-12-24T03:04:02.378509Z TRACE drive{id=0}: quinn_proto::connection: sending 51 bytes in 1 datagrams
2022-12-24T03:04:02.378790Z TRACE drive{id=0}: quinn_proto::connection: got Initial packet (1200 bytes) from 127.0.0.1:64363 using id 67c132df24a5dd12af026b3f59e38630c80e7012
2022-12-24T03:04:02.379559Z TRACE drive{id=0}:send{space=Initial pn=9}: quinn_proto::connection: ACK ArrayRangeSet([0..7]), Delay = 0us
2022-12-24T03:04:02.379674Z TRACE drive{id=0}: quinn_proto::connection: sending 51 bytes in 1 datagrams
2022-12-24T03:04:05.380006Z TRACE drive{id=0}: quinn_proto::connection: timeout timer=LossDetection
2022-12-24T03:04:05.380177Z TRACE drive{id=0}: quinn_proto::connection: PTO fired in_flight=9646 count=3 space=Handshake
2022-12-24T03:04:05.380571Z TRACE drive{id=0}:send{space=Handshake pn=5}: quinn_proto::connection: CRYPTO: off 2162 len 7
2022-12-24T03:04:05.380811Z TRACE drive{id=0}: quinn_proto::connection: sending 53 bytes in 1 datagrams
2022-12-24T03:04:05.380988Z TRACE drive{id=0}:send{space=Handshake pn=6}: quinn_proto::connection: CRYPTO: off 0 len 1009
2022-12-24T03:04:05.381186Z TRACE drive{id=0}: quinn_proto::connection: sending 1055 bytes in 1 datagrams
2022-12-24T03:04:10.372154Z TRACE drive{id=0}: quinn_proto::connection: got Initial packet (1200 bytes) from 127.0.0.1:64363 using id 67c132df24a5dd12af026b3f59e38630c80e7012
2022-12-24T03:04:10.373322Z TRACE drive{id=0}:send{space=Initial pn=10}: quinn_proto::connection: ACK ArrayRangeSet([0..8]), Delay = 0us
2022-12-24T03:04:10.373468Z TRACE drive{id=0}: quinn_proto::connection: sending 51 bytes in 1 datagrams
2022-12-24T03:04:10.373756Z TRACE drive{id=0}: quinn_proto::connection: got Initial packet (1200 bytes) from 127.0.0.1:64363 using id 67c132df24a5dd12af026b3f59e38630c80e7012
2022-12-24T03:04:10.374527Z TRACE drive{id=0}:send{space=Initial pn=11}: quinn_proto::connection: ACK ArrayRangeSet([0..9]), Delay = 0us
2022-12-24T03:04:10.374669Z TRACE drive{id=0}: quinn_proto::connection: sending 51 bytes in 1 datagrams
2022-12-24T03:04:16.371825Z TRACE drive{id=0}: quinn_proto::connection: timeout timer=LossDetection
2022-12-24T03:04:16.372014Z TRACE drive{id=0}: quinn_proto::connection: PTO fired in_flight=10754 count=4 space=Initial
2022-12-24T03:04:16.372481Z TRACE drive{id=0}:send{space=Initial pn=12}: quinn_proto::connection: CRYPTO: off 0 len 90
2022-12-24T03:04:16.372636Z TRACE drive{id=0}:send{space=Initial pn=12}: quinn_proto::connection::packet_builder: PADDING * 1063
2022-12-24T03:04:16.372987Z TRACE drive{id=0}: quinn_proto::connection: sending 1200 bytes in 1 datagrams
2022-12-24T03:04:16.373172Z TRACE drive{id=0}:send{space=Initial pn=13}: quinn_proto::connection: CRYPTO: off 0 len 90
2022-12-24T03:04:16.373282Z TRACE drive{id=0}:send{space=Initial pn=13}: quinn_proto::connection::packet_builder: PADDING * 1063
2022-12-24T03:04:16.374757Z TRACE drive{id=0}: quinn_proto::connection: sending 1200 bytes in 1 datagrams

With server IP 127.0.0.1:

>>>>>>>>>> Logs from the client <<<<<<<<<<<

2022-12-24T03:09:02.832491Z  INFO rstun::client: connecting, idle_timeout:150000, retry_timeout:5000, threads:1
2022-12-24T03:09:02.832537Z  INFO rstun::client: preparing...
2022-12-24T03:09:02.833744Z  INFO rstun::client: client state: Preparing
2022-12-24T03:09:02.835821Z TRACE mio::poll: registering event source with poller: token=Token(0), interests=READABLE
2022-12-24T03:09:02.836271Z  INFO rstun::client: starting access server for [TunnelOut] tunneling: 0.0.0.0:9911
2022-12-24T03:09:02.836680Z  INFO rstun::access_server: starting access server, addr: 0.0.0.0:9911
2022-12-24T03:09:02.837315Z TRACE mio::poll: registering event source with poller: token=Token(1), interests=READABLE | WRITABLE
2022-12-24T03:09:02.837353Z  INFO rstun::access_server: started access server, addr: 0.0.0.0:9911
2022-12-24T03:09:02.837545Z  INFO rstun::client: client state: Connecting
2022-12-24T03:09:02.841705Z TRACE mio::poll: registering event source with poller: token=Token(2), interests=READABLE | WRITABLE
2022-12-24T03:09:02.841890Z  INFO rstun::client: connecting to 127.0.0.1:3515, local_addr: 0.0.0.0:57753
2022-12-24T03:09:02.841943Z TRACE quinn_proto::endpoint: initial_dcid=04b9089e90cbca2a72626816df059dbe9c287ca1
2022-12-24T03:09:02.842284Z DEBUG rustls::client::hs: No cached session for DnsName(DnsName(DnsName("localhost")))
2022-12-24T03:09:02.842498Z DEBUG rustls::client::hs: Not resuming any session
2022-12-24T03:09:02.842899Z TRACE rustls::client::hs: Sending ClientHello Message {
    version: TLSv1_0,
    payload: Handshake {
        parsed: HandshakeMessagePayload {
            typ: ClientHello,
            payload: ClientHello(
                ClientHelloPayload {
                    client_version: TLSv1_2,
                    random: c9b13dd8629a4708bff190fba7649d8ce95f7730ce7cc69fbcf859155644ed17,
                    session_id: ,
                    cipher_suites: [
                        TLS13_AES_256_GCM_SHA384,
                        TLS13_AES_128_GCM_SHA256,
                        TLS13_CHACHA20_POLY1305_SHA256,
                        TLS_ECDHE_ECDSA_WITH_AES_256_GCM_SHA384,
                        TLS_ECDHE_ECDSA_WITH_AES_128_GCM_SHA256,
                        TLS_ECDHE_ECDSA_WITH_CHACHA20_POLY1305_SHA256,
                        TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384,
                        TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256,
                        TLS_ECDHE_RSA_WITH_CHACHA20_POLY1305_SHA256,
                        TLS_EMPTY_RENEGOTIATION_INFO_SCSV,
                    ],
                    compression_methods: [
                        Null,
                    ],
                    extensions: [
                        SupportedVersions(
                            [
                                TLSv1_3,
                            ],
                        ),
                        ECPointFormats(
                            [
                                Uncompressed,
                            ],
                        ),
                        NamedGroups(
                            [
                                X25519,
                                secp256r1,
                                secp384r1,
                            ],
                        ),
                        SignatureAlgorithms(
                            [
                                ECDSA_NISTP384_SHA384,
                                ECDSA_NISTP256_SHA256,
                                ED25519,
                                RSA_PSS_SHA512,
                                RSA_PSS_SHA384,
                                RSA_PSS_SHA256,
                                RSA_PKCS1_SHA512,
                                RSA_PKCS1_SHA384,
                                RSA_PKCS1_SHA256,
                            ],
                        ),
                        ExtendedMasterSecretRequest,
                        CertificateStatusRequest(
                            OCSP(
                                OCSPCertificateStatusRequest {
                                    responder_ids: [],
                                    extensions: ,
                                },
                            ),
                        ),
                        ServerName(
                            [
                                ServerName {
                                    typ: HostName,
                                    payload: HostName(
                                        (
                                            6c6f63616c686f7374,
                                            DnsName(
                                                "localhost",
                                            ),
                                        ),
                                    ),
                                },
                            ],
                        ),
                        SignedCertificateTimestampRequest,
                        KeyShare(
                            [
                                KeyShareEntry {
                                    group: X25519,
                                    payload: 3e5521379440a5c3b1ab92db6989e2231099ea4d2fcde18d9259ad4f4b11d342,
                                },
                            ],
                        ),
                        PresharedKeyModes(
                            [
                                PSK_DHE_KE,
                            ],
                        ),
                        TransportParameters(
                            [
                                1,
                                4,
                                128,
                                2,
                                73,
                                240,
                                3,
                                2,
                                69,
                                200,
                                4,
                                4,
                                128,
                                16,
                                0,
                                0,
                                5,
                                4,
                                128,
                                19,
                                18,
                                208,
                                6,
                                4,
                                128,
                                19,
                                18,
                                208,
                                7,
                                4,
                                128,
                                19,
                                18,
                                208,
                                8,
                                2,
                                68,
                                0,
                                9,
                                2,
                                64,
                                100,
                                14,
                                1,
                                5,
                                64,
                                182,
                                0,
                                32,
                                4,
                                128,
                                0,
                                255,
                                255,
                                15,
                                8,
                                67,
                                175,
                                220,
                                27,
                                165,
                                231,
                                255,
                                54,
                                106,
                                178,
                                0,
                            ],
                        ),
                        SessionTicket(
                            Request,
                        ),
                    ],
                },
            ),
        },
        encoded: 0100010c0303c9b13dd8629a4708bff190fba7649d8ce95f7730ce7cc69fbcf859155644ed17000014130213011303c02cc02bcca9c030c02fcca800ff010000cf002b0003020304000b00020100000a00080006001d00170018000d00140012050304030807080608050804060105010401001700000005000501000000000000000e000c0000096c6f63616c686f737400120000003300260024001d00203e5521379440a5c3b1ab92db6989e2231099ea4d2fcde18d9259ad4f4b11d342002d00020101003900430104800249f0030245c80404801000000504801312d00604801312d00704801312d008024400090240640e010540b60020048000ffff0f0843afdc1ba5e7ff366ab20000230000,
    },
}
2022-12-24T03:09:02.845332Z TRACE quinn_proto::connection: wrote 272 Initial CRYPTO bytes
2022-12-24T03:09:02.845695Z TRACE drive{id=0}:send{space=Initial pn=0}: quinn_proto::connection: CRYPTO: off 0 len 272
2022-12-24T03:09:02.845730Z TRACE drive{id=0}:send{space=Initial pn=0}: quinn_proto::connection::packet_builder: PADDING * 869
2022-12-24T03:09:02.845877Z TRACE drive{id=0}: quinn_proto::connection: sending 1200 bytes in 1 datagrams
2022-12-24T03:09:02.859422Z TRACE drive{id=0}: quinn_proto::connection: got Initial packet (145 bytes) from 127.0.0.1:3515 using id 43afdc1ba5e7ff36
2022-12-24T03:09:02.859519Z TRACE drive{id=0}:recv{space=Initial pn=0}: quinn_proto::connection: switching remote CID to fa232e8d449b3a76
2022-12-24T03:09:02.859638Z TRACE drive{id=0}:recv{space=Initial pn=0}:frame{ty=CRYPTO}: quinn_proto::connection: consumed 90 CRYPTO bytes
2022-12-24T03:09:02.859701Z TRACE drive{id=0}:recv{space=Initial pn=0}:frame{ty=CRYPTO}: rustls::client::hs: We got ServerHello ServerHelloPayload {
    legacy_version: TLSv1_2,
    random: 12e301d1945169b5382990583401120ed624f20c73c07a460f812dee4b2cb2a8,
    session_id: ,
    cipher_suite: TLS13_CHACHA20_POLY1305_SHA256,
    compression_method: Null,
    extensions: [
        KeyShare(
            KeyShareEntry {
                group: X25519,
                payload: aaa24153b39c677d678fdc756df7b5f28a95ec47402c357c250b3eb50f8b4539,
            },
        ),
        SupportedVersions(
            TLSv1_3,
        ),
    ],
}
2022-12-24T03:09:02.859991Z DEBUG drive{id=0}:recv{space=Initial pn=0}:frame{ty=CRYPTO}: rustls::client::hs: Using ciphersuite TLS13_CHACHA20_POLY1305_SHA256
2022-12-24T03:09:02.860022Z DEBUG drive{id=0}:recv{space=Initial pn=0}:frame{ty=CRYPTO}: rustls::client::tls13: Not resuming
2022-12-24T03:09:02.860042Z TRACE drive{id=0}:recv{space=Initial pn=0}:frame{ty=CRYPTO}: rustls::client::client_conn: EarlyData rejected
2022-12-24T03:09:02.860326Z TRACE drive{id=0}:recv{space=Initial pn=0}: quinn_proto::connection: Handshake keys ready
2022-12-24T03:09:02.860353Z TRACE drive{id=0}: quinn_proto::connection: got Handshake packet (1055 bytes) from 127.0.0.1:3515 using id 43afdc1ba5e7ff36
2022-12-24T03:09:02.860400Z TRACE drive{id=0}:recv{space=Handshake pn=0}:frame{ty=CRYPTO}: quinn_proto::connection: consumed 1009 CRYPTO bytes
2022-12-24T03:09:02.860425Z DEBUG drive{id=0}:recv{space=Handshake pn=0}:frame{ty=CRYPTO}: rustls::client::tls13: TLS1.3 encrypted extensions: [ServerNameAck, TransportParameters([1, 4, 128, 0, 156, 64, 3, 2, 69, 200, 4, 4, 128, 16, 0, 0, 5, 4, 128, 19, 18, 208, 6, 4, 128, 19, 18, 208, 7, 4, 128, 19, 18, 208, 8, 2, 68, 0, 9, 2, 64, 100, 14, 1, 5, 64, 182, 0, 2, 16, 110, 148, 47, 104, 203, 146, 57, 34, 0, 30, 64, 13, 228, 74, 64, 8, 32, 4, 128, 0, 255, 255, 0, 20, 4, 185, 8, 158, 144, 203, 202, 42, 114, 98, 104, 22, 223, 5, 157, 190, 156, 40, 124, 161, 15, 8, 250, 35, 46, 141, 68, 155, 58, 118, 106, 178, 0])]
2022-12-24T03:09:02.860469Z DEBUG drive{id=0}:recv{space=Handshake pn=0}:frame{ty=CRYPTO}: rustls::client::hs: ALPN protocol is None
2022-12-24T03:09:02.860498Z TRACE drive{id=0}:recv{space=Handshake pn=0}: quinn_proto::connection: handshake ongoing
2022-12-24T03:09:02.860541Z TRACE drive{id=0}:send{space=Initial pn=1}: quinn_proto::connection: ACK ArrayRangeSet([0..1]), Delay = 0us
2022-12-24T03:09:02.860574Z TRACE drive{id=0}: quinn_proto::connection: discarding Initial keys
2022-12-24T03:09:02.860599Z TRACE drive{id=0}:send{space=Handshake pn=0}: quinn_proto::connection: ACK ArrayRangeSet([0..1]), Delay = 0us
2022-12-24T03:09:02.860617Z TRACE drive{id=0}:send{space=Handshake pn=0}: quinn_proto::connection::packet_builder: PADDING * 1099
2022-12-24T03:09:02.860658Z TRACE drive{id=0}: quinn_proto::connection: sending 1200 bytes in 1 datagrams
2022-12-24T03:09:02.860726Z TRACE drive{id=0}: quinn_proto::connection: got Handshake packet (1200 bytes) from 127.0.0.1:3515 using id 43afdc1ba5e7ff36
2022-12-24T03:09:02.860763Z TRACE drive{id=0}:recv{space=Handshake pn=1}:frame{ty=CRYPTO}: quinn_proto::connection: consumed 1153 CRYPTO bytes
2022-12-24T03:09:02.860807Z TRACE drive{id=0}:recv{space=Handshake pn=1}:frame{ty=CRYPTO}: rustls::client::tls13: Server cert is [Certificate(b"0\x82\x05\xc30\x82\x03\xab\xa0\x03\x02\x01\x02\x02\x14R,\xef\xa0\x8f%P\xde\xa26XW\x89\x1d\xdf\xb0\xeb,\xa3\xd90\r\x06\t*\x86H\x86\xf7\r\x01\x01\x0b\x05\00q1\x0b0\t\x06\x03U\x04\x06\x13\x02CN1\x0b0\t\x06\x03U\x04\x08\x0c\x02GD1\x0b0\t\x06\x03U\x04\x07\x0c\x02GZ1\x110\x0f\x06\x03U\x04\n\x0c\x08PERSONAL1\x0b0\t\x06\x03U\x04\x0b\x0c\x02IT1\x0c0\n\x06\x03U\x04\x03\x0c\x03NVK1\x1a0\x18\x06\t*\x86H\x86\xf7\r\x01\t\x01\x16\x0babc@abc.com0\x1e\x17\r211016162007Z\x17\r311014162007Z0q1\x0b0\t\x06\x03U\x04\x06\x13\x02CN1\x0b0\t\x06\x03U\x04\x08\x0c\x02GD1\x0b0\t\x06\x03U\x04\x07\x0c\x02GZ1\x110\x0f\x06\x03U\x04\n\x0c\x08PERSONAL1\x0b0\t\x06\x03U\x04\x0b\x0c\x02IT1\x0c0\n\x06\x03U\x04\x03\x0c\x03NVK1\x1a0\x18\x06\t*\x86H\x86\xf7\r\x01\t\x01\x16\x0babc@abc.com0\x82\x02\"0\r\x06\t*\x86H\x86\xf7\r\x01\x01\x01\x05\0\x03\x82\x02\x0f\00\x82\x02\n\x02\x82\x02\x01\0\xd0`\x18\xad2s\x02c\xf9\x0f\xeeR>\xc1\x91_/\xaf\x97`\xf5\x01c2\xa3\x99\x94\x12\xd2;Ju\x02\x19\x12\x8d\x11\xdaq\xed\xf6Z>,\xd9\x9e4J\xa384ON\xf9G\xb7\xc2\xbdL\x83\x8c\xf9\xab\x0b\xfc\xd1zWgZ\xbbu\")8qP\xaa\xd9\xa9\xc3\x90\xbav\x1b\xf3\xc8W\xa1f\xce\xd0\xae\xb3\xa4\xcf\x1d\xf0my['\xa7\"\xe4\xc0\x1ek\x95kK\xe85X\xde\xd9Z\xab\xc5\x89{\xef,S\xacB\x11A\x92\x122\xff\xc6\x80\x96\xc0XX\x19~{\xb8\x98\xd2\x13\x192\xc6\x15\x8d\xf1z'\x949\x02\xe2q\x1f\xf7\x1d\xa3\x1d\x82\x1f\xecE\x18\xf1\n\xfc\x18]/\xaf(\xc3\xb6\xc4bH\xc8F\x9eTCT\xe6\xbd3\x1a2\x83a\n-\xaf\xe9\xa9\x99$\xeaUy\x96\x01'\xfa\xb7F\xd5c\xf1\x88\x025\xe3\x93\xadd\xbd\xc3\xfe\xe8H\xa6\xa2\x83\xfc\xa0\x08\xbe\x1a\x93\xcc\xc76\xd6\xde\xb5dv\xc6\xea\x1a\x93\x04p\x84\x1df\xb1m\xa5\x98\xe4\x1b\x7f\x842V\x8cP\xdf\x8di|\xd5\xb7*:D\xed`\xf9\xda\xad\xbf\xde@l\xfe\xd0l=\x02\xd1FO6\x1dxA\x90\xab\xfb\x81dE\xd9\x01|\x04\xb4]\x83k\xaag\xf7\xe0MEpv@\x0c\xc6x\xe8\xbf\xd0\xb6@\xed\xdbR\x06\xc7F\xd4\xaeK\xe3n$\x14\xa2%g&\x91tz`\"\x1bN\xefD\xeb\xa4\xca/W\x15l\xe1\xd7\x8d\x9frE\xb0\x8bu>,\xb0\x7fk \xc6\xb0P\xea\rU\x96\x91d\x901\x1d\x84n\xaa3O\n\xe9\xadrsD\t\xc7\xcfP\xf1\xed\x10]\xe7Z\x1c/,\xd8a\x9d\x01\xe5\xb0\xff[\xa8\x8d/\x86\xde\x10bQOw\xed\xf8\xf5\x1b\xa5\xe4\xdc\\\x8a>\x96|\xc19B\x05\xf7\xd5\xf6\xa0\x1f\xc9~\x9e\xb4\xeaH\x02\xfbz\xcf\xef\xa50U\xf1\xc5\xd3\xa0\xb4\xbf\x90\xbc\xb3O\xe50\x04/\xe9\x86\x97z\t\x94\x8b?\xbdB\xa5\xcf\xac\xe4\xf4I\x15\x06#\x05\xd7%\xeb\xcc\x89:\xad\x15&\xd1qb\x08I^\x0b'\x02\x03\x01\0\x01\xa3S0Q0\x1d\x06\x03U\x1d\x0e\x04\x16\x04\x14C2\x11w\xba\xb9\x0c\xae)\x8c\xe9\xc2\xae\x1ey\xfe\xf7\x7f\xae\xff0\x1f\x06\x03U\x1d#\x04\x180\x16\x80\x14C2\x11w\xba\xb9\x0c\xae)\x8c\xe9\xc2\xae\x1ey\xfe\xf7\x7f\xae\xff0\x0f\x06\x03U\x1d\x13\x01\x01\xff\x04\x050\x03\x01\x01\xff0\r\x06\t*\x86H\x86\xf7\r\x01\x01\x0b\x05\0\x03\x82\x02\x01\0\x97\x01\xb1\xb8\x06\x80\x10\x8a%6\t\x18\xf6\xd26\xbet\xb6n\xda\xb7\x14\xb28\xc0)\xc3\x0eo\xbf\xef.E\xc6k\x0e\x1e*\xa5\x8d\xe3\xd9\xed\xad\xa6\xbe\xc4\xd9\xad\x9c0\xa9LuJ\x1b\xaez\xc2\xc9\0\x91\x10E\x81\xcbK\x95O\xf3\xfc|\x05J\xf5_e\xa7On\xe5yK\xae\xb5\x1f\xacc3J\x10\x176\xea\xfa\x9d\xd1\n\x01-\xe0\x12&8D\x11*\xc7\x04\xf7\x99\xaf}\xc5Yp\x868\x90\xdf2\xedp^\xf4\"0:\xb0\x81A\xd6\xf7M\xc9\xdfh\xf9\xd2\xe6PN\x83\xf9\n\xfcO\x18\xd4\xc2#\xdbX.J#\xc6\\&\xd6m0\xb9\x93\xc8\xca\x80\x8e\xbfD\xcf\x9a6\x94\xd8F\x8a\xe7\xaf\x82\xc2\x8e\xa5\xad\x98\x9d\x0f\xd3IF\xcb\xba5MI\xe4\xb5\xa1\xf1=\xc2d\xc7\xc28\xbc&ZL\x11\\\x86\xe0\x10p.\xe9\xf6w\xf4\xe9\xfc#>\xf6M\xaf\x8f\xfb\x10@zA%R_\x16\xa4\xbd\xaeN\xbdl\xc9\xd368\xb6\xaf\xa5\x7f\x94\x8d\x1e\x0e\xfew\xd4\xce4\xba\xb9vx\xe9\x9f\xcaI4X#\xbe\x8bb\xf6\08\x9c\xf1?\x08\xe1}\xadl\x8a\xbc\xcaj\x08v\x03\x82*\xe7\xf2N\xffB\x82/\xdb\x0c\xfc#F\x87\x16\xf5\xedQ\x89|\x8b\x9c\x1c\x87\xa7\xf3\x834B\x02\xc7\xc44P \xb4M\xfd ?\xf7\xc9]c_\x17\xb9\xfd\xcbX\xd7\x9f\x18\xdf\xaae\xe0\xdf\xe0\"\xcc\xb9\xa9\x06\xb2\x16\x9f\xf2\x91kS\xe4o\xdfx3)\x17\xa6\x8c!\xff\x87U ~u:\xb1<\xa9c\xaf\x1a2\xad-m\x18\x0fo\x89\xc5\xc0\xe9\x06\x19\x19/4\xeb#\xc2z\xccr\xc4\xa4v$[\xda6w\xc6\xe4\xf3\xd1\xad4\xdbE\xda\0\t\x0cd}\x03\x182}\xfd\xa5\xecy\x97\x04.\xe6\xdeA\\3X\x01\x9e^\"\x14Qygr\xf3x;y\xfd\xac-\xaf\xd4&X5o\x8fe\xdd&b\xc0J\xb5\x9b\x95\x08\x8eX?\xe0\xd0\xad\x99~T\xfah\xf4\xbb\"\xbe\xce\xa0\x9a\x1fNcX\xe7;\xdc\x1c5\xc3\x03\x14\xa0")]
2022-12-24T03:09:02.861171Z  INFO drive{id=0}:recv{space=Handshake pn=1}:frame{ty=CRYPTO}: rstun::client: certificate verified!
2022-12-24T03:09:02.861383Z TRACE drive{id=0}:recv{space=Handshake pn=1}: quinn_proto::connection: handshake ongoing
2022-12-24T03:09:02.861420Z TRACE drive{id=0}:send{space=Handshake pn=1}: quinn_proto::connection: ACK ArrayRangeSet([0..2]), Delay = 0us
2022-12-24T03:09:02.861448Z TRACE drive{id=0}: quinn_proto::connection: sending 50 bytes in 1 datagrams
2022-12-24T03:09:02.861508Z TRACE drive{id=0}: quinn_proto::connection: got Handshake packet (53 bytes) from 127.0.0.1:3515 using id 43afdc1ba5e7ff36
2022-12-24T03:09:02.861544Z TRACE drive{id=0}:recv{space=Handshake pn=2}:frame{ty=CRYPTO}: quinn_proto::connection: consumed 7 CRYPTO bytes
2022-12-24T03:09:02.861884Z TRACE drive{id=0}:recv{space=Handshake pn=2}: quinn_proto::connection: Data keys ready
2022-12-24T03:09:02.861921Z TRACE drive{id=0}:recv{space=Handshake pn=2}: quinn_proto::connection: wrote 36 Handshake CRYPTO bytes
2022-12-24T03:09:02.862222Z TRACE drive{id=0}:recv{space=Handshake pn=2}: quinn_proto::connection: established
2022-12-24T03:09:02.862260Z TRACE drive{id=0}:send{space=Handshake pn=2}: quinn_proto::connection: ACK ArrayRangeSet([0..3]), Delay = 0us
2022-12-24T03:09:02.862277Z TRACE drive{id=0}:send{space=Handshake pn=2}: quinn_proto::connection: CRYPTO: off 0 len 36
2022-12-24T03:09:02.862307Z TRACE drive{id=0}: quinn_proto::connection: sending 89 bytes in 1 datagrams
2022-12-24T03:09:02.862378Z  INFO rstun::client: client state: Connected
2022-12-24T03:09:02.862443Z TRACE drive{id=0}: quinn_proto::connection: got Data packet (138 bytes) from 127.0.0.1:3515 using id 43afdc1ba5e7ff36
2022-12-24T03:09:02.862648Z  INFO rstun::client: connected to server: 127.0.0.1:3515
2022-12-24T03:09:02.862712Z TRACE drive{id=0}:recv{space=Data pn=0}: quinn_proto::connection: got frame NewConnectionId(NewConnectionId { sequence: 1, retire_prior_to: 0, id: [11, 255, 15, 100, 2, 236, 62, 16], reset_token: ResetToken([71, 148, 0, 233, 176, 59, 213, 250, 106, 179, 17, 64, 36, 19, 183, 253]) })
2022-12-24T03:09:02.862735Z TRACE drive{id=0}:recv{space=Data pn=0}:frame{ty=NEW_CONNECTION_ID}: quinn_proto::connection: sequence=1 id=0bff0f6402ec3e10 retire_prior_to=0
2022-12-24T03:09:02.862767Z TRACE drive{id=0}:recv{space=Data pn=0}: quinn_proto::connection: got frame NewConnectionId(NewConnectionId { sequence: 2, retire_prior_to: 0, id: [75, 104, 17, 153, 33, 235, 212, 244], reset_token: ResetToken([158, 210, 84, 28, 227, 149, 228, 119, 234, 239, 44, 247, 9, 96, 19, 154]) })
2022-12-24T03:09:02.862787Z TRACE drive{id=0}:recv{space=Data pn=0}:frame{ty=NEW_CONNECTION_ID}: quinn_proto::connection: sequence=2 id=4b68119921ebd4f4 retire_prior_to=0
2022-12-24T03:09:02.862819Z TRACE drive{id=0}:recv{space=Data pn=0}: quinn_proto::connection: got frame NewConnectionId(NewConnectionId { sequence: 3, retire_prior_to: 0, id: [59, 156, 21, 254, 40, 14, 248, 75], reset_token: ResetToken([128, 44, 141, 238, 182, 229, 184, 203, 12, 178, 133, 61, 12, 234, 149, 197]) })
2022-12-24T03:09:02.862838Z TRACE drive{id=0}:recv{space=Data pn=0}:frame{ty=NEW_CONNECTION_ID}: quinn_proto::connection: sequence=3 id=3b9c15fe280ef84b retire_prior_to=0
2022-12-24T03:09:02.862869Z TRACE drive{id=0}:recv{space=Data pn=0}: quinn_proto::connection: got frame NewConnectionId(NewConnectionId { sequence: 4, retire_prior_to: 0, id: [1, 162, 216, 251, 75, 23, 178, 186], reset_token: ResetToken([241, 175, 78, 149, 32, 135, 227, 152, 252, 118, 91, 102, 100, 62, 12, 29]) })
2022-12-24T03:09:02.862889Z TRACE drive{id=0}:recv{space=Data pn=0}:frame{ty=NEW_CONNECTION_ID}: quinn_proto::connection: sequence=4 id=01a2d8fb4b17b2ba retire_prior_to=0
2022-12-24T03:09:02.862937Z TRACE drive{id=0}:send{space=Data pn=0}: quinn_proto::connection: ACK ArrayRangeSet([0..1]), Delay = 0us
2022-12-24T03:09:02.862955Z TRACE drive{id=0}:send{space=Data pn=0}: quinn_proto::connection: NEW_CONNECTION_ID sequence=1 id=6de622ca54d8c7e3
2022-12-24T03:09:02.862974Z TRACE drive{id=0}:send{space=Data pn=0}: quinn_proto::connection: NEW_CONNECTION_ID sequence=2 id=bc539040e26868d7
2022-12-24T03:09:02.862992Z TRACE drive{id=0}:send{space=Data pn=0}: quinn_proto::connection: NEW_CONNECTION_ID sequence=3 id=4cb9dc1700793314
2022-12-24T03:09:02.863010Z TRACE drive{id=0}:send{space=Data pn=0}: quinn_proto::connection: NEW_CONNECTION_ID sequence=4 id=750f2828c149d93b
2022-12-24T03:09:02.863040Z TRACE drive{id=0}: quinn_proto::connection: sending 146 bytes in 1 datagrams
2022-12-24T03:09:02.863069Z  INFO rstun::client: client state: LoggingIn
2022-12-24T03:09:02.863081Z  INFO rstun::client: logging in...
2022-12-24T03:09:02.863091Z TRACE drive{id=0}: quinn_proto::connection: got Data packet (112 bytes) from 127.0.0.1:3515 using id 43afdc1ba5e7ff36
2022-12-24T03:09:02.863102Z DEBUG rstun::client: sending login request...
2022-12-24T03:09:02.863120Z TRACE drive{id=0}:recv{space=Data pn=1}: quinn_proto::connection: got frame HandshakeDone
2022-12-24T03:09:02.863134Z TRACE drive{id=0}:recv{space=Data pn=1}:frame{ty=HANDSHAKE_DONE}: quinn_proto::connection: discarding Handshake keys
2022-12-24T03:09:02.863165Z TRACE drive{id=0}:recv{space=Data pn=1}: quinn_proto::connection: got crypto frame offset=0 len=81
2022-12-24T03:09:02.863183Z TRACE drive{id=0}:recv{space=Data pn=1}:frame{ty=CRYPTO}: quinn_proto::connection: consumed 81 CRYPTO bytes
2022-12-24T03:09:02.863226Z DEBUG drive{id=0}:recv{space=Data pn=1}:frame{ty=CRYPTO}: rustls::client::tls13: Ticket saved
2022-12-24T03:09:02.863265Z TRACE drive{id=0}:send{space=Data pn=1}: quinn_proto::connection: ACK ArrayRangeSet([0..2]), Delay = 0us
2022-12-24T03:09:02.863290Z TRACE drive{id=0}: quinn_proto::connection: sending 34 bytes in 1 datagrams
2022-12-24T03:09:02.863338Z TRACE quinn_proto::connection::streams: wrote 4 bytes stream=client bidirectional stream 0
2022-12-24T03:09:02.863368Z TRACE quinn_proto::connection::streams: wrote 38 bytes stream=client bidirectional stream 0
2022-12-24T03:09:02.863378Z DEBUG rstun::client: sent login request!
2022-12-24T03:09:02.863431Z TRACE drive{id=0}:send{space=Data pn=2}: quinn_proto::connection::streams::state: STREAM id=client bidirectional stream 0 off=0 len=42 fin=false
2022-12-24T03:09:02.863464Z TRACE drive{id=0}: quinn_proto::connection: sending 71 bytes in 1 datagrams
2022-12-24T03:09:02.863606Z TRACE drive{id=0}: quinn_proto::connection: got Data packet (36 bytes) from 127.0.0.1:3515 using id 6de622ca54d8c7e3
2022-12-24T03:09:02.863636Z TRACE drive{id=0}:recv{space=Data pn=2}: quinn_proto::connection: got frame Ack(Ack { largest: 0, delay: 0, ecn: Some(EcnCounts { ect0: 1, ect1: 0, ce: 0 }), ranges: "[0..=0]" })
2022-12-24T03:09:02.863675Z TRACE drive{id=0}:recv{space=Data pn=2}: quinn_proto::connection: got frame RetireConnectionId { sequence: 0 }
2022-12-24T03:09:02.863709Z TRACE drive{id=0}:send{space=Data pn=3}: quinn_proto::connection: ACK ArrayRangeSet([1..3]), Delay = 0us
2022-12-24T03:09:02.863734Z TRACE drive{id=0}: quinn_proto::connection: sending 34 bytes in 1 datagrams
2022-12-24T03:09:02.863759Z TRACE quinn_proto::endpoint: peer retired CID 0: 43afdc1ba5e7ff36
2022-12-24T03:09:02.863804Z TRACE drive{id=0}:send{space=Data pn=4}: quinn_proto::connection: NEW_CONNECTION_ID sequence=5 id=388f0c39792331c6
2022-12-24T03:09:02.863833Z TRACE drive{id=0}: quinn_proto::connection: sending 54 bytes in 1 datagrams
2022-12-24T03:09:02.864519Z TRACE drive{id=0}: quinn_proto::connection: got Data packet (34 bytes) from 127.0.0.1:3515 using id 6de622ca54d8c7e3
2022-12-24T03:09:02.864549Z TRACE drive{id=0}:recv{space=Data pn=3}: quinn_proto::connection: got frame Ack(Ack { largest: 2, delay: 0, ecn: Some(EcnCounts { ect0: 3, ect1: 0, ce: 0 }), ranges: "[0..=2]" })
2022-12-24T03:09:02.864793Z TRACE drive{id=0}: quinn_proto::connection: got Data packet (34 bytes) from 127.0.0.1:3515 using id 6de622ca54d8c7e3
2022-12-24T03:09:02.864828Z TRACE drive{id=0}:recv{space=Data pn=4}: quinn_proto::connection: got frame Ack(Ack { largest: 4, delay: 0, ecn: Some(EcnCounts { ect0: 5, ect1: 0, ce: 0 }), ranges: "[1..=4]" })
2022-12-24T03:09:22.868426Z TRACE drive{id=0}: quinn_proto::connection: got Data packet (30 bytes) from 127.0.0.1:3515 using id 6de622ca54d8c7e3
2022-12-24T03:09:22.868766Z TRACE drive{id=0}:recv{space=Data pn=5}: quinn_proto::connection: got frame Ping
2022-12-24T03:09:22.869137Z TRACE drive{id=0}:send{space=Data pn=5}: quinn_proto::connection: ACK ArrayRangeSet([3..6]), Delay = 0us
2022-12-24T03:09:22.869349Z TRACE drive{id=0}: quinn_proto::connection: sending 34 bytes in 1 datagrams
2022-12-24T03:09:42.873016Z TRACE drive{id=0}: quinn_proto::connection: got Data packet (30 bytes) from 127.0.0.1:3515 using id 6de622ca54d8c7e3
2022-12-24T03:09:42.873347Z TRACE drive{id=0}:recv{space=Data pn=6}: quinn_proto::connection: got frame Ping
2022-12-24T03:09:42.873665Z TRACE drive{id=0}:send{space=Data pn=6}: quinn_proto::connection: ACK ArrayRangeSet([3..7]), Delay = 0us
2022-12-24T03:09:42.873888Z TRACE drive{id=0}: quinn_proto::connection: sending 34 bytes in 1 datagrams


>>>>>>>>>> Logs from the server <<<<<<<<<<<

2022-12-24T03:08:53.343899Z TRACE mio::poll: registering event source with poller: token=Token(0), interests=READABLE
2022-12-24T03:08:53.344455Z TRACE mio::poll: registering event source with poller: token=Token(1), interests=READABLE | WRITABLE
2022-12-24T03:08:53.344507Z  INFO rstun::server: server is bound to: 0.0.0.0:3515, idle_timeout: 40000
2022-12-24T03:09:02.848464Z TRACE first recv:frame{ty=CRYPTO}: quinn_proto::connection: consumed 272 CRYPTO bytes
2022-12-24T03:09:02.848611Z TRACE first recv:frame{ty=CRYPTO}: rustls::server::hs: we got a clienthello ClientHelloPayload { client_version: TLSv1_2, random: c9b13dd8629a4708bff190fba7649d8ce95f7730ce7cc69fbcf859155644ed17, session_id: , cipher_suites: [TLS13_AES_256_GCM_SHA384, TLS13_AES_128_GCM_SHA256, TLS13_CHACHA20_POLY1305_SHA256, TLS_ECDHE_ECDSA_WITH_AES_256_GCM_SHA384, TLS_ECDHE_ECDSA_WITH_AES_128_GCM_SHA256, TLS_ECDHE_ECDSA_WITH_CHACHA20_POLY1305_SHA256, TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384, TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256, TLS_ECDHE_RSA_WITH_CHACHA20_POLY1305_SHA256, TLS_EMPTY_RENEGOTIATION_INFO_SCSV], compression_methods: [Null], extensions: [SupportedVersions([TLSv1_3]), ECPointFormats([Uncompressed]), NamedGroups([X25519, secp256r1, secp384r1]), SignatureAlgorithms([ECDSA_NISTP384_SHA384, ECDSA_NISTP256_SHA256, ED25519, RSA_PSS_SHA512, RSA_PSS_SHA384, RSA_PSS_SHA256, RSA_PKCS1_SHA512, RSA_PKCS1_SHA384, RSA_PKCS1_SHA256]), ExtendedMasterSecretRequest, CertificateStatusRequest(OCSP(OCSPCertificateStatusRequest { responder_ids: [], extensions:  })), ServerName([ServerName { typ: HostName, payload: HostName((6c6f63616c686f7374, DnsName("localhost"))) }]), SignedCertificateTimestampRequest, KeyShare([KeyShareEntry { group: X25519, payload: 3e5521379440a5c3b1ab92db6989e2231099ea4d2fcde18d9259ad4f4b11d342 }]), PresharedKeyModes([PSK_DHE_KE]), TransportParameters([1, 4, 128, 2, 73, 240, 3, 2, 69, 200, 4, 4, 128, 16, 0, 0, 5, 4, 128, 19, 18, 208, 6, 4, 128, 19, 18, 208, 7, 4, 128, 19, 18, 208, 8, 2, 68, 0, 9, 2, 64, 100, 14, 1, 5, 64, 182, 0, 32, 4, 128, 0, 255, 255, 15, 8, 67, 175, 220, 27, 165, 231, 255, 54, 106, 178, 0]), SessionTicket(Request)] }
2022-12-24T03:09:02.848723Z TRACE first recv:frame{ty=CRYPTO}: rustls::server::server_conn: sni Some(DnsName("localhost"))
2022-12-24T03:09:02.848741Z TRACE first recv:frame{ty=CRYPTO}: rustls::server::server_conn: sig schemes [ECDSA_NISTP384_SHA384, ECDSA_NISTP256_SHA256, ED25519, RSA_PSS_SHA512, RSA_PSS_SHA384, RSA_PSS_SHA256, RSA_PKCS1_SHA512, RSA_PKCS1_SHA384, RSA_PKCS1_SHA256]
2022-12-24T03:09:02.848759Z TRACE first recv:frame{ty=CRYPTO}: rustls::server::server_conn: alpn protocols None
2022-12-24T03:09:02.848773Z TRACE first recv:frame{ty=CRYPTO}: rustls::server::server_conn: cipher suites [TLS13_AES_256_GCM_SHA384, TLS13_AES_128_GCM_SHA256, TLS13_CHACHA20_POLY1305_SHA256, TLS_ECDHE_ECDSA_WITH_AES_256_GCM_SHA384, TLS_ECDHE_ECDSA_WITH_AES_128_GCM_SHA256, TLS_ECDHE_ECDSA_WITH_CHACHA20_POLY1305_SHA256, TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384, TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256, TLS_ECDHE_RSA_WITH_CHACHA20_POLY1305_SHA256, TLS_EMPTY_RENEGOTIATION_INFO_SCSV]   
2022-12-24T03:09:02.848795Z DEBUG first recv:frame{ty=CRYPTO}: rustls::server::hs: decided upon suite TLS13_CHACHA20_POLY1305_SHA256
2022-12-24T03:09:02.848973Z TRACE first recv:frame{ty=CRYPTO}: rustls::server::tls13::client_hello: sending server hello Message { version: TLSv1_2, payload: Handshake { parsed: HandshakeMessagePayload { typ: ServerHello, payload: ServerHello(ServerHelloPayload { legacy_version: TLSv1_2, random: 12e301d1945169b5382990583401120ed624f20c73c07a460f812dee4b2cb2a8, session_id: , cipher_suite: TLS13_CHACHA20_POLY1305_SHA256, compression_method: Null, extensions: [KeyShare(KeyShareEntry { group: X25519, payload: aaa24153b39c677d678fdc756df7b5f28a95ec47402c357c250b3eb50f8b4539 }), SupportedVersions(TLSv1_3)] }) }, encoded: 02000056030312e301d1945169b5382990583401120ed624f20c73c07a460f812dee4b2cb2a800130300002e00330024001d0020aaa24153b39c677d678fdc756df7b5f28a95ec47402c357c250b3eb50f8b4539002b00020304 } }
2022-12-24T03:09:02.849231Z TRACE first recv:frame{ty=CRYPTO}: rustls::server::tls13::client_hello: sending encrypted extensions Message { version: TLSv1_3, payload: Handshake { parsed: HandshakeMessagePayload { typ: EncryptedExtensions, payload: EncryptedExtensions([ServerNameAck, TransportParameters([1, 4, 128, 0, 156, 64, 3, 2, 69, 200, 4, 4, 128, 16, 0, 0, 5, 4, 128, 19, 18, 208, 6, 4, 128, 19, 18, 208, 7, 4, 128, 19, 18, 208, 8, 2, 68, 0, 9, 2, 64, 100, 14, 1, 5, 64, 182, 0, 2, 16, 110, 148, 47, 104, 203, 146, 57, 34, 0, 30, 64, 13, 228, 74, 64, 8, 32, 4, 128, 0, 255, 255, 0, 20, 4, 185, 8, 158, 144, 203, 202, 42, 114, 98, 104, 22, 223, 5, 157, 190, 156, 40, 124, 161, 15, 8, 250, 35, 46, 141, 68, 155, 58, 118, 106, 178, 0])]) }, encoded: 080000750073000000000039006b010480009c40030245c80404801000000504801312d00604801312d00704801312d008024400090240640e010540b60002106e942f68cb923922001e400de44a400820048000ffff001404b9089e90cbca2a72626816df059dbe9c287ca10f08fa232e8d449b3a766ab200 } }
2022-12-24T03:09:02.849330Z TRACE first recv:frame{ty=CRYPTO}: rustls::server::tls13::client_hello: sending certificate Message { version: TLSv1_3, payload: Handshake { parsed: HandshakeMessagePayload { typ: Certificate, payload: CertificateTLS13(CertificatePayloadTLS13 { context: , entries: [CertificateEntry { cert: Certificate(b"0\x82\x05\xc30\x82\x03\xab\xa0\x03\x02\x01\x02\x02\x14R,\xef\xa0\x8f%P\xde\xa26XW\x89\x1d\xdf\xb0\xeb,\xa3\xd90\r\x06\t*\x86H\x86\xf7\r\x01\x01\x0b\x05\00q1\x0b0\t\x06\x03U\x04\x06\x13\x02CN1\x0b0\t\x06\x03U\x04\x08\x0c\x02GD1\x0b0\t\x06\x03U\x04\x07\x0c\x02GZ1\x110\x0f\x06\x03U\x04\n\x0c\x08PERSONAL1\x0b0\t\x06\x03U\x04\x0b\x0c\x02IT1\x0c0\n\x06\x03U\x04\x03\x0c\x03NVK1\x1a0\x18\x06\t*\x86H\x86\xf7\r\x01\t\x01\x16\x0babc@abc.com0\x1e\x17\r211016162007Z\x17\r311014162007Z0q1\x0b0\t\x06\x03U\x04\x06\x13\x02CN1\x0b0\t\x06\x03U\x04\x08\x0c\x02GD1\x0b0\t\x06\x03U\x04\x07\x0c\x02GZ1\x110\x0f\x06\x03U\x04\n\x0c\x08PERSONAL1\x0b0\t\x06\x03U\x04\x0b\x0c\x02IT1\x0c0\n\x06\x03U\x04\x03\x0c\x03NVK1\x1a0\x18\x06\t*\x86H\x86\xf7\r\x01\t\x01\x16\x0babc@abc.com0\x82\x02\"0\r\x06\t*\x86H\x86\xf7\r\x01\x01\x01\x05\0\x03\x82\x02\x0f\00\x82\x02\n\x02\x82\x02\x01\0\xd0`\x18\xad2s\x02c\xf9\x0f\xeeR>\xc1\x91_/\xaf\x97`\xf5\x01c2\xa3\x99\x94\x12\xd2;Ju\x02\x19\x12\x8d\x11\xdaq\xed\xf6Z>,\xd9\x9e4J\xa384ON\xf9G\xb7\xc2\xbdL\x83\x8c\xf9\xab\x0b\xfc\xd1zWgZ\xbbu\")8qP\xaa\xd9\xa9\xc3\x90\xbav\x1b\xf3\xc8W\xa1f\xce\xd0\xae\xb3\xa4\xcf\x1d\xf0my['\xa7\"\xe4\xc0\x1ek\x95kK\xe85X\xde\xd9Z\xab\xc5\x89{\xef,S\xacB\x11A\x92\x122\xff\xc6\x80\x96\xc0XX\x19~{\xb8\x98\xd2\x13\x192\xc6\x15\x8d\xf1z'\x949\x02\xe2q\x1f\xf7\x1d\xa3\x1d\x82\x1f\xecE\x18\xf1\n\xfc\x18]/\xaf(\xc3\xb6\xc4bH\xc8F\x9eTCT\xe6\xbd3\x1a2\x83a\n-\xaf\xe9\xa9\x99$\xeaUy\x96\x01'\xfa\xb7F\xd5c\xf1\x88\x025\xe3\x93\xadd\xbd\xc3\xfe\xe8H\xa6\xa2\x83\xfc\xa0\x08\xbe\x1a\x93\xcc\xc76\xd6\xde\xb5dv\xc6\xea\x1a\x93\x04p\x84\x1df\xb1m\xa5\x98\xe4\x1b\x7f\x842V\x8cP\xdf\x8di|\xd5\xb7*:D\xed`\xf9\xda\xad\xbf\xde@l\xfe\xd0l=\x02\xd1FO6\x1dxA\x90\xab\xfb\x81dE\xd9\x01|\x04\xb4]\x83k\xaag\xf7\xe0MEpv@\x0c\xc6x\xe8\xbf\xd0\xb6@\xed\xdbR\x06\xc7F\xd4\xaeK\xe3n$\x14\xa2%g&\x91tz`\"\x1bN\xefD\xeb\xa4\xca/W\x15l\xe1\xd7\x8d\x9frE\xb0\x8bu>,\xb0\x7fk \xc6\xb0P\xea\rU\x96\x91d\x901\x1d\x84n\xaa3O\n\xe9\xadrsD\t\xc7\xcfP\xf1\xed\x10]\xe7Z\x1c/,\xd8a\x9d\x01\xe5\xb0\xff[\xa8\x8d/\x86\xde\x10bQOw\xed\xf8\xf5\x1b\xa5\xe4\xdc\\\x8a>\x96|\xc19B\x05\xf7\xd5\xf6\xa0\x1f\xc9~\x9e\xb4\xeaH\x02\xfbz\xcf\xef\xa50U\xf1\xc5\xd3\xa0\xb4\xbf\x90\xbc\xb3O\xe50\x04/\xe9\x86\x97z\t\x94\x8b?\xbdB\xa5\xcf\xac\xe4\xf4I\x15\x06#\x05\xd7%\xeb\xcc\x89:\xad\x15&\xd1qb\x08I^\x0b'\x02\x03\x01\0\x01\xa3S0Q0\x1d\x06\x03U\x1d\x0e\x04\x16\x04\x14C2\x11w\xba\xb9\x0c\xae)\x8c\xe9\xc2\xae\x1ey\xfe\xf7\x7f\xae\xff0\x1f\x06\x03U\x1d#\x04\x180\x16\x80\x14C2\x11w\xba\xb9\x0c\xae)\x8c\xe9\xc2\xae\x1ey\xfe\xf7\x7f\xae\xff0\x0f\x06\x03U\x1d\x13\x01\x01\xff\x04\x050\x03\x01\x01\xff0\r\x06\t*\x86H\x86\xf7\r\x01\x01\x0b\x05\0\x03\x82\x02\x01\0\x97\x01\xb1\xb8\x06\x80\x10\x8a%6\t\x18\xf6\xd26\xbet\xb6n\xda\xb7\x14\xb28\xc0)\xc3\x0eo\xbf\xef.E\xc6k\x0e\x1e*\xa5\x8d\xe3\xd9\xed\xad\xa6\xbe\xc4\xd9\xad\x9c0\xa9LuJ\x1b\xaez\xc2\xc9\0\x91\x10E\x81\xcbK\x95O\xf3\xfc|\x05J\xf5_e\xa7On\xe5yK\xae\xb5\x1f\xacc3J\x10\x176\xea\xfa\x9d\xd1\n\x01-\xe0\x12&8D\x11*\xc7\x04\xf7\x99\xaf}\xc5Yp\x868\x90\xdf2\xedp^\xf4\"0:\xb0\x81A\xd6\xf7M\xc9\xdfh\xf9\xd2\xe6PN\x83\xf9\n\xfcO\x18\xd4\xc2#\xdbX.J#\xc6\\&\xd6m0\xb9\x93\xc8\xca\x80\x8e\xbfD\xcf\x9a6\x94\xd8F\x8a\xe7\xaf\x82\xc2\x8e\xa5\xad\x98\x9d\x0f\xd3IF\xcb\xba5MI\xe4\xb5\xa1\xf1=\xc2d\xc7\xc28\xbc&ZL\x11\\\x86\xe0\x10p.\xe9\xf6w\xf4\xe9\xfc#>\xf6M\xaf\x8f\xfb\x10@zA%R_\x16\xa4\xbd\xaeN\xbdl\xc9\xd368\xb6\xaf\xa5\x7f\x94\x8d\x1e\x0e\xfew\xd4\xce4\xba\xb9vx\xe9\x9f\xcaI4X#\xbe\x8bb\xf6\08\x9c\xf1?\x08\xe1}\xadl\x8a\xbc\xcaj\x08v\x03\x82*\xe7\xf2N\xffB\x82/\xdb\x0c\xfc#F\x87\x16\xf5\xedQ\x89|\x8b\x9c\x1c\x87\xa7\xf3\x834B\x02\xc7\xc44P \xb4M\xfd ?\xf7\xc9]c_\x17\xb9\xfd\xcbX\xd7\x9f\x18\xdf\xaae\xe0\xdf\xe0\"\xcc\xb9\xa9\x06\xb2\x16\x9f\xf2\x91kS\xe4o\xdfx3)\x17\xa6\x8c!\xff\x87U ~u:\xb1<\xa9c\xaf\x1a2\xad-m\x18\x0fo\x89\xc5\xc0\xe9\x06\x19\x19/4\xeb#\xc2z\xccr\xc4\xa4v$[\xda6w\xc6\xe4\xf3\xd1\xad4\xdbE\xda\0\t\x0cd}\x03\x182}\xfd\xa5\xecy\x97\x04.\xe6\xdeA\\3X\x01\x9e^\"\x14Qygr\xf3x;y\xfd\xac-\xaf\xd4&X5o\x8fe\xdd&b\xc0J\xb5\x9b\x95\x08\x8eX?\xe0\xd0\xad\x99~T\xfah\xf4\xbb\"\xbe\xce\xa0\x9a\x1fNcX\xe7;\xdc\x1c5\xc3\x03\x14\xa0"), exts: [] }] }) }, encoded: 0b0005d0000005cc0005c7308205c3308203aba0030201020214522cefa08f2550dea2365857891ddfb0eb2ca3d9300d06092a864886f70d01010b05003071310b300906035504061302434e310b300906035504080c024744310b300906035504070c02475a3111300f060355040a0c08504552534f4e414c310b3009060355040b0c024954310c300a06035504030c034e564b311a301806092a864886f70d010901160b616263406162632e636f6d301e170d3231313031363136323030375a170d3331313031343136323030375a3071310b300906035504061302434e310b300906035504080c024744310b300906035504070c02475a3111300f060355040a0c08504552534f4e414c310b3009060355040b0c024954310c300a06035504030c034e564b311a301806092a864886f70d010901160b616263406162632e636f6d30820222300d06092a864886f70d01010105000382020f003082020a0282020100d06018ad32730263f90fee523ec1915f2faf9760f5016332a3999412d23b4a750219128d11da71edf65a3e2cd99e344aa338344f4ef947b7c2bd4c838cf9ab0bfcd17a57675abb752229387150aad9a9c390ba761bf3c857a166ced0aeb3a4cf1df06d795b27a722e4c01e6b956b4be83558ded95aabc5897bef2c53ac421141921232ffc68096c05858197e7bb898d2131932c6158df17a27943902e2711ff71da31d821fec4518f10afc185d2faf28c3b6c46248c8469e544354e6bd331a3283610a2dafe9a99924ea5579960127fab746d563f1880235e393ad64bdc3fee848a6a283fca008be1a93ccc736d6deb56476c6ea1a930470841d66b16da598e41b7f8432568c50df8d697cd5b72a3a44ed60f9daadbfde406cfed06c3d02d1464f361d784190abfb816445d9017c04b45d836baa67f7e04d457076400cc678e8bfd0b640eddb5206c746d4ae4be36e2414a225672691747a60221b4eef44eba4ca2f57156ce1d78d9f7245b08b753e2cb07f6b20c6b050ea0d5596916490311d846eaa334f0ae9ad72734409c7cf50f1ed105de75a1c2f2cd8619d01e5b0ff5ba88d2f86de1062514f77edf8f51ba5e4dc5c8a3e967cc1394205f7d5f6a01fc97e9eb4ea4802fb7acfefa53055f1c5d3a0b4bf90bcb34fe530042fe986977a09948b3fbd42a5cface4f44915062305d725ebcc893aad1526d1716208495e0b270203010001a3533051301d0603551d0e0416041443321177bab90cae298ce9c2ae1e79fef77faeff301f0603551d2304183016801443321177bab90cae298ce9c2ae1e79fef77faeff300f0603551d130101ff040530030101ff300d06092a864886f70d01010b050003820201009701b1b80680108a25360918f6d236be74b66edab714b238c029c30e6fbfef2e45c66b0e1e2aa58de3d9edada6bec4d9ad9c30a94c754a1bae7ac2c90091104581cb4b954ff3fc7c054af55f65a74f6ee5794baeb51fac63334a101736eafa9dd10a012de012263844112ac704f799af7dc55970863890df32ed705ef422303ab08141d6f74dc9df68f9d2e6504e83f90afc4f18d4c223db582e4a23c65c26d66d30b993c8ca808ebf44cf9a3694d8468ae7af82c28ea5ad989d0fd34946cbba354d49e4b5a1f13dc264c7c238bc265a4c115c86e010702ee9f677f4e9fc233ef64daf8ffb10407a4125525f16a4bdae4ebd6cc9d33638b6afa57f948d1e0efe77d4ce34bab97678e99fca49345823be8b62f600389cf13f08e17dad6c8abcca6a087603822ae7f24eff42822fdb0cfc23468716f5ed51897c8b9c1c87a7f383344202c7c4345020b44dfd203ff7c95d635f17b9fdcb58d79f18dfaa65e0dfe022ccb9a906b2169ff2916b53e46fdf78332917a68c21ff8755207e753ab13ca963af1a32ad2d6d180f6f89c5c0e90619192f34eb23c27acc72c4a476245bda3677c6e4f3d1ad34db45da00090c647d0318327dfda5ec7997042ee6de415c3358019e5e221451796772f3783b79fdac2dafd42658356f8f65dd2662c04ab59b95088e583fe0d0ad997e54fa68f4bb22becea09a1f4e6358e73bdc1c35c30314a00000 } }
2022-12-24T03:09:02.856886Z TRACE first recv:frame{ty=CRYPTO}: rustls::server::tls13::client_hello: sending certificate-verify Message { version: TLSv1_3, payload: Handshake { parsed: HandshakeMessagePayload { typ: CertificateVerify, payload: CertificateVerify(DigitallySignedStruct { scheme: RSA_PSS_SHA512, sig: 5a32f7ffe2ec0b9a7aec828ff8b5466b92fd7283175b9cfec92f85f43471fe9b6629666d6408749a88a9f9b142ccc8cb29a2f40d959b31043b616e7b9399ea0cec589711520535f3d4dcd1b041c1d57418868579f431e5e65d9b79a3b68666b7ecf5ec175bd623492d39fc879ce19943411d67c9f7d35b84b2a9bd0a89c77d00f344c037e4fde98439421e1b925c0550f6bb972f6c70684346ef6dd5fa3aa3493ace566333cd01d1f62de30dcb0ba5370b7feb7708914840b5727df3eeabacb7082073e37f6bf3342bd22968d3f903f1c78f06f2432a5d819c05b767079a532c78ba60727955bece2f39e102e9b1b8cc50efd3a459d1a8cb505f1553ec09566f0deeb51a75ac03a1b91f05b12312d678c928ea978945ca547b7a7c980a293a76d7e636603434c2693e0e132531ab4780c7bc736baa2683f324a2df3e2d9b58de728351eb864e3e3193cbd9be74a5cd998728b6398243797a8dd673a15493d57dd81c09a88a2e93acf76806ad345d6740a9f8c6c40346bd066c2e1f89c8ae4d3c5ba2427dfe7712d5d6abd553f4e81a2d498ad0fbbbf4d7ee2f8b2e36bd01395b55867c8617fdc1c9aab1d687b9a0ae65eec4ece9094965d003e983283a60cb9a02ab044197e46d2fb65cf2f1b72da51578ecd2ad33f4bdffbe8d95c515a9dacb1c24b3ce5074f4851dc630c2598cbe0fcffc567fcbc0fd96a725b825ceb88380 }) }, encoded: 0f000204080602005a32f7ffe2ec0b9a7aec828ff8b5466b92fd7283175b9cfec92f85f43471fe9b6629666d6408749a88a9f9b142ccc8cb29a2f40d959b31043b616e7b9399ea0cec589711520535f3d4dcd1b041c1d57418868579f431e5e65d9b79a3b68666b7ecf5ec175bd623492d39fc879ce19943411d67c9f7d35b84b2a9bd0a89c77d00f344c037e4fde98439421e1b925c0550f6bb972f6c70684346ef6dd5fa3aa3493ace566333cd01d1f62de30dcb0ba5370b7feb7708914840b5727df3eeabacb7082073e37f6bf3342bd22968d3f903f1c78f06f2432a5d819c05b767079a532c78ba60727955bece2f39e102e9b1b8cc50efd3a459d1a8cb505f1553ec09566f0deeb51a75ac03a1b91f05b12312d678c928ea978945ca547b7a7c980a293a76d7e636603434c2693e0e132531ab4780c7bc736baa2683f324a2df3e2d9b58de728351eb864e3e3193cbd9be74a5cd998728b6398243797a8dd673a15493d57dd81c09a88a2e93acf76806ad345d6740a9f8c6c40346bd066c2e1f89c8ae4d3c5ba2427dfe7712d5d6abd553f4e81a2d498ad0fbbbf4d7ee2f8b2e36bd01395b55867c8617fdc1c9aab1d687b9a0ae65eec4ece9094965d003e983283a60cb9a02ab044197e46d2fb65cf2f1b72da51578ecd2ad33f4bdffbe8d95c515a9dacb1c24b3ce5074f4851dc630c2598cbe0fcffc567fcbc0fd96a725b825ceb88380 } }  
2022-12-24T03:09:02.857133Z TRACE first recv:frame{ty=CRYPTO}: rustls::server::tls13::client_hello: sending finished Message { version: TLSv1_3, payload: Handshake { parsed: HandshakeMessagePayload { typ: Finished, payload: Finished(bb98b599636a4ca82d19266a73a75202340f63463a6598ba3f8a780c2105e91e) }, encoded: 14000020bb98b599636a4ca82d19266a73a75202340f63463a6598ba3f8a780c2105e91e } }
2022-12-24T03:09:02.857373Z TRACE first recv: quinn_proto::connection: Handshake keys ready
2022-12-24T03:09:02.857466Z TRACE first recv: quinn_proto::connection: wrote 90 Initial CRYPTO bytes
2022-12-24T03:09:02.857569Z TRACE first recv: quinn_proto::connection: Data keys ready
2022-12-24T03:09:02.857602Z TRACE first recv: quinn_proto::connection: wrote 2169 Handshake CRYPTO bytes
2022-12-24T03:09:02.857903Z TRACE quinn_proto::endpoint: connection incoming id=0 icid=04b9089e90cbca2a72626816df059dbe9c287ca1
2022-12-24T03:09:02.858079Z TRACE drive{id=0}:send{space=Initial pn=0}: quinn_proto::connection: ACK ArrayRangeSet([0..1]), Delay = 0us
2022-12-24T03:09:02.858101Z TRACE drive{id=0}:send{space=Initial pn=0}: quinn_proto::connection: CRYPTO: off 0 len 90
2022-12-24T03:09:02.858498Z TRACE drive{id=0}:send{space=Handshake pn=0}: quinn_proto::connection: CRYPTO: off 0 len 1009
2022-12-24T03:09:02.858636Z TRACE drive{id=0}: quinn_proto::connection: sending 1200 bytes in 1 datagrams
2022-12-24T03:09:02.858672Z TRACE drive{id=0}:send{space=Handshake pn=1}: quinn_proto::connection: CRYPTO: off 1009 len 1153
2022-12-24T03:09:02.858735Z TRACE drive{id=0}: quinn_proto::connection: sending 1200 bytes in 1 datagrams
2022-12-24T03:09:02.858761Z TRACE drive{id=0}:send{space=Handshake pn=2}: quinn_proto::connection: CRYPTO: off 2162 len 7
2022-12-24T03:09:02.858847Z TRACE drive{id=0}: quinn_proto::connection: sending 53 bytes in 1 datagrams
2022-12-24T03:09:02.859083Z TRACE drive{id=0}:send{space=Data pn=0}: quinn_proto::connection: NEW_CONNECTION_ID sequence=1 id=0bff0f6402ec3e10
2022-12-24T03:09:02.859108Z TRACE drive{id=0}:send{space=Data pn=0}: quinn_proto::connection: NEW_CONNECTION_ID sequence=2 id=4b68119921ebd4f4
2022-12-24T03:09:02.859127Z TRACE drive{id=0}:send{space=Data pn=0}: quinn_proto::connection: NEW_CONNECTION_ID sequence=3 id=3b9c15fe280ef84b
2022-12-24T03:09:02.859145Z TRACE drive{id=0}:send{space=Data pn=0}: quinn_proto::connection: NEW_CONNECTION_ID sequence=4 id=01a2d8fb4b17b2ba
2022-12-24T03:09:02.859294Z TRACE drive{id=0}: quinn_proto::connection: sending 138 bytes in 1 datagrams
2022-12-24T03:09:02.860849Z TRACE drive{id=0}: quinn_proto::connection: got Initial packet (51 bytes) from 127.0.0.1:57753 using id fa232e8d449b3a76
2022-12-24T03:09:02.860937Z TRACE drive{id=0}: quinn_proto::connection: got Handshake packet (1149 bytes) from 127.0.0.1:57753 using id fa232e8d449b3a76
2022-12-24T03:09:02.860969Z TRACE drive{id=0}:recv{space=Handshake pn=0}: quinn_proto::connection: discarding Initial keys
2022-12-24T03:09:02.861143Z TRACE drive{id=0}:recv{space=Handshake pn=0}: quinn_proto::connection: handshake ongoing
2022-12-24T03:09:02.861539Z TRACE drive{id=0}: quinn_proto::connection: got Handshake packet (50 bytes) from 127.0.0.1:57753 using id fa232e8d449b3a76
2022-12-24T03:09:02.861583Z TRACE drive{id=0}:recv{space=Handshake pn=1}: quinn_proto::connection: handshake ongoing
2022-12-24T03:09:02.862489Z TRACE drive{id=0}: quinn_proto::connection: got Handshake packet (89 bytes) from 127.0.0.1:57753 using id fa232e8d449b3a76
2022-12-24T03:09:02.862542Z TRACE drive{id=0}:recv{space=Handshake pn=2}:frame{ty=CRYPTO}: quinn_proto::connection: consumed 36 CRYPTO bytes
2022-12-24T03:09:02.862612Z TRACE drive{id=0}:recv{space=Handshake pn=2}:frame{ty=CRYPTO}: rustls::server::tls13: sending new ticket Message { version: TLSv1_3, payload: Handshake { parsed: HandshakeMessagePayload { typ: NewSessionTicket, payload: NewSessionTicketTLS13(NewSessionTicketPayloadTLS13 { lifetime: 86400, age_add: 1549723023, nonce: ba104f9f31f50126893045189f64153d5b90750a28588982e6e2f24dc13a0c9b, ticket: 5b3c75c09e668c8beda18ce8bb6f0e63378daa6a3577214be980f45e99a1d6bb, exts: [] }) }, encoded: 0400004d000151805c5ee58f20ba104f9f31f50126893045189f64153d5b90750a28588982e6e2f24dc13a0c9b00205b3c75c09e668c8beda18ce8bb6f0e63378daa6a3577214be980f45e99a1d6bb0000 } } (stateless: false)
2022-12-24T03:09:02.862666Z TRACE drive{id=0}:recv{space=Handshake pn=2}: quinn_proto::connection: wrote 81 Data CRYPTO bytes
2022-12-24T03:09:02.862687Z TRACE drive{id=0}:recv{space=Handshake pn=2}: quinn_proto::connection: discarding Handshake keys
2022-12-24T03:09:02.862703Z TRACE drive{id=0}:recv{space=Handshake pn=2}: quinn_proto::connection: established
2022-12-24T03:09:02.862735Z TRACE drive{id=0}:send{space=Data pn=1}: quinn_proto::connection: CRYPTO: off 0 len 81
2022-12-24T03:09:02.862762Z TRACE drive{id=0}: quinn_proto::connection: sending 112 bytes in 1 datagrams
2022-12-24T03:09:02.862801Z  INFO rstun::server: received connection, authenticating... addr:127.0.0.1:57753
2022-12-24T03:09:02.862828Z  INFO rstun::server: received bi_stream request, addr: 127.0.0.1:57753
2022-12-24T03:09:02.863132Z TRACE drive{id=0}: quinn_proto::connection: got Data packet (146 bytes) from 127.0.0.1:57753 using id fa232e8d449b3a76
2022-12-24T03:09:02.863170Z TRACE drive{id=0}:recv{space=Data pn=0}: quinn_proto::connection: got frame Ack(Ack { largest: 0, delay: 0, ecn: Some(EcnCounts { ect0: 1, ect1: 0, ce: 0 }), ranges: "[0..=0]" })
2022-12-24T03:09:02.863226Z TRACE drive{id=0}:recv{space=Data pn=0}: quinn_proto::connection: got frame NewConnectionId(NewConnectionId { sequence: 1, retire_prior_to: 0, id: [109, 230, 34, 202, 84, 216, 199, 227], reset_token: ResetToken([200, 196, 90, 248, 101, 63, 133, 52, 173, 85, 199, 225, 128, 120, 166, 228]) })
2022-12-24T03:09:02.863250Z TRACE drive{id=0}:recv{space=Data pn=0}:frame{ty=NEW_CONNECTION_ID}: quinn_proto::connection: sequence=1 id=6de622ca54d8c7e3 retire_prior_to=0
2022-12-24T03:09:02.863286Z TRACE drive{id=0}:recv{space=Data pn=0}: quinn_proto::connection: got frame NewConnectionId(NewConnectionId { sequence: 2, retire_prior_to: 0, id: [188, 83, 144, 64, 226, 104, 104, 215], reset_token: ResetToken([127, 131, 172, 223, 246, 40, 145, 202, 40, 81, 187, 192, 70, 188, 77, 169]) })
2022-12-24T03:09:02.863306Z TRACE drive{id=0}:recv{space=Data pn=0}:frame{ty=NEW_CONNECTION_ID}: quinn_proto::connection: sequence=2 id=bc539040e26868d7 retire_prior_to=0
2022-12-24T03:09:02.863338Z TRACE drive{id=0}:recv{space=Data pn=0}: quinn_proto::connection: got frame NewConnectionId(NewConnectionId { sequence: 3, retire_prior_to: 0, id: [76, 185, 220, 23, 0, 121, 51, 20], reset_token: ResetToken([157, 160, 96, 18, 150, 32, 183, 163, 61, 226, 86, 199, 76, 134, 79, 132]) })
2022-12-24T03:09:02.863358Z TRACE drive{id=0}:recv{space=Data pn=0}:frame{ty=NEW_CONNECTION_ID}: quinn_proto::connection: sequence=3 id=4cb9dc1700793314 retire_prior_to=0
2022-12-24T03:09:02.863389Z TRACE drive{id=0}:recv{space=Data pn=0}: quinn_proto::connection: got frame NewConnectionId(NewConnectionId { sequence: 4, retire_prior_to: 0, id: [117, 15, 40, 40, 193, 73, 217, 59], reset_token: ResetToken([131, 167, 211, 60, 181, 247, 243, 36, 108, 203, 136, 184, 74, 137, 223, 231]) })
2022-12-24T03:09:02.863409Z TRACE drive{id=0}:recv{space=Data pn=0}:frame{ty=NEW_CONNECTION_ID}: quinn_proto::connection: sequence=4 id=750f2828c149d93b retire_prior_to=0
2022-12-24T03:09:02.863451Z TRACE drive{id=0}:send{space=Data pn=2}: quinn_proto::connection: ACK ArrayRangeSet([0..1]), Delay = 0us
2022-12-24T03:09:02.863469Z TRACE drive{id=0}:send{space=Data pn=2}: quinn_proto::connection: RETIRE_CONNECTION_ID sequence=0
2022-12-24T03:09:02.863497Z TRACE drive{id=0}: quinn_proto::connection: sending 36 bytes in 1 datagrams
2022-12-24T03:09:02.863558Z TRACE drive{id=0}: quinn_proto::connection: got Data packet (34 bytes) from 127.0.0.1:57753 using id fa232e8d449b3a76
2022-12-24T03:09:02.863589Z TRACE drive{id=0}:recv{space=Data pn=1}: quinn_proto::connection: got frame Ack(Ack { largest: 1, delay: 0, ecn: Some(EcnCounts { ect0: 2, ect1: 0, ce: 0 }), ranges: "[0..=1]" })
2022-12-24T03:09:02.863651Z TRACE drive{id=0}: quinn_proto::connection: got Data packet (71 bytes) from 127.0.0.1:57753 using id fa232e8d449b3a76
2022-12-24T03:09:02.863682Z TRACE drive{id=0}:recv{space=Data pn=2}: quinn_proto::connection: got stream frame id=client bidirectional stream 0 offset=0 len=42 fin=false
2022-12-24T03:09:02.863727Z TRACE drive{id=0}:send{space=Data pn=3}: quinn_proto::connection: ACK ArrayRangeSet([0..3]), Delay = 0us
2022-12-24T03:09:02.863752Z TRACE drive{id=0}: quinn_proto::connection: sending 34 bytes in 1 datagrams
2022-12-24T03:09:02.863872Z TRACE drive{id=0}: quinn_proto::connection: got Data packet (34 bytes) from 127.0.0.1:57753 using id fa232e8d449b3a76
2022-12-24T03:09:02.864532Z TRACE drive{id=0}:recv{space=Data pn=3}: quinn_proto::connection: got frame Ack(Ack { largest: 2, delay: 0, ecn: Some(EcnCounts { ect0: 3, ect1: 0, ce: 0 }), ranges: "[1..=2]" })
2022-12-24T03:09:02.864592Z TRACE drive{id=0}: quinn_proto::connection: got Data packet (54 bytes) from 127.0.0.1:57753 using id fa232e8d449b3a76
2022-12-24T03:09:02.864622Z TRACE drive{id=0}:recv{space=Data pn=4}: quinn_proto::connection: got frame NewConnectionId(NewConnectionId { sequence: 5, retire_prior_to: 0, id: [56, 143, 12, 57, 121, 35, 49, 198], reset_token: ResetToken([214, 54, 211, 183, 73, 171, 49, 141, 168, 209, 253, 229, 0, 247, 250, 73]) })
2022-12-24T03:09:02.864642Z TRACE drive{id=0}:recv{space=Data pn=4}:frame{ty=NEW_CONNECTION_ID}: quinn_proto::connection: sequence=5 id=388f0c39792331c6 retire_prior_to=0
2022-12-24T03:09:02.864683Z TRACE drive{id=0}:send{space=Data pn=4}: quinn_proto::connection: ACK ArrayRangeSet([1..5]), Delay = 0us
2022-12-24T03:09:02.864707Z TRACE drive{id=0}: quinn_proto::connection: sending 34 bytes in 1 datagrams
2022-12-24T03:09:22.866545Z TRACE drive{id=0}: quinn_proto::connection: timeout timer=KeepAlive
2022-12-24T03:09:22.866715Z TRACE drive{id=0}: quinn_proto::connection: sending keep-alive
2022-12-24T03:09:22.867046Z TRACE drive{id=0}:send{space=Data pn=5}: quinn_proto::connection: PING
2022-12-24T03:09:22.867166Z TRACE drive{id=0}:send{space=Data pn=5}: quinn_proto::connection::packet_builder: PADDING * 3
2022-12-24T03:09:22.867393Z TRACE drive{id=0}: quinn_proto::connection: sending 30 bytes in 1 datagrams
2022-12-24T03:09:22.869947Z TRACE drive{id=0}: quinn_proto::connection: got Data packet (34 bytes) from 127.0.0.1:57753 using id fa232e8d449b3a76
2022-12-24T03:09:22.870229Z TRACE drive{id=0}:recv{space=Data pn=5}: quinn_proto::connection: got frame Ack(Ack { largest: 5, delay: 0, ecn: Some(EcnCounts { ect0: 6, ect1: 0, ce: 0 }), ranges: "[3..=5]" })
2022-12-24T03:09:42.871306Z TRACE drive{id=0}: quinn_proto::connection: timeout timer=KeepAlive
2022-12-24T03:09:42.871473Z TRACE drive{id=0}: quinn_proto::connection: sending keep-alive
2022-12-24T03:09:42.871784Z TRACE drive{id=0}:send{space=Data pn=6}: quinn_proto::connection: PING
2022-12-24T03:09:42.871900Z TRACE drive{id=0}:send{space=Data pn=6}: quinn_proto::connection::packet_builder: PADDING * 3
2022-12-24T03:09:42.872119Z TRACE drive{id=0}: quinn_proto::connection: sending 30 bytes in 1 datagrams
2022-12-24T03:09:42.874446Z TRACE drive{id=0}: quinn_proto::connection: got Data packet (34 bytes) from 127.0.0.1:57753 using id fa232e8d449b3a76
2022-12-24T03:09:42.874753Z TRACE drive{id=0}:recv{space=Data pn=6}: quinn_proto::connection: got frame Ack(Ack { largest: 6, delay: 0, ecn: Some(EcnCounts { ect0: 7, ect1: 0, ce: 0 }), ranges: "[3..=6]" })

Or you can run the test using this repo: https://github.com/neevek/rstun/tree/dev

  1. Start the server
./target/debug/rstund -l0.0.0.0:3515 -d0.0.0.0:0 -t1 -p1234 -c./localhost.crt.der -k./localhost.key.der
  1. Start the client
./target/debug/rstunc -mOUT -r127.0.0.1:3515 -p1234 -c./localhost.crt.der -a0.0.0.0:0^0

or

./target/debug/rstunc -mOUT -r0.0.0.0:3515 -p1234 -c./localhost.crt.der -a0.0.0.0:0^0

@Ralith
Copy link
Collaborator

Ralith commented Dec 24, 2022 •
edited
Loading

When both the client and server run locally, server listens on 0.0.0.0, that client connects to it using 0.0.0.0 hangs without passing the handshake phase.

0.0.0.0 is not an IP address, but a wildcard value that means "all addresses." It is not a meaningful target to connect to; this will fail under any protocol. We should add a check for this, as you're not the first to be tripped up.

the server calls RecvStream::read_exact() to read first 4 bytes as the message length, but never returns

This is a separate problem. Logs indicate that your server has received the data. Looking at your code, I'm guessing
https://github.com/neevek/rstun/blob/b97733b3ae2fd955def77f8b4027544ab16fda1b/src/server.rs#L133-L139 is where the server gets stuck. Your server is creating a new stream, then immediately trying to read data from it. The client does not know this stream exists, because QUIC streams are not visible to the peer until you send something on them. Meanwhile, the client has sent its message on a different stream that it created itself (note "client bidirectional stream 0" in the logs), which you are not attempting to read. You probably intended to use accept_bi, to get the client-initiated stream, rather than creating a new one with open_bi.

@Ralith Ralith mentioned this issue Dec 24, 2022
Merged
@neevek
Copy link
Author

neevek commented Dec 25, 2022

You probably intended to use accept_bi, to get the client-initiated stream, rather than creating a new one with open_bi.

This is the exact culprit, thank you so much! Now the code runs as fast as a rocket!

@Ralith
Copy link
Collaborator

Ralith commented Dec 26, 2022

Glad to hear it!

@Ralith Ralith closed this as completed Dec 26, 2022
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
3 participants
@Ralith @neevek @dzvon