sozu
sozu copied to clipboard
sozu-proxy
rustls proxy might be broken
While testing 0.14 with rustls, I encounter this error on every HTTPS request (with trace level logs):
2021-September-23T09:07:27.070263Z 1632388047070263293 2027840 WRK-00 TRACE sozu_lib::timer inserted timeout; slot=121; token=Token(0)
2021-September-23T09:07:27.071405Z 1632388047071405896 2027840 WRK-00 TRACE sozu_lib::tls trying to resolve name: "unhandledexpression.com" for signature scheme: [ECDSA_NISTP256_SHA256, RSA_PSS_SHA256, RSA_PKCS1_SHA256, ECDSA_NISTP384_SHA384, RSA_PSS_SHA384, RSA_PKCS1_SHA384, RSA_PSS_SHA512, RSA_PKCS1_SHA512]
2021-September-23T09:07:27.071876Z 1632388047071876442 2027840 WRK-00 TRACE sozu_lib::tls looking for certificate for "unhandledexpression.com" with fingerprint CertificateFingerprint(502176ef7ffb1a53cabb5cf484414c348a88af0347e1cd367ad7a237bb8be282)
2021-September-23T09:07:27.090921Z 1632388047090921966 2027840 WRK-00 TRACE sozu_lib::https_rustls::session front readable interpreting session order Continue
2021-September-23T09:07:27.091019Z 1632388047091019224 2027840 WRK-00 TRACE sozu_lib::https_rustls::session PROXY Token(5) F:Readiness { interest: RWEH, readiness: -W--, mixed: -W-- } B:None
2021-September-23T09:07:27.091170Z 1632388047091170408 2027840 WRK-00 TRACE sozu_lib::https_rustls::session front writable interpreting session order Continue
2021-September-23T09:07:27.091220Z 1632388047091220591 2027840 WRK-00 TRACE sozu_lib::https_rustls::session PROXY Token(5) F:Readiness { interest: R-EH, readiness: -W--, mixed: ---- } B:None
2021-September-23T09:07:27.114857Z 1632388047114857397 2027840 WRK-00 TRACE sozu_lib::server PROXY Token(5) got events: Readable | Writable
2021-September-23T09:07:27.114956Z 1632388047114956910 2027840 WRK-00 TRACE sozu_lib::https_rustls::session token Token(5) got event RW--
2021-September-23T09:07:27.115026Z 1632388047115026041 2027840 WRK-00 TRACE sozu_lib::https_rustls::session PROXY Token(5) F:Readiness { interest: R-EH, readiness: RW--, mixed: R--- } B:None
2021-September-23T09:07:27.115086Z 1632388047115086844 2027840 WRK-00 TRACE sozu_lib::timer unlinking timeout; slot=121; token=Token(0)
2021-September-23T09:07:27.115139Z 1632388047115139294 2027840 WRK-00 TRACE sozu_lib::timer setting timeout; delay=Duration { seconds: 12, nanoseconds: 100697728 }; tick=121; current-tick=22
2021-September-23T09:07:27.115189Z 1632388047115189633 2027840 WRK-00 TRACE sozu_lib::timer inserted timeout; slot=121; token=Token(0)
2021-September-23T09:07:27.115365Z 1632388047115365034 2027840 WRK-00 ERROR TLS alert received: Message {
typ: Alert,
version: TLSv1_3,
payload: Alert(
AlertMessagePayload {
level: Fatal,
description: CertificateRequired,
},
),
}
2021-September-23T09:07:27.115526Z 1632388047115526526 2027840 WRK-00 ERROR could not perform handshake: AlertReceived(CertificateRequired)
Apparently the certificate is correctly looked up by the resolver, but still not used by rustls in the handshake
So, I set up a sozu with rustls and execute a curl request and this what I got:
On the client side:
$ curl -s -vvvv https://localhost:10443
* Trying 127.0.0.1:10443...
* Connected to localhost (127.0.0.1) port 10443 (#0)
* ALPN, offering h2
* ALPN, offering http/1.1
* successfully set certificate verify locations:
* CAfile: none
* CApath: /etc/ssl/certs
* TLSv1.3 (OUT), TLS handshake, Client hello (1):
* TLSv1.3 (IN), TLS handshake, Server hello (2):
* TLSv1.3 (IN), TLS handshake, Encrypted Extensions (8):
* TLSv1.3 (IN), TLS handshake, Certificate (11):
* TLSv1.3 (OUT), TLS alert, decode error (562):
* error:1416F09F:SSL routines:tls_process_server_certificate:length mismatch
* Closing connection 0
On the server side, I got the following log once I updated log message:
2021-September-27T08:55:54.566964Z 1632732954566964223 13925 WRK-00 ERROR read socket, on new packets, could not perform handshake: DecryptError
The error come from https://github.com/sozu-proxy/sozu/blob/0.14/lib/src/protocol/rustls.rs#L63
This error is already present on the main branch, it should be something else
ok. That looks like something that would be hard to debug, but easy to bisect. Could you show @Keksoj how to do that? It's a good learning experience :wink:
It looks like it is related to the pull request #700, I introduce a first patch with the pull request #736, but I have seen another issue during end to end tests that I need to dig