h1-client: "Connection closed" error when re-using the H1Client for a 2nd request

[JEnoch]

The following code uses the same H1Client instance to perform twice the same request (http). The second request hangs for ~5 seconds and then returns an Err with "connection closed". The same code using IsahcClient doesn't fail.

use http_client::h1::H1Client as DefaultClient;
// use http_client::isahc::IsahcClient as DefaultClient;

use http_client::HttpClient;
use http_client::http_types::*;
use async_std::task;

fn main() {
    task::block_on(async {
        env_logger::init();

        let url = "http://httpd.apache.org/";
        let req = Request::new(Method::Get, Url::parse(url).unwrap());
        let client = DefaultClient::new();

        println!("GET {} #1", url);
        let mut res: Response = client.send(req.clone()).await.unwrap();
        if res.status() != StatusCode::Ok {
            println!("ERROR in result: {:?}", res);
            panic!();
        }
        let msg = res.body_bytes().await.unwrap();
        let msg = String::from_utf8_lossy(&msg);
        if !msg.contains("The Apache HTTP Server Project") {
            panic!();
        }
        println!("#1 OK");

        println!("GET {} #2", url);
        let mut res: Response = client.send(req.clone()).await.unwrap();
        if res.status() != StatusCode::Ok {
            println!("ERROR in result: {:?}", res);
            panic!();
        }
        let msg = res.body_bytes().await.unwrap();
        let msg = String::from_utf8_lossy(&msg);
        if !msg.contains("The Apache HTTP Server Project") {
            panic!();
        }
        println!("#2 OK");
    });
}

Cargo.toml:

[package]
name = "http-client-test"
version = "0.0.1"
edition = "2018"

[dependencies]
http-client = { version = "6.3.3", default-features = false, features = ["h1_client"] }
# http-client = { version = "6.3.3", default-features = false, features = ["curl_client"] }
async-std = "1.9.0"
env_logger = "0.8"

[[bin]]
name = "test"

[Fishrock123]

This is the fault of the new connection pooling code. We should back it out under an unstable flag. This will take my Friday, probably.

I was going to try to fix first it but the backtraces are absolute indecipherable nonsense and not at all useful. https://github.com/http-rs/http-client/pull/72 Was a hopeful attempt at fixing this and related issues but does not seemed to have covered all the bases...

For what it's worth, https://github.com/http-rs/surf/pull/294 makes the tests run into this.

[JEnoch]

Sorry to spoil you Friday! I stumbled on this trying to make influxdb-rs to use Surf with h1-client... I dug up to this point, but was puzzled by the real cause and the lack of useful logs.

[Fishrock123]

http-client reproducible test case:

#[async_std::test]
async fn keep_alive() {
    let _mock_guard = mockito::mock("GET", "/report")
        .with_status(200)
        .expect_at_least(2)
        .create();

    let client = DefaultClient::new();
    let url: Url = format!("{}/report", mockito::server_url()).parse().unwrap();
    let req = Request::new(
        http_types::Method::Get,
        url
    );
    client.send(req.clone()).await.unwrap();
    client.send(req.clone()).await.unwrap();
}

[Fishrock123]

Here is the backtrace, this 100% indecipherable. This comes from some thread in core??

How is this possible? Shouldn't there be at least some stack of async-io's driver/reactor hitting epoll? I am so confused.

