Connection Error from Hyper

[gatoWololo]

There are two hyper errors I am seeing from the server:

First Error

  2023-01-19T22:23:07.785767Z ERROR lock_keeper_key_server::server::service: connection error: not connected
    at lock-keeper-key-server/src/server/service.rs:96

The easiest way to reproduce this error is to use try registering an account that already exists. While the server is running, execute reg EXISTING_ACCOUNT PASSWORD from the client CLI. I use failing operations to reproduce this error as successful client CLI operations will produce multiple gRPC calls (additional gRPC calls for authenticating and getUserID).
Here is a more complete log:

  2023-01-19T23:00:21.817365Z ERROR lock_keeper_key_server::operations::register: error: AccountAlreadyRegistered
    at lock-keeper-key-server/src/operations/register.rs:32
    in lock_keeper_key_server::operations::register::operation
    in lock_keeper_key_server::server::operation::handle_unauthenticated_request with metadata: "RequestMetadata { account_name: AccountName(\"omar\"), action: Register, session_id: None, request_id: 780dcaf8-691a-4ec8-95f7-ba2c9d4d9c50 }", request_id: "780dcaf8-691a-4ec8-95f7-ba2c9d4d9c50"

  2023-01-19T23:00:21.817608Z  INFO lock_keeper_key_server::server::operation: This operation completed with an error!
    at lock-keeper-key-server/src/server/operation.rs:112
    in lock_keeper_key_server::server::operation::handle_unauthenticated_request with metadata: "RequestMetadata { account_name: AccountName(\"omar\"), action: Register, session_id: None, request_id: 780dcaf8-691a-4ec8-95f7-ba2c9d4d9c50 }", request_id: "780dcaf8-691a-4ec8-95f7-ba2c9d4d9c50"

  2023-01-19T23:00:21.824426Z ERROR lock_keeper_key_server::server::service: connection error: not connected
    at lock-keeper-key-server/src/server/service.rs:96

Specifically, this is the service task that is failing and returning the error:

            // Spawn a task to handle each connection
            let _ = tokio::spawn(async move {
                if let Err(e) = handle_connection(http, conn, tls_acceptor, svc).await {
                    // Log the error but don't bother returning it since it has nowhere to go.
                    error!("{}", e);
                }
            });

It is not obvious from this trace, but the connection error does not depend on our task spawned in handle_unauthenticated_request returning. Which makes sense since these are two separated, uncoupled tasks. Additionally adding a std::thread:sleep or tokio::sleep to our handle_unauthenticated_request task does not make a difference. This further affirms that the two tasks are unrelated.

I stepped though the code in a debugger to understand where this code was coming from. I believe the error is triggered by the client dropping its end of the channels this is a relevant backtrace from gdb:

