hyper + hyper-tls server intermittently stops accepting connections

[JuxhinDB]

Hey, this seems like the correct repository to write this issue on. If not please let me know so that I can move it for you.

---

Overview

Versions

hyper - "0.13.8"
rustls = "0.18.1"
tokio-rustls = "0.14"
tokio = "0.2.22"

We use hyper-rs server and client to serve as the foundation for a special traffic replay proxy (i.e. not passthru). A client sends an HTTP/S request to our proxy, which goes to our server. Internally we have a client that mutates the request and sends out an HTTP/S request to an origin server, waits for the response and finally the server returns the response (mutated) back to the original client.

Issue

On average, between 8 to 48 hours of letting the proxy run, we consistently hit an issue where the hyper-rs server seemingly refuses to accept any connections. A couple of points on this:

1. I cannot seem to reproduce this issue in any way. I tried heavy load tests, long soak tests over 8 hours, intermittent slow tests to see if it's an issue due to trying to reuse stale connections;
2. There are no errors at any point in time related to this. When running sudo RUST_LOG="debug" ./proxy, I was hoping to gain some insight, but all we seem to see are debug messages related to buffer reads;
3. tcpdump shows connection attempts coming through, just no response from the server.

Miscellaneous Troubleshooting

Some of these points may not be entirely relevant, but I am adding them incase they may help spring up some ideas.

Hyper Server + TLS Setup

Note that the proxy needs to be TLS-aware in this scenario.

let addr = SocketAddr::from((config.server.address, config.server.port));

let mut tls_config = rustls::ServerConfig::new(rustls::NoClientAuth::new());
tls_config.set_single_cert(...).expect("invalid key or certificate");

let tls_acceptor = TlsAcceptor::from(Arc::new(tls_config));
let arc_acceptor = Arc::new(tls_acceptor);

let mut listener = TcpListener::bind(&addr).await.expect(&format!("unable to bind to addr: {:?}", &addr));
let incoming = listener.incoming();

let incoming = hyper::server::accept::from_stream(incoming.filter_map(|socket| async {
    match socket {
        Ok(stream) => match arc_acceptor.clone().accept(stream).await {
            Ok(val) => Some(Ok::<_, hyper::Error>(val)),
            Err(e) => {
                error!("tcp socket inner err: {}", e);
                None                    
            }
        },
        Err(e) => {
            error!("tcp socket outer err: {}", e);
            None
        }
    }
}));

let http_tls_service = make_service_fn(move |_| {
    // arc clone some configuration
    async move {
        Ok::<_, Infallible>(service_fn(move |_req| {
            // arc clone some configuration
            on_request_handler(_req, config, services)
        }))
    }
});

let server = Server::builder(incoming).serve(http_tls_service);

// Run
if let Err(e) = server.await {
    error!("server error: {}", e);
}  

Connections stuck in CLOSE_WAIT

The only indicator of something possibly going run occurs when the proxy hangs, and we take a look at active tcp connections (netstat -anp). We notice that there are an abnormal number of connections stuck in CLOSE_WAIT.

tcp      367      0 182.211.74.112:443     35.173.69.86:49930      CLOSE_WAIT  off (0.00/0/0)
tcp      291      0 182.211.74.112:443     138.246.253.24:45312    CLOSE_WAIT  off (0.00/0/0)
tcp      367      0 182.211.74.112:443     35.173.69.86:58335      CLOSE_WAIT  off (0.00/0/0)
tcp      367      0 182.211.74.112:443     52.42.49.200:58022      CLOSE_WAIT  off (0.00/0/0)
tcp      367      0 182.211.74.112:443     35.173.69.86:9528       CLOSE_WAIT  off (0.00/0/0)

In total however we only see around 120 connections stuck in this state which still shouldn't hang the server. One thing to note here, is that the connection seems to be hanging on our server-side and there appears to always be a remaining 367 bytes in the Recv-Q that are never read, and remain stuck there.

