Hyper: Client hang with hyper 0.14 (tokio, async-std)

[pandaman64]

Context: we are investigating if upgrading hyper to 0.13 fixes #2306, and it seems not.

Steps to reproduce

Prerequisites:

• You need to run a docker daemon. The default setting should be ok as the reproducer uses Unix domain sockets.
• ulimit -n 65536 (increasing open file limits)

1. clone https://github.com/pandaman64/hyper-hang-tokio
2. cargo run

Expected behavior

The program should run until the system resource is exhausted.

Actual behavior

It hangs after indeterminate iterations.

Log (last several iterations)

Oct 27 16:48:35.474 DEBUG hyper::client::pool: reuse idle connection for ("unix", 2f7661722f72756e2f646f636b65722e736f636b:0)
Oct 27 16:48:35.474 DEBUG hyper::proto::h1::io: flushed 76 bytes
Oct 27 16:48:35.475 DEBUG hyper::proto::h1::io: read 110 bytes
Oct 27 16:48:35.475 DEBUG hyper::proto::h1::io: parsed 3 headers
Oct 27 16:48:35.475 DEBUG hyper::proto::h1::conn: incoming body is empty
Oct 27 16:48:35.476 DEBUG hyper::client::pool: reuse idle connection for ("unix", 2f7661722f72756e2f646f636b65722e736f636b:0)
Oct 27 16:48:35.477 DEBUG hyper::proto::h1::io: flushed 75 bytes
Oct 27 16:48:35.477 DEBUG hyper::client::pool: pooling idle connection for ("unix", 2f7661722f72756e2f646f636b65722e736f636b:0)
Oct 27 16:48:35.478 DEBUG hyper::proto::h1::io: read 211 bytes
Oct 27 16:48:35.478 DEBUG hyper::proto::h1::io: parsed 7 headers
Oct 27 16:48:35.478 DEBUG hyper::proto::h1::conn: incoming body is chunked encoding
436
Oct 27 16:48:35.478 DEBUG hyper::client::pool: reuse idle connection for ("unix", 2f7661722f72756e2f646f636b65722e736f636b:0)
Oct 27 16:48:35.479 DEBUG hyper::proto::h1::io: flushed 76 bytes
Oct 27 16:48:35.479 DEBUG hyper::proto::h1::io: read 110 bytes
Oct 27 16:48:35.479 DEBUG hyper::proto::h1::io: parsed 3 headers
Oct 27 16:48:35.479 DEBUG hyper::proto::h1::conn: incoming body is empty
Oct 27 16:48:35.480 DEBUG hyper::client::pool: reuse idle connection for ("unix", 2f7661722f72756e2f646f636b65722e736f636b:0)
Oct 27 16:48:35.480 DEBUG hyper::client::pool: pooling idle connection for ("unix", 2f7661722f72756e2f646f636b65722e736f636b:0)
Oct 27 16:48:35.481 DEBUG hyper::proto::h1::io: flushed 75 bytes
Oct 27 16:48:35.481 DEBUG hyper::proto::h1::io: read 211 bytes
Oct 27 16:48:35.481 DEBUG hyper::proto::h1::io: parsed 7 headers
Oct 27 16:48:35.481 DEBUG hyper::proto::h1::conn: incoming body is chunked encoding
437
Oct 27 16:48:35.482 DEBUG hyper::client::pool: reuse idle connection for ("unix", 2f7661722f72756e2f646f636b65722e736f636b:0)
Oct 27 16:48:35.482 DEBUG hyper::proto::h1::io: flushed 76 bytes
Oct 27 16:48:35.482 DEBUG hyper::proto::h1::io: read 110 bytes
Oct 27 16:48:35.482 DEBUG hyper::proto::h1::io: parsed 3 headers
Oct 27 16:48:35.483 DEBUG hyper::proto::h1::conn: incoming body is empty
Oct 27 16:48:35.483 DEBUG hyper::client::pool: reuse idle connection for ("unix", 2f7661722f72756e2f646f636b65722e736f636b:0)
Oct 27 16:48:35.484 DEBUG hyper::proto::h1::io: flushed 75 bytes
Oct 27 16:48:35.484 DEBUG hyper::client::pool: pooling idle connection for ("unix", 2f7661722f72756e2f646f636b65722e736f636b:0)
Oct 27 16:48:35.484 DEBUG hyper::proto::h1::io: read 211 bytes
Oct 27 16:48:35.484 DEBUG hyper::proto::h1::io: parsed 7 headers
Oct 27 16:48:35.484 DEBUG hyper::proto::h1::conn: incoming body is chunked encoding
Oct 27 16:48:35.484 DEBUG hyper::client::pool: pooling idle connection for ("unix", 2f7661722f72756e2f646f636b65722e736f636b:0)
438
Oct 27 16:48:35.485 DEBUG hyper::client::pool: reuse idle connection for ("unix", 2f7661722f72756e2f646f636b65722e736f636b:0)

