Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

thread 'isahc-agent-42001' panicked #295

Closed
aurexav opened this issue Jan 29, 2021 · 5 comments
Closed

thread 'isahc-agent-42001' panicked #295

aurexav opened this issue Jan 29, 2021 · 5 comments
Labels
bug Something is borken

Comments

@aurexav
Copy link

aurexav commented Jan 29, 2021 •
edited
Loading

Is this a bug of isahc? I just:

for i in 0.. {
    http_client.send_async(request(i)).await?;
}

Then it:

// thread 'isahc-agent-42651' panicked at 'Receiver::next_message called after `None` 2021-01-29T10:50:51.263Z TRACE subalfred::substrate::github > 201
// ', /home/xavier/.cargo/registry/src/git.luolix.top-1ecc6299db9ec823/futures-channel-0.3.12/src/mpsc/mod.rs:1035:41
// note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace
// Error: unknown error
//
// Caused by:
//     [26] Failed to open/read local data from file/application
@sagebind
Copy link
Owner

Thanks for filing an issue! First let's get some additional info so that I can help troubleshoot:

  • What version of Isahc are you using?
  • How is your HTTP client configured?
  • Can you include a full backtrace of the error?

@aurexav
Copy link
Author

aurexav commented Jan 29, 2021 •
edited
Loading

  1. isahc = { version = "1.0.3", features = ["json"] }
  2. pub fn new(oauth_token: impl AsRef<str>) -> Self {
	let http_client = HttpClientBuilder::new()
		.default_header("Authorization", &format!("token {}", oauth_token.as_ref()))
		.build()
		.unwrap();

	Self { http_client }
}
  3. stack backtrace:
   0:     0x5636d032d710 - std::backtrace_rs::backtrace::libunwind::trace::he85dfb3ae4206056
                               at /rustc/a1dfd2490a6cb456b92e469fa550dc217e20ad6d/library/std/src/../../backtrace/src/backtrace/libunwind.rs:96
   1:     0x5636d032d710 - std::backtrace_rs::backtrace::trace_unsynchronized::h1ad28094d7b00c21
                               at /rustc/a1dfd2490a6cb456b92e469fa550dc217e20ad6d/library/std/src/../../backtrace/src/backtrace/mod.rs:66
   2:     0x5636d032d710 - std::sys_common::backtrace::_print_fmt::h901b54610713cd21
                               at /rustc/a1dfd2490a6cb456b92e469fa550dc217e20ad6d/library/std/src/sys_common/backtrace.rs:79
   3:     0x5636d032d710 - <std::sys_common::backtrace::_print::DisplayBacktrace as core::fmt::Display>::fmt::hb0ad78ee1571f7e0
                               at /rustc/a1dfd2490a6cb456b92e469fa550dc217e20ad6d/library/std/src/sys_common/backtrace.rs:58
   4:     0x5636d0353e1c - core::fmt::write::h1857a60b204f1b6a
                               at /rustc/a1dfd2490a6cb456b92e469fa550dc217e20ad6d/library/core/src/fmt/mod.rs:1080
   5:     0x5636d03262b2 - std::io::Write::write_fmt::hf7b7d7b243f84a36
                               at /rustc/a1dfd2490a6cb456b92e469fa550dc217e20ad6d/library/std/src/io/mod.rs:1516
   6:     0x5636d032ff4d - std::sys_common::backtrace::_print::hd093978a5287b8ff
                               at /rustc/a1dfd2490a6cb456b92e469fa550dc217e20ad6d/library/std/src/sys_common/backtrace.rs:61
   7:     0x5636d032ff4d - std::sys_common::backtrace::print::h20f46787581d56d7
                               at /rustc/a1dfd2490a6cb456b92e469fa550dc217e20ad6d/library/std/src/sys_common/backtrace.rs:48
   8:     0x5636d032ff4d - std::panicking::default_hook::{{closure}}::h486cbb4b82ffc357
                               at /rustc/a1dfd2490a6cb456b92e469fa550dc217e20ad6d/library/std/src/panicking.rs:208
   9:     0x5636d032fbf8 - std::panicking::default_hook::h4190c9e3edd4d591
                               at /rustc/a1dfd2490a6cb456b92e469fa550dc217e20ad6d/library/std/src/panicking.rs:227
  10:     0x5636d0330631 - std::panicking::rust_panic_with_hook::h72e78719cdda225c
                               at /rustc/a1dfd2490a6cb456b92e469fa550dc217e20ad6d/library/std/src/panicking.rs:577
  11:     0x5636d03301d9 - std::panicking::begin_panic_handler::{{closure}}::h8bd07dbd34150a96
                               at /rustc/a1dfd2490a6cb456b92e469fa550dc217e20ad6d/library/std/src/panicking.rs:484
  12:     0x5636d032dbac - std::sys_common::backtrace::__rust_end_short_backtrace::hdb6b3066ad29028a
                               at /rustc/a1dfd2490a6cb456b92e469fa550dc217e20ad6d/library/std/src/sys_common/backtrace.rs:153
  13:     0x5636d0330199 - rust_begin_unwind
                               at /rustc/a1dfd2490a6cb456b92e469fa550dc217e20ad6d/library/std/src/panicking.rs:483
  14:     0x5636d0352441 - core::panicking::panic_fmt::hb15d6f55e8472f62
                               at /rustc/a1dfd2490a6cb456b92e469fa550dc217e20ad6d/library/core/src/panicking.rs:85
  15:     0x5636d03521d3 - core::option::expect_failed::h6bc6a05976f4cb88
                               at /rustc/a1dfd2490a6cb456b92e469fa550dc217e20ad6d/library/core/src/option.rs:1226
  16:     0x5636d0290a67 - futures_channel::mpsc::Receiver<T>::next_message::h25ff8b37b8b250b2
  17:     0x5636d02911bc - <futures_channel::mpsc::Receiver<T> as futures_core::stream::Stream>::poll_next::ha693d748ae190604
  18:     0x5636d028ff65 - <sluice::pipe::chunked::Writer as futures_io::if_std::AsyncWrite>::poll_write::h91d57b4a4ffd5c6b
  19:     0x5636d028f95a - <sluice::pipe::PipeWriter as futures_io::if_std::AsyncWrite>::poll_write::h7fe90838a7b83873
  20:     0x5636d02253e1 - <isahc::handler::RequestHandler as curl::easy::handler::Handler>::write::h3c040b0be9927c29
  21:     0x5636d02602eb - curl::panic::catch::hfc71357895624e7a
  22:     0x5636d024e7ea - curl::easy::handler::write_cb::he679381db280074b
  23:     0x5636d02a4b27 - Curl_client_write
  24:     0x5636d02aebbd - Curl_readwrite
  25:     0x5636d02a1967 - multi_runsingle
  26:     0x5636d02a29d8 - curl_multi_perform
  27:     0x5636d0292257 - curl::multi::Multi::perform::h3f79c3cc34ae337b
  28:     0x5636d021d858 - isahc::agent::AgentContext::run::hc9067e195cdae57a
  29:     0x5636d023d4a4 - std::sys_common::backtrace::__rust_begin_short_backtrace::hbd3934591a01321c
  30:     0x5636d025f40c - core::ops::function::FnOnce::call_once{{vtable.shim}}::h9f283ec974350ddc
  31:     0x5636d033820a - <alloc::boxed::Box<F> as core::ops::function::FnOnce<A>>::call_once::h1080dfe0ef616bdf
                               at /rustc/a1dfd2490a6cb456b92e469fa550dc217e20ad6d/library/alloc/src/boxed.rs:1042
  32:     0x5636d033820a - <alloc::boxed::Box<F> as core::ops::function::FnOnce<A>>::call_once::hd2747e1f2d5cec32
                               at /rustc/a1dfd2490a6cb456b92e469fa550dc217e20ad6d/library/alloc/src/boxed.rs:1042
  33:     0x5636d033820a - std::sys::unix::thread::Thread::new::thread_start::hd0f336b4ef6808a7
                               at /rustc/a1dfd2490a6cb456b92e469fa550dc217e20ad6d/library/std/src/sys/unix/thread.rs:87
  34:     0x7f72363143e9 - start_thread
  35:     0x7f7236575293 - __GI___clone
  36:                0x0 - <unknown>