After seeing this occur a couple of times, I am noticing that the CLOSE_WAIT connections are primarily caused by the same set of remote clients, which leads me to think that they are abruptly closing connections causing potential issues. If there are any recommendations on how to systematically try to reduce this, I'm open to ideas.

It may also be important to note that on this same server, a previous version of the proxy did not experience similar issues. There is also a nameserver module in Go that accompanies the proxy that runs indefinitely even after the proxy hangs. Any pointers would be really great.

[JuxhinDB]

Currently running a debug build with tracing enabled in the production environment to see if we develop any interesting behavior there. Will report back as soon as the issue hits with any subsequent details.

[JuxhinDB]

Been three days and the issue has not resurfaced when running with a debug build. Only appears to be an issue with the release profile. Will close for the time being and re-open when I have further details.

[jedisct1]

Same issue here, in a very similar configuration. Solved by adding nginx as a frontend to hyper.

[JuxhinDB]

@jedisct1 -- I suspect the issue is related to improper handling of real/distinct connections either by the library or by myself. I intend to dive a little deeper into it and see if I can add some insight. A reverse proxy works, but in my usecase I really would like to ship a single binary.

[JuxhinDB]

Still happening unfortunately, trying to gather as much info as I can. Here are some potential insights when trying out another diagnostic tool, uroboros.

1. There is no case of resource exhaustion, cpu/mem/io/fds all are extremely low.
2. Process remains in 'S' state (interruptible sleep) and flags look normal.

When comparing to another process running, the only things that stands our like a sore thumb are:

• Virtual Mem (however I'm not sure how accurate this is, doesn't match htop).
• Minor and Major faults stats being reported, which are off the roof.

@seanmonstar would you have some guidance on how to peak into the runtime tasks to monitor their status? With full trace enabled, I still think I'm running around blind.

[jedisct1]

Since it doesn't happen when running behind a reverse proxy, it is likely to be a specific sequence sent by a client that causes hyper to freeze.

[JuxhinDB]

I had a similar thought but it seems infinitely weird that a single client connection (excluding volumetric traffic) which hang the entire runtime. The issue just occurred again now infact, this time only running for 3h 30m. I may need to try this with another runtime instead of tokio.

Connection related traces I receive at the end of a request. These are consistent as we have a monitoring service that pings every minute (the issue started before setting up the monitoring service).

{"timestamp": "2021-01-06 12:08:48", "msg": "TRACE - hyper::proto::h1::conn (thread: 140702874970912/tokio-runtime-worker) - force_io_read; io error = Os { code: 104, kind: ConnectionReset, message: "Connection reset by peer" } "}
{"timestamp": "2021-01-06 12:08:48", "msg": "TRACE - hyper::proto::h1::conn (thread: 140702874970912/tokio-runtime-worker) - State::close() "}
{"timestamp": "2021-01-06 12:08:48", "msg": "DEBUG - hyper::server::conn::spawn_all (thread: 140702874970912/tokio-runtime-worker) - connection error: connection error: Connection reset by peer (os error 104) "}
{"timestamp": "2021-01-06 12:08:48", "msg": "TRACE - mio::poll (thread: 140702874970912/tokio-runtime-worker) - deregistering handle with poller"}
{"timestamp": "2021-01-06 12:09:29", "msg": "TRACE - mio::poll (thread: 140702874985504/main) - registering with poller"}

I'll monitor TCP traffic on server and try to correlate the client sequence to when the service drops.

[JuxhinDB]

Closing this issue as I do not have much more to add to this. I heeded @jedisct1 advice and refactored the proxy internals to (1) remove TLS-aware components from the internal proxy, (2) refactor the request/response lifecycle to implement the service struct and (3) place the proxy behind HAProxy as a level-4 transparent reverse proxy. So far it's been ~16 hours with no issues--will see how it goes.