Reproducer

I'm pasting the reproducer here for ease of reference.

use futures::prelude::*;
fn main() {
    // env_logger::Builder::from_default_env()
    //     .target(env_logger::fmt::Target::Stdout)
    //     .init();
    tracing_subscriber::fmt::init();

    let mut runtime = tokio::runtime::Builder::new()
        .threaded_scheduler()
        .enable_all()
        .build()
        .unwrap();
    let client: hyper::Client<hyperlocal::UnixConnector> =
        hyper::Client::builder().build(hyperlocal::UnixConnector);
    for i in 0.. {
        println!("{}", i);
        let res = runtime
            .block_on(async {
                let _resp = client
                    .get(hyperlocal::Uri::new("/var/run/docker.sock", "//events?").into())
                    .await;
                client
                    .get(hyperlocal::Uri::new("/var/run/docker.sock", "/events?").into())
                    .await
            })
            .unwrap();
        runtime.spawn(res.into_body().into_future());
    }
}

Notes

1. Double slashes in the uri ("//events?") does matter. We need two requests with different uris.
2. I suspect this is a hyper issue because we can reproduce the same hang both with tokio and async-std:
   
   
   
   • tokio reproducer: https://github.com/pandaman64/hyper-hang-tokio
   
   
   • async-std reproducer: https://github.com/pandaman64/hyper-hang-async-std
   
   

[seanmonstar]

Thanks for trying this out with the newer version. I wonder about using block_on so much, since the detection of an unusable connection happens in a spawned task that might not be getting run as much.

Have you seen the same issue if you change this to async/await?

#[tokio::main]
async fn main() {
    // env_logger::Builder::from_default_env()
    //     .target(env_logger::fmt::Target::Stdout)
    //     .init();
    tracing_subscriber::fmt::init();
    let client: hyper::Client<hyperlocal::UnixConnector> =
        hyper::Client::builder().build(hyperlocal::UnixConnector);
    for i in 0.. {
        println!("{}", i);
                let _resp = client
                    .get(hyperlocal::Uri::new("/var/run/docker.sock", "//events?").into())
                    .await;
                client
                    .get(hyperlocal::Uri::new("/var/run/docker.sock", "/events?").into())
                    .await;
    }
}

[pandaman64]

Thank you for the response!

I tried the following version without block_on, still it hangs:

#[tokio::main]
async fn main() {
    // env_logger::Builder::from_default_env()
    //     .target(env_logger::fmt::Target::Stdout)
    //     .init();
    tracing_subscriber::fmt::init();

    let client: hyper::Client<hyperlocal::UnixConnector> =
        hyper::Client::builder().build(hyperlocal::UnixConnector);
    for i in 0.. {
        println!("{}", i);
        let _resp = client
            .get(hyperlocal::Uri::new("/var/run/docker.sock", "//events?").into())
            .await;
        let res = client
            .get(hyperlocal::Uri::new("/var/run/docker.sock", "/events?").into())
            .await
            .unwrap();

        tokio::spawn(res.into_body().into_future());
    }
}