Error: unknown error

Caused by:
    [26] Failed to open/read local data from file/application

Stack backtrace:
   0: <core::future::from_generator::GenFuture<T> as core::future::future::Future>::poll
   1: subalfred::main::main::{{closure}}
   2: <core::future::from_generator::GenFuture<T> as core::future::future::Future>::poll
   3: std::thread::local::LocalKey<T>::with
   4: <core::future::from_generator::GenFuture<T> as core::future::future::Future>::poll
   5: async_io::driver::block_on
   6: std::thread::local::LocalKey<T>::with
   7: async_std::task::builder::Builder::blocking
   8: subalfred::main
   9: std::sys_common::backtrace::__rust_begin_short_backtrace
  10: std::rt::lang_start::{{closure}}
  11: core::ops::function::impls::<impl core::ops::function::FnOnce<A> for &F>::call_once
             at /rustc/a1dfd2490a6cb456b92e469fa550dc217e20ad6d/library/core/src/ops/function.rs:259
      std::panicking::try::do_call
             at /rustc/a1dfd2490a6cb456b92e469fa550dc217e20ad6d/library/std/src/panicking.rs:381
      std::panicking::try
             at /rustc/a1dfd2490a6cb456b92e469fa550dc217e20ad6d/library/std/src/panicking.rs:345
      std::panic::catch_unwind
             at /rustc/a1dfd2490a6cb456b92e469fa550dc217e20ad6d/library/std/src/panic.rs:382
      std::rt::lang_start_internal
             at /rustc/a1dfd2490a6cb456b92e469fa550dc217e20ad6d/library/std/src/rt.rs:51
  12: main
  13: __libc_start_main
  14: _start