tokio_rustls::common::{impl#3}::poll_shutdown<tokio::net::tcp::stream::TcpStream, rustls::server::server_conn::ServerConnection, rustls::server::server_conn::ServerConnectionData> mod.rs:334
tokio_rustls::server::{impl#3}::poll_shutdown<tokio::net::tcp::stream::TcpStream> server.rs:127
hyper::common::io::rewind::{impl#2}::poll_shutdown<tokio_rustls::server::TlsStream<tokio::net::tcp::stream::TcpStream>> rewind.rs:100
h2::codec::framed_write::FramedWrite<hyper::common::io::rewind::Rewind<tokio_rustls::server::TlsStream<tokio::net::tcp::stream::TcpStream>>, h2::proto::streams::prioritize::Prioritized<hyper::proto::h2::SendBuf<bytes::bytes::Bytes>>>::shutdown<hyper::common::io::rewind::Rewind<tokio_rustls::server::TlsStream<tokio::net::tcp::stream::TcpStream>>, h2::proto::streams::prioritize::Prioritized<hyper::proto::h2::SendBuf<bytes::bytes::Bytes>>> framed_write.rs:164
h2::codec::Codec<hyper::common::io::rewind::Rewind<tokio_rustls::server::TlsStream<tokio::net::tcp::stream::TcpStream>>, h2::proto::streams::prioritize::Prioritized<hyper::proto::h2::SendBuf<bytes::bytes::Bytes>>>::shutdown<hyper::common::io::rewind::Rewind<tokio_rustls::server::TlsStream<tokio::net::tcp::stream::TcpStream>>, h2::proto::streams::prioritize::Prioritized<hyper::proto::h2::SendBuf<bytes::bytes::Bytes>>> mod.rs:151
h2::proto::connection::Connection<hyper::common::io::rewind::Rewind<tokio_rustls::server::TlsStream<tokio::net::tcp::stream::TcpStream>>, h2::server::Peer, hyper::proto::h2::SendBuf<bytes::bytes::Bytes>>::poll<hyper::common::io::rewind::Rewind<tokio_rustls::server::TlsStream<tokio::net::tcp::stream::TcpStream>>, h2::server::Peer, hyper::proto::h2::SendBuf<bytes::bytes::Bytes>> connection.rs:285
h2::server::Connection<hyper::common::io::rewind::Rewind<tokio_rustls::server::TlsStream<tokio::net::tcp::stream::TcpStream>>, hyper::proto::h2::SendBuf<bytes::bytes::Bytes>>::poll_closed<hyper::common::io::rewind::Rewind<tokio_rustls::server::TlsStream<tokio::net::tcp::stream::TcpStream>>, hyper::proto::h2::SendBuf<bytes::bytes::Bytes>> server.rs:504
h2::server::Connection<hyper::common::io::rewind::Rewind<tokio_rustls::server::TlsStream<tokio::net::tcp::stream::TcpStream>>, hyper::proto::h2::SendBuf<bytes::bytes::Bytes>>::poll_accept<hyper::common::io::rewind::Rewind<tokio_rustls::server::TlsStream<tokio::net::tcp::stream::TcpStream>>, hyper::proto::h2::SendBuf<bytes::bytes::Bytes>> server.rs:416
hyper::proto::h2::server::Serving<hyper::common::io::rewind::Rewind<tokio_rustls::server::TlsStream<tokio::net::tcp::stream::TcpStream>>, http_body::combinators::box_body::UnsyncBoxBody<bytes::bytes::Bytes, tonic::status::Status>>::poll_server<hyper::common::io::rewind::Rewind<tokio_rustls::server::TlsStream<tokio::net::tcp::stream::TcpStream>>, http_body::combinators::box_body::UnsyncBoxBody<bytes::bytes::Bytes, tonic::status::Status>, tonic::transport::service::router::Routes, hyper::common::exec::Exec> server.rs:279
hyper::proto::h2::server::{impl#2}::poll<hyper::common::io::rewind::Rewind<tokio_rustls::server::TlsStream<tokio::net::tcp::stream::TcpStream>>, tonic::transport::service::router::Routes, http_body::combinators::box_body::UnsyncBoxBody<bytes::bytes::Bytes, tonic::status::Status>, hyper::common::exec::Exec> server.rs:213
hyper::server::conn::{impl#8}::poll<tokio_rustls::server::TlsStream<tokio::net::tcp::stream::TcpStream>, http_body::combinators::box_body::UnsyncBoxBody<bytes::bytes::Bytes, tonic::status::Status>, tonic::transport::service::router::Routes, hyper::common::exec::Exec> conn.rs:954
hyper::server::conn::{impl#5}::poll<tokio_rustls::server::TlsStream<tokio::net::tcp::stream::TcpStream>, http_body::combinators::box_body::UnsyncBoxBody<bytes::bytes::Bytes, tonic::status::Status>, tonic::transport::service::router::Routes, hyper::common::exec::Exec> conn.rs:872
lock_keeper_key_server::server::service::handle_connection::{async_fn#0} service.rs:

The backtrace is a bit hard to parse, but you can see our handle_connection frame at the bottom and calls down/up the stack.
The failure happens deep inside h2/tokio_rustls when the server is trying to shutdown the TLS connection? We can see what the logging messages from h2 are before the failure. Nothing stands out to me as obviously incorrect:

  2023-01-19T23:18:33.224381Z TRACE h2::proto::streams::counts: transition_after; stream=StreamId(1); state=State { inner: Closed(Error(Reset(StreamId(1), NO_ERROR, Library))) }; is_closed=true; pending_send_empty=true; buffered_send_data=0; num_recv=0; num_send=0
    at /home/omar/.cargo/registry/src/github.com-1ecc6299db9ec823/h2-0.3.15/src/proto/streams/counts.rs:136
    in h2::proto::connection::poll
    in h2::proto::connection::Connection with peer: Server
    in h2::server::server_handshake

  2023-01-19T23:18:33.224620Z TRACE h2::proto::connection: connection.state: Closing(NO_ERROR, Library)
    at /home/omar/.cargo/registry/src/github.com-1ecc6299db9ec823/h2-0.3.15/src/proto/connection.rs:254
    in h2::proto::connection::poll
    in h2::proto::connection::Connection with peer: Server
    in h2::server::server_handshake

  2023-01-19T23:18:33.224756Z TRACE h2::proto::connection: connection closing after flush
    at /home/omar/.cargo/registry/src/github.com-1ecc6299db9ec823/h2-0.3.15/src/proto/connection.rs:283
    in h2::proto::connection::poll
    in h2::proto::connection::Connection with peer: Server
    in h2::server::server_handshake

  2023-01-19T23:18:33.224899Z TRACE h2::codec::framed_write: flushing buffer
    at /home/omar/.cargo/registry/src/github.com-1ecc6299db9ec823/h2-0.3.15/src/codec/framed_write.rs:154
    in h2::codec::framed_write::FramedWrite::flush
    in h2::proto::connection::poll
    in h2::proto::connection::Connection with peer: Server
    in h2::server::server_handshake

  2023-01-19T23:18:33.225076Z DEBUG rustls::conn: Sending warning alert CloseNotify
    at /home/omar/.cargo/registry/src/github.com-1ecc6299db9ec823/rustls-0.20.7/src/conn.rs:1329
    in h2::proto::connection::poll
    in h2::proto::connection::Connection with peer: Server
    in h2::server::server_handshake

  2023-01-19T23:18:33.225472Z TRACE h2::proto::streams::streams: Streams::recv_eof
    at /home/omar/.cargo/registry/src/github.com-1ecc6299db9ec823/h2-0.3.15/src/proto/streams/streams.rs:812

  2023-01-19T23:18:33.225599Z TRACE mio::poll: deregistering event source from poller
    at /home/omar/.cargo/registry/src/github.com-1ecc6299db9ec823/mio-0.8.5/src/poll.rs:663

  2023-01-19T23:18:33.225817Z ERROR lock_keeper_key_server::server::service: connection error: not connected
    at lock-keeper-key-server/src/server/service.rs:96

Second Error

Sometimes I also see a

  2023-01-19T22:35:33.606986Z ERROR lock_keeper_key_server::server::service: connection error: not connected
    at lock-keeper-key-server/src/server/service.rs:96

  2023-01-19T22:35:33.622515Z ERROR lock_keeper_key_server::operations::authenticate: error: LockKeeper(TonicStatus(Status { code: Unknown, message: "error reading a body from connection: stream error received: stream no longer needed", source: Some(hyper::Error(Body, Error { kind: Reset(StreamId(1), CANCEL, Remote) })) }))
    at lock-keeper-key-server/src/operations/authenticate.rs:40
    in lock_keeper_key_server::operations::authenticate::operation
    in lock_keeper_key_server::server::operation::handle_unauthenticated_request with metadata: "RequestMetadata { account_name: AccountName(\"omar\"), action: Authenticate, session_id: None, request_id: 5dd21cef-6670-40ea-bab9-e4b2590949a9 }", request_id: "5dd21cef-6670-40ea-bab9-e4b2590949a9"

  2023-01-19T22:35:33.622651Z  INFO lock_keeper_key_server::server::operation: This operation completed with an error!
    at lock-keeper-key-server/src/server/operation.rs:110
    in lock_keeper_key_server::server::operation::handle_unauthenticated_request with metadata: "RequestMetadata { account_name: AccountName(\"omar\"), action: Authenticate, session_id: None, request_id: 5dd21cef-6670-40ea-bab9-e4b2590949a9 }", request_id: "5dd21cef-6670-40ea-bab9-e4b2590949a9"

  2023-01-19T22:35:33.622791Z ERROR lock_keeper_key_server::server::operation: Problem while sending error over channel: tokio Sender error: channel closed
    at lock-keeper-key-server/src/server/operation.rs:124
    in lock_keeper_key_server::server::operation::handle_error with e: LockKeeper(TonicStatus(Status { code: Unknown, message: "error reading a body from connection: stream error received: stream no longer needed", source: Some(hyper::Error(Body, Error { kind: Reset(StreamId(1), CANCEL, Remote) })) }))
    in lock_keeper_key_server::server::operation::handle_unauthenticated_request with metadata: "RequestMetadata { account_name: AccountName(\"omar\"), action: Authenticate, session_id: None, request_id: 5dd21cef-6670-40ea-bab9-e4b2590949a9 }", request_id: "5dd21cef-6670-40ea-bab9-e4b2590949a9"

The second error is far more descriptive! It may be better to start debugging with this error.
Other thoughts:

• Originally I was surprised how our channel gRPC calls returned immediately and all the documentation happened thought channels. This is pretty standard behavior for tonic and you can find the same usage here.
• I googled second error and found this relevant-ish issue. It gives some insight to how this is related to streams.