The last tokio::spawn seems necessary for reproduction.

[pandaman64]

The spawned future (res.into_body().into_future()) will receive bytes on docker operations (e.g. docker run --rm hello-world).
And I find that the program resumes looping after running docker commands (and eventually hangs again).

Probably too many spawned tasks block .get() futures from resolving?

[sfackler]

I ran your latest example in a Ubuntu WSL2 install and it ran just fine until I eventually killed it at iteration ~15,000. Are you sure the problem is with hyper and not your Docker driver not responding for some reason?

[pandaman64]

Hmm. My WSL2 Box (Ubuntu 20.04.1 LTS (Focal Fossa)) does reproduce the hang.
In my environment, async-std version tends to hang earlier. Did you try that?

[sfackler]

I do see the hang with the async-std version after a couple hundred iterations, yeah.

[pandaman64]

My coworker reported that the following version randomly stops working when invoking repeatedly:

use futures::prelude::*;
#[tokio::main]
async fn main() {
    let args: Vec<String> = std::env::args().collect();
    env_logger::init();
    let client: hyper::Client<hyperlocal::UnixConnector> =
        hyper::Client::builder().build(hyperlocal::UnixConnector);
    let _resp = client
        .get(hyperlocal::Uri::new("/var/run/docker.sock", "//events").into()) // this uri can be "//"
        .await;
    let resp = client
        .get(hyperlocal::Uri::new("/var/run/docker.sock", "/events").into())
        .await
        .unwrap();
    tokio::spawn(resp.into_body().into_future());
    let _resp = client
        .get(hyperlocal::Uri::new("/var/run/docker.sock", "//events").into()) // this uri can be "//", too
        .await;
    println!("ok: {}", args[1]);
}

I couldn't reproduce it with RUST_LOG=debug, though RUST_LOG=trace or RUST_LOG= do reproduce.

trace log of the last invocation