@aurexav
Copy link
Author

aurexav commented Jan 29, 2021 •
edited
Loading

The request body's length is around 65536.

If I truncate it to 8192, that will increase the chance of success. But still will fail (in that infinite loop).

@sagebind
Copy link
Owner

Thanks, this is very helpful! Based on the stack trace, I think this might be caused by a bug in sluice. Could be similar to #72. I will look into it further when I have a chance.

@sagebind sagebind added the bug Something is borken label Jan 29, 2021
sagebind added a commit to sagebind/sluice that referenced this issue Jan 30, 2021
@sagebind
Fix panic caused by race condition when writing while dropping reader
ffe43f8 
`Writer` has a race condition that might cause a panic if `poll_write` is called more than once while the `Reader` is in the processed of being dropped on another thread.

The race condition is caused by the drop order of `Reader`: Since fields are dropped in the order they are defined in, the buffer pool channel is dropped _before_ the buffer stream channel. If `poll_write` is called more than once between these two drop calls, then the underlying channel will panic because we've polled it after already returning `None`.

The fix is to ensure the buffer stream channel is closed _first_ before the buffer pool channel, since that is the channel we use to detect when the reader is closed. One way of doing this would be to just reverse the order these two fields are defined in, but it is better to be clear that the drop order matters by using an explicit drop handler.

See also sagebind/isahc#295.
@sagebind sagebind mentioned this issue Jan 30, 2021
Merged
@sagebind
Copy link
Owner

My hunch was correct; this appears to be a rare race condition bug in sluice: sagebind/sluice#16. I will push a patch for sluice and a patch in Isahc that pulls in the fix shortly.

sagebind added a commit to sagebind/sluice that referenced this issue Jan 30, 2021
@sagebind
Fix panic caused by race condition when writing while dropping reader (…
8ca411f 
…#16)

`Writer` has a race condition that might cause a panic if `poll_write` is called more than once while the `Reader` is in the processed of being dropped on another thread.

The race condition is caused by the drop order of `Reader`: Since fields are dropped in the order they are defined in, the buffer pool channel is dropped _before_ the buffer stream channel. If `poll_write` is called more than once between these two drop calls, then the underlying channel will panic because we've polled it after already returning `None`.

The fix is to ensure the buffer stream channel is closed _first_ before the buffer pool channel, since that is the channel we use to detect when the reader is closed. One way of doing this would be to just reverse the order these two fields are defined in, but it is better to be clear that the drop order matters by using an explicit drop handler.

With this fix, we know that the second channel will be polled _at most_ once when closed, because subsequent calls to `poll_write` will check the first channel before polling the second.

See also sagebind/isahc#295.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
bug Something is borken
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@sagebind @aurexav