Skip to content

Client hang with hyper 0.14 (tokio, async-std) #2312

Closed as not planned
Closed as not planned
Client hang with hyper 0.14 (tokio, async-std)#2312

Description

@pandaman64
pandaman64
opened on Oct 27, 2020

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) 
435
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:

Activity

  1. seanmonstar commented on Oct 27, 2020

    @seanmonstar
    seanmonstar
    on Oct 27, 2020
    Member

    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;
    }
}

  2. pandaman64 commented on Oct 27, 2020

    @pandaman64
    pandaman64
    on Oct 27, 2020
    Author

    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.

  3. pandaman64 commented on Oct 27, 2020

    @pandaman64
    pandaman64
    on Oct 27, 2020
    Author

    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?

  4. sfackler commented on Oct 28, 2020

    @sfackler
    sfackler
    on Oct 28, 2020
    Contributor

    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?

  5. pandaman64 commented on Oct 28, 2020

    @pandaman64
    pandaman64
    on Oct 28, 2020
    Author

    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?

  6. sfackler commented on Oct 28, 2020

    @sfackler
    sfackler
    on Oct 28, 2020
    Contributor

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

  7. pandaman64 commented on Oct 28, 2020

    @pandaman64
    pandaman64
    on Oct 28, 2020
    Author

    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

  8. pandaman64 commented on Nov 5, 2020

    @pandaman64
    pandaman64
    on Nov 5, 2020
    Author

    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.

  9. nyuichi
    added 2 commits that reference this issue on Nov 12, 2020

    workaround for hyperium/hyper#2312

    86dd94e

    workaround for hyperium/hyper#2312

    f934777
  10. lynzrand
    added a commit that references this issue on Nov 16, 2020

    fix(judger): workaround for hyper issue

    d12b517
  11. eldesh
    added a commit that references this issue on Nov 18, 2020

    workaround for hyperium/hyper#2312

    f5a309b

  12. pandaman64 commented on Feb 12, 2021

    @pandaman64
    pandaman64
    on Feb 12, 2021
    Author

    Update:

  13. pandaman64
    changed the title [-]Client hang with hyper 0.13 (tokio, async-std)[/-] [+]Client hang with hyper 0.14 (tokio, async-std)[/+] on Feb 12, 2021

  14. univerz commented on Dec 2, 2021

    @univerz
    univerz
    on Dec 2, 2021
      * I suspect there is something wrong with [the pool implementation](https://github.com/hyperium/hyper/blob/42587059e6175735b1a8656c5ddbff0edb19294c/src/client/pool.rs), but I couldn't find it.

    there is TODO: unhack inside Pool::reuse, but hard for me to say how serious it is.

    from my debugging it looks like there is no initial Connection poll (& then through ProtoClient -> Dispatcher -> Conn request is not encoded), but i have surprisingly hard time to figure out where that poll should be initiated to investigate it further.

  15. 5 remaining items

  16. arthurprs commented on Dec 13, 2022

    @arthurprs
    arthurprs
    on Dec 13, 2022
    Contributor

    We've been hit by #2312 yesterday (and I think once before) and tracked it down to this. The example program from #2312 can easily show the problem.

    We're using pool_max_idle_per_host(0) while no better solution exists 😭

  17. kpark-hrp commented on Feb 1, 2023

    @kpark-hrp
    kpark-hrp
    on Feb 1, 2023

    I just wasted my entire day because of this. This also affects reqwest obviously because it implements hyper underneath. How I encountered this bug...

        std::thread::spawn(move || {
        let a = tokio::runtime::Builder::new_multi_thread().build().unwrap();
        a.block_on(
            async {
                // reqwest call here then `.await`
            }
        );
    }).join().expect("Thread panicked")

    But, .pool_max_idle_per_host(0) did the trick of workaround

  18. olanod
    added a commit that references this issue on Feb 14, 2023

    Maybe fix room joins

    809c9b4

  19. numberjuani commented on Aug 31, 2023

    @numberjuani
    numberjuani
    on Aug 31, 2023

    is there any timeline for fixing this or have we given up?

  20. GunnarMorrigan commented on Sep 20, 2023

    @GunnarMorrigan
    GunnarMorrigan
    on Sep 20, 2023

    I have a two step container build process to reduce container size. In the initial build container everything works fine. However, In my second container it breaks with the same behaviour as described here.

    Could this be the same issue or is it a docker driver issue that @sfackler described above?
    It does the same under docker and podman..

    2023-09-20T18:00:00.716743Z TRACE hyper::client::pool: 638: checkout waiting for idle connection: ("https", _URL_HERE_)
2023-09-20T18:00:00.716810Z DEBUG reqwest::connect: 429: starting new connection: https://_URL_HERE_/    
2023-09-20T18:00:00.716878Z TRACE hyper::client::connect::http: 278: Http::connect; scheme=Some("https"), host=Some("_URL_HERE_"), port=None
2023-09-20T18:00:00.717060Z DEBUG hyper::client::connect::dns: 122: resolving host="_URL_HERE_"
2023-09-20T18:00:00.905903Z DEBUG hyper::client::connect::http: 537: connecting to IP:443
2023-09-20T18:00:00.909242Z DEBUG hyper::client::connect::http: 540: connected to IP:443
2023-09-20T18:00:00.993186Z TRACE hyper::client::pool: 680: checkout dropped for ("https", _URL_HERE_)
2023-09-20T18:00:00.993237Z DEBUG azure_core::policies::retry_policies::retry_policy: 114: io error occurred when making request which will be retried: failed to execute `reqwest` request
  21. demoray
    added a commit that references this issue on Jan 5, 2024

    work around hang issue in hyper (#1550)

    38597f0
  22. x86pup
    added a commit that references this issue on Mar 19, 2024

    fix(client): Fix deadlock; candidate solution to hyperium#2312.

    b88b821
  23. andybalaam
    added a commit that references this issue on Mar 22, 2024

    client: Set pool_max_idle_per_host to 0 on hyper::Client

    d7466e3

  24. rami3l commented on Jun 6, 2024

    @rami3l
    rami3l
    on Jun 6, 2024

    @jevolk Just being curious, I saw you pushed a commit in a fork (https://github.com/jevolk/hyper/commit/56a64cf0bae4118d5b276fbb0eeb68dc286db38b) that seemingly to have "[fixed] the deadlock". Would you mind shedding a light on this issue?

  25. jevolk commented on Jun 17, 2024

    @jevolk
    jevolk
    on Jun 17, 2024

    @jevolk Just being curious, I saw you pushed a commit in a fork (jevolk@56a64cf) that seemingly to have "[fixed] the deadlock". Would you mind shedding a light on this issue?

    The patch appears to prevent the deadlock for the test https://github.com/pandaman64/hyper-hang-tokio but it is not the best solution. I've observed some regressions when using it under normal circumstances which is why I never opened a PR. I left it for future reference.

    I should note my application makes an arguably exotic use of reqwest and hyper (legacy) client pools by communicating with thousands of remote hosts in a distributed system, often with several connections each, in an async+multi-threaded process: we do not set pool_max_idle_per_host=0. I have never hit this deadlock and no users have ever reported it. Thus I have not revisited this issue in some time now...

  26. juliusl commented on Sep 28, 2024

    @juliusl
    juliusl
    on Sep 28, 2024

    @pandaman64 out of curiosity, does this repro if you read the response of the first request in your example?

         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(_resp.into_body().into_future());
        tokio::spawn(res.into_body().into_future());

  27. pandaman64 commented on Oct 6, 2024

    @pandaman64
    pandaman64
    on Oct 6, 2024
    Author

    @juliusl I no longer have the environment reproduced the issue so I cannot comment on this, but I believe some other examples linked in this issue do read the body.

  28. seanmonstar commented on Nov 4, 2024

    @seanmonstar
    seanmonstar
    on Nov 4, 2024
    Member

    I appreciate that many have linked to this issue, and that some have included details. But the maintainers have so far been unable to reproduce in a way that we can investigate this. The code in question is also run under large load in many systems where it doesn't seem to occur. And, because of the generic title, I suspect many link here with issues that are probably separate. So, my plan here is to close this specific issue.

    This isn't to say that the issue can't be in hyper. We unfortunately do write bugs. But if this is an issue in your system, if you can help debug where exactly the hang is, that would greatly help us help you. New issues with unique details are always welcome.

  29. seanmonstar
    closed this as not plannedon Nov 4, 2024
  30. tgoodyear
    added a commit that references this issue on Oct 10, 2026

    Azure blob storage: share a pooled HTTP client and token credential

    5fecc2c
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

No one assigned

    Labels

    No labels
    No labels

    Type

    No type

    Projects

    No projects

      Milestone

      No milestone

      Relationships

      None yet

      Development

      No branches or pull requests

      Issue actions