[2020-10-28T03:39:24Z TRACE want] signal: Want
[2020-10-28T03:39:24Z TRACE tokio::util::trace] -> task
[2020-10-28T03:39:24Z TRACE tokio::util::trace] -> task
[2020-10-28T03:39:24Z TRACE hyper::proto::h1::conn] flushed({role=client}): State { reading: Init, writing: Init, keep_alive: Idle } 
[2020-10-28T03:39:24Z TRACE want] poll_want: taker wants!
[2020-10-28T03:39:24Z TRACE hyper::client::pool] pool closed, canceling idle interval 
[2020-10-28T03:39:24Z TRACE tokio::util::trace] <- task
[2020-10-28T03:39:24Z TRACE hyper::client::pool] pool dropped, dropping pooled (("unix", 2f7661722f72756e2f646f636b65722e736f636b:0)) 
[2020-10-28T03:39:24Z TRACE tokio::util::trace] -- task
[2020-10-28T03:39:24Z TRACE tokio::util::trace] <- task
[2020-10-28T03:39:24Z TRACE tokio::util::trace] -- task
[2020-10-28T03:39:24Z TRACE hyper::proto::h1::dispatch] client tx closed 
[2020-10-28T03:39:24Z TRACE hyper::proto::h1::conn] State::close_read() 
[2020-10-28T03:39:24Z TRACE hyper::proto::h1::conn] State::close_write() 
[2020-10-28T03:39:24Z TRACE hyper::proto::h1::conn] flushed({role=client}): State { reading: Closed, writing: Closed, keep_alive: Disabled } 
[2020-10-28T03:39:24Z TRACE hyper::proto::h1::conn] shut down IO complete 
[2020-10-28T03:39:24Z TRACE mio::poll] deregistering handle with poller
[2020-10-28T03:39:24Z TRACE want] signal: Closed
[2020-10-28T03:39:24Z TRACE tokio::util::trace] <- task
[2020-10-28T03:39:24Z TRACE tokio::util::trace] -- task
[2020-10-28T03:39:24Z TRACE tokio::util::trace] -- task
[2020-10-28T03:39:24Z TRACE tokio::util::trace] -- task
[2020-10-28T03:39:24Z TRACE mio::poll] deregistering handle with poller
[2020-10-28T03:39:24Z TRACE want] signal: Closed
[2020-10-28T03:39:24Z TRACE want] signal found waiting giver, notifying
[2020-10-28T03:39:24Z TRACE tokio::util::trace] -- task
[2020-10-28T03:39:24Z TRACE hyper::client::pool] checkout waiting for idle connection: ("unix", 2f7661722f72756e2f646f636b65722e736f636b:0) 
[2020-10-28T03:39:24Z TRACE mio::poll] registering with poller
[2020-10-28T03:39:24Z TRACE hyper::client::conn] client handshake HTTP/1 
[2020-10-28T03:39:24Z TRACE hyper::client] handshake complete, spawning background dispatcher task 
[2020-10-28T03:39:24Z TRACE tokio::util::trace] task; kind=task future=futures_util::future::future::Map<futures_util::future::try_future::MapErr<hyper::client::conn::Connection<hyperlocal::client::UnixStream, hyper::body::body::Body>, hyper::client::Client<hyperlocal::client::UnixConnector>::connect_to::{{closure}}::{{closure}}::{{closure}}::{{closure}}>, hyper::client::Client<hyperlocal::client::UnixConnector>::connect_to::{{closure}}::{{closure}}::{{closure}}::{{closure}}>
[2020-10-28T03:39:24Z TRACE tokio::util::trace] -> task
[2020-10-28T03:39:24Z TRACE want] signal: Want
[2020-10-28T03:39:24Z TRACE want] signal found waiting giver, notifying
[2020-10-28T03:39:24Z TRACE hyper::proto::h1::conn] flushed({role=client}): State { reading: Init, writing: Init, keep_alive: Busy } 
[2020-10-28T03:39:24Z TRACE want] poll_want: taker wants!
[2020-10-28T03:39:24Z TRACE tokio::util::trace] <- task
[2020-10-28T03:39:24Z TRACE hyper::client::pool] checkout dropped for ("unix", 2f7661722f72756e2f646f636b65722e736f636b:0) 
[2020-10-28T03:39:24Z TRACE tokio::util::trace] -> task
[2020-10-28T03:39:24Z TRACE hyper::proto::h1::role] encode_headers
[2020-10-28T03:39:24Z TRACE hyper::proto::h1::role] -> encode_headers
[2020-10-28T03:39:24Z TRACE hyper::proto::h1::role] Client::encode method=GET, body=None 
[2020-10-28T03:39:24Z TRACE hyper::proto::h1::role] <- encode_headers
[2020-10-28T03:39:24Z TRACE hyper::proto::h1::role] -- encode_headers
[2020-10-28T03:39:24Z TRACE hyper::proto::h1::io] detected no usage of vectored write, flattening 
[2020-10-28T03:39:24Z DEBUG hyper::proto::h1::io] flushed 69 bytes 
[2020-10-28T03:39:24Z TRACE hyper::proto::h1::conn] flushed({role=client}): State { reading: Init, writing: KeepAlive, keep_alive: Busy } 
[2020-10-28T03:39:24Z TRACE tokio::util::trace] <- task
[2020-10-28T03:39:24Z TRACE tokio::util::trace] -> task
[2020-10-28T03:39:24Z TRACE hyper::proto::h1::conn] Conn::read_head 
[2020-10-28T03:39:24Z DEBUG hyper::proto::h1::io] read 103 bytes 
[2020-10-28T03:39:24Z TRACE hyper::proto::h1::role] parse_headers
[2020-10-28T03:39:24Z TRACE hyper::proto::h1::role] -> parse_headers
[2020-10-28T03:39:24Z TRACE hyper::proto::h1::role] Response.parse([Header; 100], [u8; 103]) 
[2020-10-28T03:39:24Z TRACE hyper::proto::h1::role] Response.parse Complete(103) 
[2020-10-28T03:39:24Z TRACE hyper::proto::h1::role] <- parse_headers
[2020-10-28T03:39:24Z TRACE hyper::proto::h1::role] -- parse_headers
[2020-10-28T03:39:24Z DEBUG hyper::proto::h1::io] parsed 3 headers 
[2020-10-28T03:39:24Z DEBUG hyper::proto::h1::conn] incoming body is empty 
[2020-10-28T03:39:24Z TRACE hyper::proto::h1::conn] maybe_notify; read_from_io blocked 
[2020-10-28T03:39:24Z TRACE tokio::util::trace] task; kind=task future=futures_util::future::future::Map<futures_util::future::poll_fn::PollFn<hyper::client::Client<hyperlocal::client::UnixConnector>::send_request::{{closure}}::{{closure}}::{{closure}}>, hyper::client::Client<hyperlocal::client::UnixConnector>::send_request::{{closure}}::{{closure}}::{{closure}}>
[2020-10-28T03:39:24Z TRACE tokio::util::trace] -> task
[2020-10-28T03:39:24Z TRACE want] signal: Want
[2020-10-28T03:39:24Z TRACE hyper::client::pool] checkout waiting for idle connection: ("unix", 2f7661722f72756e2f646f636b65722e736f636b:0) 
[2020-10-28T03:39:24Z TRACE want] signal found waiting giver, notifying
[2020-10-28T03:39:24Z TRACE tokio::util::trace] <- task
[2020-10-28T03:39:24Z TRACE tokio::util::trace] -> task
[2020-10-28T03:39:24Z TRACE hyper::proto::h1::conn] flushed({role=client}): State { reading: Init, writing: Init, keep_alive: Idle } 
[2020-10-28T03:39:24Z TRACE want] poll_want: taker wants!
[2020-10-28T03:39:24Z TRACE hyper::client::pool] put; add idle connection for ("unix", 2f7661722f72756e2f646f636b65722e736f636b:0) 
[2020-10-28T03:39:24Z TRACE mio::poll] registering with poller
[2020-10-28T03:39:24Z TRACE hyper::client::pool] put; found waiter for ("unix", 2f7661722f72756e2f646f636b65722e736f636b:0) 
[2020-10-28T03:39:24Z DEBUG hyper::client::pool] reuse idle connection for ("unix", 2f7661722f72756e2f646f636b65722e736f636b:0) 
[2020-10-28T03:39:24Z TRACE tokio::util::trace] <- task
[2020-10-28T03:39:24Z TRACE tokio::util::trace] -- task
[2020-10-28T03:39:24Z TRACE tokio::util::trace] task; kind=task future=futures_util::future::future::Map<futures_util::future::try_future::MapErr<hyper::common::lazy::Lazy<hyper::client::Client<hyperlocal::client::UnixConnector>::connect_to::{{closure}}, futures_util::future::either::Either<futures_util::future::try_future::AndThen<futures_util::future::try_future::MapErr<hyper::service::oneshot::Oneshot<hyperlocal::client::UnixConnector, http::uri::Uri>, hyper::error::Error::new_connect<std::io::error::Error>>, futures_util::future::either::Either<core::pin::Pin<alloc::boxed::Box<futures_util::future::try_future::MapOk<futures_util::future::try_future::AndThen<core::future::from_generator::GenFuture<hyper::client::conn::Builder::handshake<hyperlocal::client::UnixStream, hyper::body::body::Body>::{{closure}}>, futures_util::future::poll_fn::PollFn<hyper::client::conn::SendRequest<hyper::body::body::Body>::when_ready::{{closure}}>, hyper::client::Client<hyperlocal::client::UnixConnector>::connect_to::{{closure}}::{{closure}}::{{closure}}>, hyper::client::Client<hyperlocal::client::UnixConnector>::connect_to::{{closure}}::{{closure}}::{{closure}}>>>, futures_util::future::ready::Ready<core::result::Result<hyper::client::pool::Pooled<hyper::client::PoolClient<hyper::body::body::Body>>, hyper::error::Error>>>, hyper::client::Client<hyperlocal::client::UnixConnector>::connect_to::{{closure}}::{{closure}}>, futures_util::future::ready::Ready<core::result::Result<hyper::client::pool::Pooled<hyper::client::PoolClient<hyper::body::body::Body>>, hyper::error::Error>>>>, hyper::client::Client<hyperlocal::client::UnixConnector>::connection_for::{{closure}}::{{closure}}>, hyper::client::Client<hyperlocal::client::UnixConnector>::connection_for::{{closure}}::{{closure}}>
[2020-10-28T03:39:24Z TRACE tokio::util::trace] -> task
[2020-10-28T03:39:24Z TRACE want] signal: Want
[2020-10-28T03:39:24Z TRACE hyper::client::conn] client handshake HTTP/1 
[2020-10-28T03:39:24Z TRACE hyper::proto::h1::conn] flushed({role=client}): State { reading: Init, writing: Init, keep_alive: Idle } 
[2020-10-28T03:39:24Z TRACE tokio::util::trace] <- task
[2020-10-28T03:39:24Z TRACE hyper::client] handshake complete, spawning background dispatcher task 
[2020-10-28T03:39:24Z TRACE tokio::util::trace] -> task
[2020-10-28T03:39:24Z TRACE tokio::util::trace] task; kind=task future=futures_util::future::future::Map<futures_util::future::try_future::MapErr<hyper::client::conn::Connection<hyperlocal::client::UnixStream, hyper::body::body::Body>, hyper::client::Client<hyperlocal::client::UnixConnector>::connect_to::{{closure}}::{{closure}}::{{closure}}::{{closure}}>, hyper::client::Client<hyperlocal::client::UnixConnector>::connect_to::{{closure}}::{{closure}}::{{closure}}::{{closure}}>
[2020-10-28T03:39:24Z TRACE tokio::util::trace] <- task
[2020-10-28T03:39:24Z TRACE tokio::util::trace] -> task
[2020-10-28T03:39:24Z TRACE want] signal: Want
[2020-10-28T03:39:24Z TRACE want] signal found waiting giver, notifying
[2020-10-28T03:39:24Z TRACE hyper::proto::h1::role] encode_headers
[2020-10-28T03:39:24Z TRACE hyper::proto::h1::conn] flushed({role=client}): State { reading: Init, writing: Init, keep_alive: Busy } 
[2020-10-28T03:39:24Z TRACE tokio::util::trace] <- task
[2020-10-28T03:39:24Z TRACE hyper::proto::h1::role] -> encode_headers
[2020-10-28T03:39:24Z TRACE tokio::util::trace] -> task
[2020-10-28T03:39:24Z TRACE want] poll_want: taker wants!
[2020-10-28T03:39:24Z TRACE hyper::proto::h1::role] Client::encode method=GET, body=None 
[2020-10-28T03:39:24Z TRACE hyper::proto::h1::role] <- encode_headers
[2020-10-28T03:39:24Z TRACE hyper::client::pool] put; add idle connection for ("unix", 2f7661722f72756e2f646f636b65722e736f636b:0) 
[2020-10-28T03:39:24Z TRACE hyper::proto::h1::role] -- encode_headers
[2020-10-28T03:39:24Z DEBUG hyper::client::pool] pooling idle connection for ("unix", 2f7661722f72756e2f646f636b65722e736f636b:0) 
[2020-10-28T03:39:24Z DEBUG hyper::proto::h1::io] flushed 74 bytes 
[2020-10-28T03:39:24Z TRACE hyper::proto::h1::conn] flushed({role=client}): State { reading: Init, writing: KeepAlive, keep_alive: Busy } 
[2020-10-28T03:39:24Z TRACE tokio::util::trace] task; kind=task future=hyper::client::pool::IdleTask<hyper::client::PoolClient<hyper::body::body::Body>>
[2020-10-28T03:39:24Z TRACE tokio::util::trace] <- task
[2020-10-28T03:39:24Z TRACE tokio::util::trace] <- task
[2020-10-28T03:39:24Z TRACE tokio::util::trace] -- task
[2020-10-28T03:39:24Z TRACE tokio::util::trace] -> task
[2020-10-28T03:39:24Z TRACE tokio::util::trace] <- task
[2020-10-28T03:39:24Z TRACE tokio::util::trace] -> task
[2020-10-28T03:39:24Z TRACE hyper::proto::h1::conn] Conn::read_head 
[2020-10-28T03:39:24Z TRACE tokio::util::trace] -> task
[2020-10-28T03:39:24Z TRACE hyper::client::pool] idle interval checking for expired 
[2020-10-28T03:39:24Z TRACE tokio::util::trace] <- task
[2020-10-28T03:39:24Z DEBUG hyper::proto::h1::io] read 211 bytes 
[2020-10-28T03:39:24Z TRACE hyper::proto::h1::role] parse_headers
[2020-10-28T03:39:24Z TRACE hyper::proto::h1::role] -> parse_headers
[2020-10-28T03:39:24Z TRACE hyper::proto::h1::role] Response.parse([Header; 100], [u8; 211]) 
[2020-10-28T03:39:24Z TRACE hyper::proto::h1::role] Response.parse Complete(211) 
[2020-10-28T03:39:24Z TRACE hyper::proto::h1::role] <- parse_headers
[2020-10-28T03:39:24Z TRACE hyper::proto::h1::role] -- parse_headers
[2020-10-28T03:39:24Z DEBUG hyper::proto::h1::io] parsed 7 headers 
[2020-10-28T03:39:24Z DEBUG hyper::proto::h1::conn] incoming body is chunked encoding 
[2020-10-28T03:39:24Z TRACE hyper::proto::h1::decode] decode; state=Chunked(Size, 0) 
[2020-10-28T03:39:24Z TRACE hyper::proto::h1::decode] Read chunk hex size 
[2020-10-28T03:39:24Z TRACE hyper::client::pool] put; add idle connection for ("unix", 2f7661722f72756e2f646f636b65722e736f636b:0) 
[2020-10-28T03:39:24Z DEBUG hyper::client::pool] pooling idle connection for ("unix", 2f7661722f72756e2f646f636b65722e736f636b:0) 
[2020-10-28T03:39:24Z TRACE tokio::util::trace] task; kind=task future=futures_util::stream::stream::into_future::StreamFuture<hyper::body::body::Body>
[2020-10-28T03:39:24Z TRACE tokio::util::trace] -> task
[2020-10-28T03:39:24Z TRACE tokio::util::trace] <- task
[2020-10-28T03:39:24Z TRACE hyper::client::pool] take? ("unix", 2f7661722f72756e2f646f636b65722e736f636b:0): expiration = Some(90s) 
[2020-10-28T03:39:24Z TRACE hyper::proto::h1::conn] flushed({role=client}): State { reading: Body(Chunked(Size, 0)), writing: KeepAlive, keep_alive: Busy } 
[2020-10-28T03:39:24Z DEBUG hyper::client::pool] reuse idle connection for ("unix", 2f7661722f72756e2f646f636b65722e736f636b:0) 
[2020-10-28T03:39:24Z TRACE tokio::util::trace] <- task

[pandaman64]

Another coworker reported that adding

    .pool_idle_timeout(std::time::Duration::from_millis(0))
    .pool_max_idle_per_host(0)

to the client builder is a work around.

[pandaman64]

Update:

• This hang does reproduce with hyper 0.14
  
  
  
  • reproduction with hyper 0.14 + Tokio 1.2 (https://github.com/pandaman64/hyper-hang-tokio)
  
  
  • reproduction with hyper 0.14 + async-std 1.6 (https://github.com/pandaman64/hyper-hang-async-std)
  
  
  • It seems that you need to wait longer with this version
  
  
• To work around this hang, .pool_max_idle_per_host(0) is enough
  
  
  
  • I suspect there is something wrong with the pool implementation, but I couldn't find it.