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 :thinking:

     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 https://github.com/hyperium/tonic/commit/d00fd0838bcd84d1f96703af1a9a14deed786154. 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 https://github.com/hyperium/h2/pull/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.

[dinoling]

Platform server : almalinux 9.1 client : windows 11

the same happens

The client does not send out "warning alert Close_Notify", not every time

[Nehliin]

@LucioFranco we've experienced this as well a lot seemingly randomly in prod and I wonder if you think these two issues could be related https://github.com/hyperium/h2/issues/636?

[xandkar]

Same two symptoms for me in examples/src/tls_rustls/server.rs:

1. http.serve_connection(conn, svc).await --> hyper::Error(Io, Kind(UnexpectedEof)) ;
2. info.peer_certificates() --> None.

My setup:

1. Void Linux, kernel 6.6.16_1;
2. rustc 1.75.0 (82e1608df 2023-12-21);
3. tonic 233711a72a63f746d386916990fc817e36eabd80.

Also happens outside of examples in the repo, in another project where dep versions mostly mirror those from the examples:

[dependencies]
clap = { version = "4.5.1", features = ["derive"] }
hyper = "0.14"
prost = "0.12.3"
rustls-pemfile = "1"
tokio = { version = "1.36.0", features = ["full"] }
tokio-rustls = "0.24.0"
hyper-rustls = {version = "0.24.0", features = ["http2"]}
tonic = "0.11.0"
tower = "0.4.13"
anyhow = { version = "1.0.80", features = ["backtrace"] }
tower-http = { version = "0.4", features = ["add-extension", "util"] }

[build-dependencies]
tonic-build = "0.11.0"

Consistently, every time, not just intermittent/random.

[kc1212]

I'm also having this issue on macOS 14.3 with rustc 1.76.0. This repo https://github.com/kc1212/tonic-tls-poc will reproduce the issue by starting the server and then the client. The code is essentially what is in the rustls example. Below is the error message:

thread 'tokio-runtime-worker' panicked at src/server.rs:93:52:
called `Result::unwrap()` on an `Err` value: hyper::Error(Io, Kind(UnexpectedEof))
stack backtrace:
   0: rust_begin_unwind
             at /rustc/07dca489ac2d933c78d3c5158e3f43beefeb02ce/library/std/src/panicking.rs:645:5
   1: core::panicking::panic_fmt
             at /rustc/07dca489ac2d933c78d3c5158e3f43beefeb02ce/library/core/src/panicking.rs:72:14
   2: core::result::unwrap_failed
             at /rustc/07dca489ac2d933c78d3c5158e3f43beefeb02ce/library/core/src/result.rs:1649:5
   3: server::main::{{closure}}::{{closure}}
   4: std::panicking::try
   5: tokio::runtime::task::raw::poll
   6: tokio::runtime::scheduler::multi_thread::worker::Context::run_task
   7: tokio::runtime::scheduler::multi_thread::worker::Context::run
   8: tokio::runtime::context::scoped::Scoped<T>::set
   9: tokio::runtime::context::runtime::enter_runtime
  10: tokio::runtime::scheduler::multi_thread::worker::run
  11: <tokio::runtime::blocking::task::BlockingTask<T> as core::future::future::Future>::poll
  12: tokio::runtime::task::core::Core<T,S>::poll
  13: tokio::runtime::task::harness::Harness<T,S>::poll
  14: tokio::runtime::blocking::pool::Inner::run