Running rustls example results in panic on the server side

[andreiltd]

Bug Report

Version

master

Platform

Linux pop-os 6.0.6-76060006-generic x86_64

Description

Running tls_rustls example results in panic on the server side:

server: cargo run --bin tls-server-rustls
client: cargo run --bin tls-client-rustls

then on server:

Got a request from: [::1]:59296 with certs: []
thread 'tokio-runtime-worker' panicked at 'called `Result::unwrap()` on an `Err` value: hyper::Error(Io, Kind(UnexpectedEof))', examples/src/tls/server_rustls.rs:88:52
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace

Expected behavior: example is working without errors.

[LucioFranco]

It works for me locally on my mac so not sure why its failing for you

server:

     Running `target/debug/tls-server-rustls`                                                                                                                                         │
Got a request from: [::1]:60564 with certs: []  

client:

RESPONSE=Response { metadata: MetadataMap { headers: {"content-type": "application/grpc", "date": "Mon, 12 Dec 2022 19:07:24 GMT", "grpc-status": "0"} }, message: EchoResponse { message: "hello" }, extensions: Extensions }

[LucioFranco]

You could try enabling logging to see if it tells you anything.

[andreiltd]

Hey! Thanks for the reply, I can retry with logs enabled. The other problem I had is that the list of client certs is empty: with certs: [], shouldn't this contain client certificates?

[andreiltd]

Here is the output log, but I don't see any obvious problem 🤔

     Running `target/debug/tls-server-rustls`
2022-12-12T19:17:43.697143Z DEBUG rustls::server::hs: decided upon suite TLS13_AES_256_GCM_SHA384    
2022-12-12T19:17:43.697577Z DEBUG rustls::server::hs: Chosen ALPN protocol [104, 50]    
2022-12-12T19:17:43.699470Z DEBUG h2::codec::framed_write: send frame=Settings { flags: (0x0), initial_window_size: 1048576, max_frame_size: 16384, max_header_list_size: 16777216 }
2022-12-12T19:17:43.699741Z DEBUG Connection{peer=Server}: h2::codec::framed_read: received frame=Settings { flags: (0x0), enable_push: 0, initial_window_size: 2097152, max_frame_size: 16384 }
2022-12-12T19:17:43.699770Z DEBUG Connection{peer=Server}: h2::codec::framed_write: send frame=Settings { flags: (0x1: ACK) }
2022-12-12T19:17:43.699789Z DEBUG Connection{peer=Server}: h2::codec::framed_read: received frame=WindowUpdate { stream_id: StreamId(0), size_increment: 5177345 }
2022-12-12T19:17:43.699812Z DEBUG Connection{peer=Server}: h2::codec::framed_write: send frame=WindowUpdate { stream_id: StreamId(0), size_increment: 983041 }
2022-12-12T19:17:43.699904Z DEBUG Connection{peer=Server}: h2::codec::framed_read: received frame=Settings { flags: (0x1: ACK) }
2022-12-12T19:17:43.699921Z DEBUG Connection{peer=Server}: h2::proto::settings: received settings ACK; applying Settings { flags: (0x0), initial_window_size: 1048576, max_frame_size: 16384, max_header_list_size: 16777216 }
2022-12-12T19:17:43.700171Z DEBUG Connection{peer=Server}: h2::codec::framed_read: received frame=Headers { stream_id: StreamId(1), flags: (0x4: END_HEADERS) }
2022-12-12T19:17:43.700226Z DEBUG Connection{peer=Server}: h2::codec::framed_read: received frame=Data { stream_id: StreamId(1) }
2022-12-12T19:17:43.700246Z DEBUG Connection{peer=Server}: h2::codec::framed_read: received frame=Data { stream_id: StreamId(1), flags: (0x1: END_STREAM) }
Got a request from: [::1]:46330 with certs: []
2022-12-12T19:17:43.700508Z DEBUG Connection{peer=Server}: h2::codec::framed_write: send frame=Headers { stream_id: StreamId(1), flags: (0x4: END_HEADERS) }
2022-12-12T19:17:43.700567Z DEBUG Connection{peer=Server}: h2::codec::framed_write: send frame=Data { stream_id: StreamId(1) }
2022-12-12T19:17:43.700594Z DEBUG Connection{peer=Server}: h2::codec::framed_write: send frame=Headers { stream_id: StreamId(1), flags: (0x5: END_HEADERS | END_STREAM) }
2022-12-12T19:17:43.701357Z DEBUG Connection{peer=Server}: h2::proto::connection: Connection::poll; IO error error=UnexpectedEof
thread 'tokio-runtime-worker' panicked at 'called `Result::unwrap()` on an `Err` value: hyper::Error(Io, Kind(UnexpectedEof))', examples/src/tls/server_rustls.rs:92:52
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace

[LucioFranco]

Can you tell me what commit you're on? And verify you've changed nothing? Maybe this has to do with linux kernel 6

[andreiltd]

I'm on d00fd08. I have no local changes other than logging enabled (but initially checked without logging)

diff --git a/examples/src/tls/server_rustls.rs b/examples/src/tls/server_rustls.rs
index 8985cf0..e2371e4 100644
--- a/examples/src/tls/server_rustls.rs
+++ b/examples/src/tls/server_rustls.rs
@@ -12,9 +12,13 @@ use tokio_rustls::{
 };
 use tonic::{transport::Server, Request, Response, Status};
 use tower_http::ServiceBuilderExt;
+use tracing_subscriber::EnvFilter;
 
 #[tokio::main]
 async fn main() -> Result<(), Box<dyn std::error::Error>> {
+    let filter = EnvFilter::try_from_default_env().unwrap_or_else(|_| EnvFilter::new("debug"));
+    tracing_subscriber::fmt().with_env_filter(filter).init();
+
     let certs = {
         let fd = std::fs::File::open("examples/data/tls/server.pem")?;
         let mut buf = std::io::BufReader::new(&fd);

[andreiltd]

Let me know what else I can check. I'm happy to dig into this :)

[LucioFranco]

Could you clarify the full version of your OS and linux kernel? I am having trouble finding out what version you are using etc.

[andreiltd]

OS: Pop!_OS 22.04 LTS
Linux version: 6.0.6-76060006-generic (jenkins@warp.pop-os.org)

It is based on Ubuntu 22.04 LTS, but they provide updated kernel, I guess.

[crisidev]

I can reproduce on ubuntu 22.04 with 6.0.0-1007-oem.

[LucioFranco]

Same here I can reproduce it on debian with kernel 6. I also updated my code locally on my mac and was not able to reproduce with the same version of rustls. Additionally, this only happens with the rustls and not the general helloworld.

[LucioFranco]

Ok so its not a linux kernel 6+ issue, I am seeing it on 5.4 as well.

[LucioFranco]

Okay so I've been digging some more, beyond the UnexpectedEof I am also seeing NotConnected errors crop up. I wrote a fix for it here hyperium/h2#654.

As for the eof part of this, I am still debugging it but it doesn'thappen

@quinner do you have any idea? When I get eof I see there is around 8k bytes in the buf and thats why its returning eof but I don't know beyond that why its failing.