thread 'keep_alive' panicked at 'called `Result::unwrap()` on an `Err` value: An established connection was aborted by the software in your host machine. (os error 10053)', tests\test.rs:46:36
stack backtrace:
   0:     0x7ff73163f6be - std::backtrace_rs::backtrace::dbghelp::trace
                               at /rustc/cb75ad5db02783e8b0222fee363c5f63f7e2cf5b\/library\std\src\..\..\backtrace\src\backtrace\dbghelp.rs:98
   1:     0x7ff73163f6be - std::backtrace_rs::backtrace::trace_unsynchronized
                               at /rustc/cb75ad5db02783e8b0222fee363c5f63f7e2cf5b\/library\std\src\..\..\backtrace\src\backtrace\mod.rs:66
   2:     0x7ff73163f6be - std::sys_common::backtrace::_print_fmt
                               at /rustc/cb75ad5db02783e8b0222fee363c5f63f7e2cf5b\/library\std\src\sys_common\backtrace.rs:67
   3:     0x7ff73163f6be - std::sys_common::backtrace::_print::{{impl}}::fmt
                               at /rustc/cb75ad5db02783e8b0222fee363c5f63f7e2cf5b\/library\std\src\sys_common\backtrace.rs:46
   4:     0x7ff73165c58b - core::fmt::write
                               at /rustc/cb75ad5db02783e8b0222fee363c5f63f7e2cf5b\/library\core\src\fmt\mod.rs:1078
   5:     0x7ff731637228 - std::io::Write::write_fmt<alloc::vec::Vec<u8, alloc::alloc::Global>>
                               at /rustc/cb75ad5db02783e8b0222fee363c5f63f7e2cf5b\/library\std\src\io\mod.rs:1517
   6:     0x7ff731642abd - std::sys_common::backtrace::_print
                               at /rustc/cb75ad5db02783e8b0222fee363c5f63f7e2cf5b\/library\std\src\sys_common\backtrace.rs:49
   7:     0x7ff731642abd - std::sys_common::backtrace::print
                               at /rustc/cb75ad5db02783e8b0222fee363c5f63f7e2cf5b\/library\std\src\sys_common\backtrace.rs:36
   8:     0x7ff731642abd - std::panicking::default_hook::{{closure}}
                               at /rustc/cb75ad5db02783e8b0222fee363c5f63f7e2cf5b\/library\std\src\panicking.rs:208
   9:     0x7ff731642555 - std::panicking::default_hook
                               at /rustc/cb75ad5db02783e8b0222fee363c5f63f7e2cf5b\/library\std\src\panicking.rs:222
  10:     0x7ff7316433ce - std::panicking::rust_panic_with_hook
                               at /rustc/cb75ad5db02783e8b0222fee363c5f63f7e2cf5b\/library\std\src\panicking.rs:591
  11:     0x7ff731642ef1 - std::panicking::begin_panic_handler::{{closure}}
                               at /rustc/cb75ad5db02783e8b0222fee363c5f63f7e2cf5b\/library\std\src\panicking.rs:497
  12:     0x7ff73164001f - std::sys_common::backtrace::__rust_end_short_backtrace<closure-0,!>
                               at /rustc/cb75ad5db02783e8b0222fee363c5f63f7e2cf5b\/library\std\src\sys_common\backtrace.rs:141
  13:     0x7ff731642e49 - std::panicking::begin_panic_handler
                               at /rustc/cb75ad5db02783e8b0222fee363c5f63f7e2cf5b\/library\std\src\panicking.rs:493
  14:     0x7ff73165ab40 - core::panicking::panic_fmt
                               at /rustc/cb75ad5db02783e8b0222fee363c5f63f7e2cf5b\/library\core\src\panicking.rs:92
  15:     0x7ff73165a963 - core::option::expect_none_failed
                               at /rustc/cb75ad5db02783e8b0222fee363c5f63f7e2cf5b\/library\core\src\option.rs:1268
  16:     0x7ff731056710 - core::result::Result<http_types::response::Response, http_types::error::Error>::unwrap<http_types::response::Response,http_types::error::Error>
                               at C:\Users\Jeremiah\.rustup\toolchains\stable-x86_64-pc-windows-msvc\lib\rustlib\src\rust\library\core\src\result.rs:973
  17:     0x7ff73105b1bd - test::keep_alive::{{closure}}
                               at W:\Rust-Projects\http-client\tests\test.rs:46
  18:     0x7ff731058a79 - core::future::from_generator::{{impl}}::poll<generator-0>
                               at C:\Users\Jeremiah\.rustup\toolchains\stable-x86_64-pc-windows-msvc\lib\rustlib\src\rust\library\core\src\future\mod.rs:80
  19:     0x7ff7310598e9 - async_std::task::builder::{{impl}}::poll::{{closure}}<core::future::from_generator::GenFuture<generator-0>>
                               at C:\Users\Jeremiah\.cargo\registry\src\github.com-1ecc6299db9ec823\async-std-1.9.0\src\task\builder.rs:199
  20:     0x7ff73105aac1 - async_std::task::task_locals_wrapper::{{impl}}::set_current::{{closure}}<closure-0,core::task::poll::Poll<tuple<>>>
                               at C:\Users\Jeremiah\.cargo\registry\src\github.com-1ecc6299db9ec823\async-std-1.9.0\src\task\task_locals_wrapper.rs:60
  21:     0x7ff731052314 - std::thread::local::LocalKey<core::cell::Cell<const async_std::task::task_locals_wrapper::TaskLocalsWrapper*>>::try_with<core::cell::Cell<const async_std::task::task_locals_wrapper::TaskLocalsWrapper*>,closure-0,core::task::poll::Poll<tuple<>>>
                               at C:\Users\Jeremiah\.rustup\toolchains\stable-x86_64-pc-windows-msvc\lib\rustlib\src\rust\library\std\src\thread\local.rs:272
  22:     0x7ff731051d8d - std::thread::local::LocalKey<core::cell::Cell<const async_std::task::task_locals_wrapper::TaskLocalsWrapper*>>::with<core::cell::Cell<const async_std::task::task_locals_wrapper::TaskLocalsWrapper*>,closure-0,core::task::poll::Poll<tuple<>>>
                               at C:\Users\Jeremiah\.rustup\toolchains\stable-x86_64-pc-windows-msvc\lib\rustlib\src\rust\library\std\src\thread\local.rs:248
  23:     0x7ff73105a87b - async_std::task::task_locals_wrapper::TaskLocalsWrapper::set_current<closure-0,core::task::poll::Poll<tuple<>>>
                               at C:\Users\Jeremiah\.cargo\registry\src\github.com-1ecc6299db9ec823\async-std-1.9.0\src\task\task_locals_wrapper.rs:55
  24:     0x7ff731059898 - async_std::task::builder::{{impl}}::poll<core::future::from_generator::GenFuture<generator-0>>
                               at C:\Users\Jeremiah\.cargo\registry\src\github.com-1ecc6299db9ec823\async-std-1.9.0\src\task\builder.rs:197
  25:     0x7ff731056d1b - futures_lite::future::{{impl}}::poll<tuple<>,async_std::task::builder::SupportTaskLocals<core::future::from_generator::GenFuture<generator-0>>,core::future::from_generator::GenFuture<generator-0>>
                               at C:\Users\Jeremiah\.cargo\registry\src\github.com-1ecc6299db9ec823\futures-lite-1.11.3\src\future.rs:526
  26:     0x7ff731054ba9 - async_executor::{{impl}}::run::{{closure}}<tuple<>,async_std::task::builder::SupportTaskLocals<core::future::from_generator::GenFuture<generator-0>>>      
                               at C:\Users\Jeremiah\.cargo\registry\src\github.com-1ecc6299db9ec823\async-executor-1.4.0\src\lib.rs:236
  27:     0x7ff7310589e9 - core::future::from_generator::{{impl}}::poll<generator-0>
                               at C:\Users\Jeremiah\.rustup\toolchains\stable-x86_64-pc-windows-msvc\lib\rustlib\src\rust\library\core\src\future\mod.rs:80
  28:     0x7ff731054720 - async_executor::{{impl}}::run::{{closure}}<tuple<>,async_std::task::builder::SupportTaskLocals<core::future::from_generator::GenFuture<generator-0>>>      
                               at C:\Users\Jeremiah\.cargo\registry\src\github.com-1ecc6299db9ec823\async-executor-1.4.0\src\lib.rs:437
  29:     0x7ff731058b99 - core::future::from_generator::{{impl}}::poll<generator-0>
                               at C:\Users\Jeremiah\.rustup\toolchains\stable-x86_64-pc-windows-msvc\lib\rustlib\src\rust\library\core\src\future\mod.rs:80
  30:     0x7ff7310533ba - async_io::driver::block_on<tuple<>,core::future::from_generator::GenFuture<generator-0>>
                               at C:\Users\Jeremiah\.cargo\registry\src\github.com-1ecc6299db9ec823\async-io-1.3.1\src\driver.rs:142
  31:     0x7ff731057ee6 - async_global_executor::reactor::block_on::{{closure}}<core::future::from_generator::GenFuture<generator-0>,tuple<>>
                               at C:\Users\Jeremiah\.cargo\registry\src\github.com-1ecc6299db9ec823\async-global-executor-2.0.2\src\reactor.rs:3
  32:     0x7ff731057ea0 - async_global_executor::reactor::block_on<core::future::from_generator::GenFuture<generator-0>,tuple<>>
                               at C:\Users\Jeremiah\.cargo\registry\src\github.com-1ecc6299db9ec823\async-global-executor-2.0.2\src\reactor.rs:12
  33:     0x7ff731058efd - async_global_executor::executor::block_on::{{closure}}<async_std::task::builder::SupportTaskLocals<core::future::from_generator::GenFuture<generator-0>>,tuple<>>
                               at C:\Users\Jeremiah\.cargo\registry\src\github.com-1ecc6299db9ec823\async-global-executor-2.0.2\src\executor.rs:26
  34:     0x7ff7310521ff - std::thread::local::LocalKey<async_executor::LocalExecutor>::try_with<async_executor::LocalExecutor,closure-0,tuple<>>
                               at C:\Users\Jeremiah\.rustup\toolchains\stable-x86_64-pc-windows-msvc\lib\rustlib\src\rust\library\std\src\thread\local.rs:272
  35:     0x7ff731051d2e - std::thread::local::LocalKey<async_executor::LocalExecutor>::with<async_executor::LocalExecutor,closure-0,tuple<>>
                               at C:\Users\Jeremiah\.rustup\toolchains\stable-x86_64-pc-windows-msvc\lib\rustlib\src\rust\library\std\src\thread\local.rs:248
  36:     0x7ff731058e8a - async_global_executor::executor::block_on<async_std::task::builder::SupportTaskLocals<core::future::from_generator::GenFuture<generator-0>>,tuple<>>       
                               at C:\Users\Jeremiah\.cargo\registry\src\github.com-1ecc6299db9ec823\async-global-executor-2.0.2\src\executor.rs:26
  37:     0x7ff73105a09a - async_std::task::builder::{{impl}}::blocking::{{closure}}::{{closure}}<core::future::from_generator::GenFuture<generator-0>,tuple<>>
                               at C:\Users\Jeremiah\.cargo\registry\src\github.com-1ecc6299db9ec823\async-std-1.9.0\src\task\builder.rs:171
  38:     0x7ff73105a9ae - async_std::task::task_locals_wrapper::{{impl}}::set_current::{{closure}}<closure-0,tuple<>>
                               at C:\Users\Jeremiah\.cargo\registry\src\github.com-1ecc6299db9ec823\async-std-1.9.0\src\task\task_locals_wrapper.rs:60
  39:     0x7ff7310520bf - std::thread::local::LocalKey<core::cell::Cell<const async_std::task::task_locals_wrapper::TaskLocalsWrapper*>>::try_with<core::cell::Cell<const async_std::task::task_locals_wrapper::TaskLocalsWrapper*>,closure-0,tuple<>>
                               at C:\Users\Jeremiah\.rustup\toolchains\stable-x86_64-pc-windows-msvc\lib\rustlib\src\rust\library\std\src\thread\local.rs:272
  40:     0x7ff731051e4e - std::thread::local::LocalKey<core::cell::Cell<const async_std::task::task_locals_wrapper::TaskLocalsWrapper*>>::with<core::cell::Cell<const async_std::task::task_locals_wrapper::TaskLocalsWrapper*>,closure-0,tuple<>>
                               at C:\Users\Jeremiah\.rustup\toolchains\stable-x86_64-pc-windows-msvc\lib\rustlib\src\rust\library\std\src\thread\local.rs:248
  41:     0x7ff73105a8e3 - async_std::task::task_locals_wrapper::TaskLocalsWrapper::set_current<closure-0,tuple<>>
                               at C:\Users\Jeremiah\.cargo\registry\src\github.com-1ecc6299db9ec823\async-std-1.9.0\src\task\task_locals_wrapper.rs:55
  42:     0x7ff731059fb2 - async_std::task::builder::{{impl}}::blocking::{{closure}}<core::future::from_generator::GenFuture<generator-0>,tuple<>>
                               at C:\Users\Jeremiah\.cargo\registry\src\github.com-1ecc6299db9ec823\async-std-1.9.0\src\task\builder.rs:168
  43:     0x7ff73105272f - std::thread::local::LocalKey<core::cell::Cell<usize>>::try_with<core::cell::Cell<usize>,closure-0,tuple<>>
                               at C:\Users\Jeremiah\.rustup\toolchains\stable-x86_64-pc-windows-msvc\lib\rustlib\src\rust\library\std\src\thread\local.rs:272
  44:     0x7ff731051f7e - std::thread::local::LocalKey<core::cell::Cell<usize>>::with<core::cell::Cell<usize>,closure-0,tuple<>>
                               at C:\Users\Jeremiah\.rustup\toolchains\stable-x86_64-pc-windows-msvc\lib\rustlib\src\rust\library\std\src\thread\local.rs:248
  45:     0x7ff731059e82 - async_std::task::builder::Builder::blocking<core::future::from_generator::GenFuture<generator-0>,tuple<>>
                               at C:\Users\Jeremiah\.cargo\registry\src\github.com-1ecc6299db9ec823\async-std-1.9.0\src\task\builder.rs:161
  46:     0x7ff73105716d - async_std::task::block_on::block_on<core::future::from_generator::GenFuture<generator-0>,tuple<>>
                               at C:\Users\Jeremiah\.cargo\registry\src\github.com-1ecc6299db9ec823\async-std-1.9.0\src\task\block_on.rs:33
  47:     0x7ff73105a56b - test::keep_alive
                               at W:\Rust-Projects\http-client\tests\test.rs:32
  48:     0x7ff73105ac2e - test::keep_alive::{{closure}}
                               at W:\Rust-Projects\http-client\tests\test.rs:32
  49:     0x7ff73105584b - core::ops::function::FnOnce::call_once<closure-0,tuple<>>
                               at C:\Users\Jeremiah\.rustup\toolchains\stable-x86_64-pc-windows-msvc\lib\rustlib\src\rust\library\core\src\ops\function.rs:227
  50:     0x7ff73108d2e6 - core::ops::function::FnOnce::call_once
                               at /rustc/cb75ad5db02783e8b0222fee363c5f63f7e2cf5b\library\core\src\ops\function.rs:227
  51:     0x7ff73108d2e6 - test::__rust_begin_short_backtrace<fn()>
                               at /rustc/cb75ad5db02783e8b0222fee363c5f63f7e2cf5b\/library\test\src\lib.rs:516
  52:     0x7ff73108b045 - alloc::boxed::{{impl}}::call_once
                               at /rustc/cb75ad5db02783e8b0222fee363c5f63f7e2cf5b\library\alloc\src\boxed.rs:1328
  53:     0x7ff73108b045 - std::panic::{{impl}}::call_once
                               at /rustc/cb75ad5db02783e8b0222fee363c5f63f7e2cf5b\library\std\src\panic.rs:322
  54:     0x7ff73108b045 - std::panicking::try::do_call
                               at /rustc/cb75ad5db02783e8b0222fee363c5f63f7e2cf5b\library\std\src\panicking.rs:379
  55:     0x7ff73108b045 - std::panicking::try
                               at /rustc/cb75ad5db02783e8b0222fee363c5f63f7e2cf5b\library\std\src\panicking.rs:343
  56:     0x7ff73108b045 - std::panic::catch_unwind
                               at /rustc/cb75ad5db02783e8b0222fee363c5f63f7e2cf5b\library\std\src\panic.rs:396
  57:     0x7ff73108b045 - test::run_test_in_process
                               at /rustc/cb75ad5db02783e8b0222fee363c5f63f7e2cf5b\/library\test\src\lib.rs:538
  58:     0x7ff73108b045 - test::run_test::run_test_inner::{{closure}}
                               at /rustc/cb75ad5db02783e8b0222fee363c5f63f7e2cf5b\/library\test\src\lib.rs:449
  59:     0x7ff73105c3d6 - std::sys_common::backtrace::__rust_begin_short_backtrace<closure-0,tuple<>>
                               at /rustc/cb75ad5db02783e8b0222fee363c5f63f7e2cf5b\library\std\src\sys_common\backtrace.rs:125
  60:     0x7ff73105c3d6 - std::sys_common::backtrace::__rust_begin_short_backtrace<closure-0,tuple<>>
                               at /rustc/cb75ad5db02783e8b0222fee363c5f63f7e2cf5b\library\std\src\sys_common\backtrace.rs:125
  61:     0x7ff731062d04 - std::thread::{{impl}}::spawn_unchecked::{{closure}}::{{closure}}
                               at /rustc/cb75ad5db02783e8b0222fee363c5f63f7e2cf5b\library\std\src\thread\mod.rs:474
  62:     0x7ff731062d04 - std::panic::{{impl}}::call_once
                               at /rustc/cb75ad5db02783e8b0222fee363c5f63f7e2cf5b\library\std\src\panic.rs:322
  63:     0x7ff731062d04 - std::panicking::try::do_call
                               at /rustc/cb75ad5db02783e8b0222fee363c5f63f7e2cf5b\library\std\src\panicking.rs:379
  64:     0x7ff731062d04 - std::panicking::try
                               at /rustc/cb75ad5db02783e8b0222fee363c5f63f7e2cf5b\library\std\src\panicking.rs:343
  65:     0x7ff731062d04 - std::panic::catch_unwind
                               at /rustc/cb75ad5db02783e8b0222fee363c5f63f7e2cf5b\library\std\src\panic.rs:396
  66:     0x7ff731062d04 - std::thread::{{impl}}::spawn_unchecked::{{closure}}
                               at /rustc/cb75ad5db02783e8b0222fee363c5f63f7e2cf5b\library\std\src\thread\mod.rs:473
  67:     0x7ff731062d04 - core::ops::function::FnOnce::call_once<closure-0,tuple<>>
                               at /rustc/cb75ad5db02783e8b0222fee363c5f63f7e2cf5b\library\core\src\ops\function.rs:227
  68:     0x7ff73164c7e3 - alloc::boxed::{{impl}}::call_once
                               at /rustc/cb75ad5db02783e8b0222fee363c5f63f7e2cf5b\library\alloc\src\boxed.rs:1328
  69:     0x7ff73164c7e3 - alloc::boxed::{{impl}}::call_once
                               at /rustc/cb75ad5db02783e8b0222fee363c5f63f7e2cf5b\library\alloc\src\boxed.rs:1328
  70:     0x7ff73164c7e3 - std::sys::windows::thread::{{impl}}::new::thread_start
                               at /rustc/cb75ad5db02783e8b0222fee363c5f63f7e2cf5b\/library\std\src\sys\windows\thread.rs:56
  71:     0x7ff9c3347034 - BaseThreadInitThunk
  72:     0x7ff9c3e3d241 - RtlUserThreadStart

[Fishrock123]

I... think I have a working fix at https://github.com/http-rs/http-client/pull/77

I can confirm it fixes the issue in both test cases provided. I am not sure if it actually ever re-uses connections.

[Fishrock123]

@JEnoch Can you please confirm if this is fixed in v6.3.4?

[JEnoch]

@Fishrock123 I confirm it's fixed with v6.3.4. Thanks a lot!