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

WouldBlock bubbling up to the calling code #31

Closed
pimeys opened this issue Sep 29, 2020 · 10 comments
Closed

WouldBlock bubbling up to the calling code #31

pimeys opened this issue Sep 29, 2020 · 10 comments

Comments

@pimeys
Copy link

pimeys commented Sep 29, 2020

I have an issue with async-native-tls together with async-std, and looking into the backtrace, it points to somewhere in this crate.

Our crate (tiberius) runs tests just fine with tokio and async-std 1.6.3, but updating async-std to 1.6.4 or later randomly throws Io(Kind(WouldBlock)). We have a few hundred tests, and 1-5 of them randomly fail into this error. The error happens when calling connect from TlsConnector (async-native-tls 0.3.3) and passing a TcpStream to it from async-std 1.6.5 (or 1.6.4).

As I said, when passing a TcpStream from async-std 1.6.3 or a Compat version from tokio 0.2.x, the errors never happen. Hopefully this is the right crate to create the issue!

Here's a full backtrace from one of the failing tests:

---- transactions_async_std stdout ----
thread 'transactions_async_std' panicked at 'called `Result::unwrap()` on an `Err` value: Ssl(Error { code: ErrorCode(5), cause: Some(Io(Kind(WouldBlock))) }, X509VerifyResult { code: 18, error: "self signed certificate" })', /home/pimeys/code/tiberius/src/client/connection.rs:387:22
stack backtrace:
   0:     0x55f6b0a016d5 - backtrace::backtrace::libunwind::trace::h14d338b30b3ea0a7
                               at /cargo/registry/src/github.com-1ecc6299db9ec823/backtrace-0.3.46/src/backtrace/libunwind.rs:86
   1:     0x55f6b0a016d5 - backtrace::backtrace::trace_unsynchronized::h73ea91d74a3fd67f
                               at /cargo/registry/src/github.com-1ecc6299db9ec823/backtrace-0.3.46/src/backtrace/mod.rs:66
   2:     0x55f6b0a016d5 - std::sys_common::backtrace::_print_fmt::hd42948c952866e12
                               at src/libstd/sys_common/backtrace.rs:78
   3:     0x55f6b0a016d5 - <std::sys_common::backtrace::_print::DisplayBacktrace as core::fmt::Display>::fmt::ha8f928866ff7571e
                               at src/libstd/sys_common/backtrace.rs:59
   4:     0x55f6b0a2b75c - core::fmt::write::he0c1e5f7426d2718
                               at src/libcore/fmt/mod.rs:1076
   5:     0x55f6b073d675 - std::io::Write::write_fmt::h1152922039931516
                               at /rustc/04488afe34512aa4c33566eb16d8c912a3ae04f9/src/libstd/io/mod.rs:1537
   6:     0x55f6b09f9891 - std::io::impls::<impl std::io::Write for alloc::boxed::Box<W>>::write_fmt::ha927d7e5f294bce5
                               at src/libstd/io/impls.rs:176
   7:     0x55f6b0a03e60 - std::sys_common::backtrace::_print::hfc0110703f3696fd
                               at src/libstd/sys_common/backtrace.rs:62
   8:     0x55f6b0a03e60 - std::sys_common::backtrace::print::h3f77c6990ddfaa22
                               at src/libstd/sys_common/backtrace.rs:49
   9:     0x55f6b0a03e60 - std::panicking::default_hook::{{closure}}::heae49580a8d62d75
                               at src/libstd/panicking.rs:198
  10:     0x55f6b0a03b5a - std::panicking::default_hook::hecc34e3f729e213c
                               at src/libstd/panicking.rs:214
  11:     0x55f6b0a044a3 - std::panicking::rust_panic_with_hook::he82f5d0644692441
                               at src/libstd/panicking.rs:526
  12:     0x55f6b0a0409b - rust_begin_unwind
                               at src/libstd/panicking.rs:437
  13:     0x55f6b0a296c1 - core::panicking::panic_fmt::h09c929f06bb87c98
                               at src/libcore/panicking.rs:85
  14:     0x55f6b0a294e3 - core::option::expect_none_failed::h188f17af6c9f404b
                               at src/libcore/option.rs:1269
  15:     0x55f6b00dbbcc - core::result::Result<T,E>::unwrap::h0d451077fbe85e9f
                               at /home/pimeys/.rustup/toolchains/stable-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/src/libcore/result.rs:1005
  16:     0x55f6b053bb63 - tiberius::client::connection::Connection<S>::tls_handshake::{{closure}}::h683d4d491de77824
                               at /home/pimeys/code/tiberius/src/client/connection.rs:384
  17:     0x55f6b02a6072 - <core::future::from_generator::GenFuture<T> as core::future::future::Future>::poll::hf56e4ae22867706d
                               at /home/pimeys/.rustup/toolchains/stable-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/src/libcore/future/mod.rs:78
  18:     0x55f6b0562bc9 - tiberius::client::connection::Connection<S>::connect::{{closure}}::hc5b1351ccc0c3fa2
                               at /home/pimeys/code/tiberius/src/client/connection.rs:84
  19:     0x55f6b02847d2 - <core::future::from_generator::GenFuture<T> as core::future::future::Future>::poll::h1935640bb1256dc9
                               at /home/pimeys/.rustup/toolchains/stable-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/src/libcore/future/mod.rs:78
  20:     0x55f6b033b757 - tiberius::client::Client<S>::connect::{{closure}}::h4f4a431e44ae57ad
                               at /home/pimeys/code/tiberius/src/client.rs:63
  21:     0x55f6b028e432 - <core::future::from_generator::GenFuture<T> as core::future::future::Future>::poll::h59693abadb793728
                               at /home/pimeys/.rustup/toolchains/stable-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/src/libcore/future/mod.rs:78
  22:     0x55f6b03bede2 - query::transactions_async_std::{{closure}}::hc7d85b6e3f838d65
                               at tests/query.rs:50
  23:     0x55f6b0285312 - <core::future::from_generator::GenFuture<T> as core::future::future::Future>::poll::h1c531d3b875327d1
                               at /home/pimeys/.rustup/toolchains/stable-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/src/libcore/future/mod.rs:78
  24:     0x55f6b018c94e - <async_std::task::builder::SupportTaskLocals<F> as core::future::future::Future>::poll::{{closure}}::h865bd302a785556b
                               at /home/pimeys/.cargo/registry/src/github.com-1ecc6299db9ec823/async-std-1.6.5/src/task/builder.rs:199
  25:     0x55f6b01e82c7 - async_std::task::task_locals_wrapper::TaskLocalsWrapper::set_current::{{closure}}::ha6f4bab892b612bd
                               at /home/pimeys/.cargo/registry/src/github.com-1ecc6299db9ec823/async-std-1.6.5/src/task/task_locals_wrapper.rs:60
  26:     0x55f6b00c3781 - std::thread::local::LocalKey<T>::try_with::hb661b4d0c7a4f06d
                               at /home/pimeys/.rustup/toolchains/stable-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/src/libstd/thread/local.rs:263
  27:     0x55f6b007d19e - std::thread::local::LocalKey<T>::with::h0c21588fbe2ca350
                               at /home/pimeys/.rustup/toolchains/stable-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/src/libstd/thread/local.rs:239
  28:     0x55f6b01dffef - async_std::task::task_locals_wrapper::TaskLocalsWrapper::set_current::h16226ade7ae65d25
                               at /home/pimeys/.cargo/registry/src/github.com-1ecc6299db9ec823/async-std-1.6.5/src/task/task_locals_wrapper.rs:55
  29:     0x55f6b018b28b - <async_std::task::builder::SupportTaskLocals<F> as core::future::future::Future>::poll::h7cd9e5be02a3bc58
                               at /home/pimeys/.cargo/registry/src/github.com-1ecc6299db9ec823/async-std-1.6.5/src/task/builder.rs:197
  30:     0x55f6b03b140f - <futures_lite::future::Or<F1,F2> as core::future::future::Future>::poll::h0bd82c5f22cb39ad
                               at /home/pimeys/.cargo/registry/src/github.com-1ecc6299db9ec823/futures-lite-1.8.0/src/future.rs:528
  31:     0x55f6b02e8ac8 - async_executor::Executor::run::{{closure}}::hf7027d9be0e1c9d8
                               at /home/pimeys/.cargo/registry/src/github.com-1ecc6299db9ec823/async-executor-1.3.0/src/lib.rs:214
  32:     0x55f6b0294bb2 - <core::future::from_generator::GenFuture<T> as core::future::future::Future>::poll::h7f4740670e789cad
                               at /home/pimeys/.rustup/toolchains/stable-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/src/libcore/future/mod.rs:78
  33:     0x55f6b02c9e8d - async_executor::LocalExecutor::run::{{closure}}::h3a163a88dc05d212
                               at /home/pimeys/.cargo/registry/src/github.com-1ecc6299db9ec823/async-executor-1.3.0/src/lib.rs:393
  34:     0x55f6b028a0b2 - <core::future::from_generator::GenFuture<T> as core::future::future::Future>::poll::h39ca6bd8d2b323b3
                               at /home/pimeys/.rustup/toolchains/stable-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/src/libcore/future/mod.rs:78
  35:     0x55f6b0215a95 - async_io::driver::block_on::h517fd1baac558c2d
                               at /home/pimeys/.cargo/registry/src/github.com-1ecc6299db9ec823/async-io-1.1.4/src/driver.rs:142
  36:     0x55f6b039a373 - async_global_executor::reactor::block_on::ha8fa1557f5aca4b1
                               at /home/pimeys/.cargo/registry/src/github.com-1ecc6299db9ec823/async-global-executor-1.3.0/src/lib.rs:53
  37:     0x55f6b02fa439 - async_global_executor::block_on::{{closure}}::ha076dcfa8bc56aa5
                               at /home/pimeys/.cargo/registry/src/github.com-1ecc6299db9ec823/async-global-executor-1.3.0/src/lib.rs:179
  38:     0x55f6b00c6d45 - std::thread::local::LocalKey<T>::try_with::hc575102fb44c4620
                               at /home/pimeys/.rustup/toolchains/stable-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/src/libstd/thread/local.rs:263
  39:     0x55f6b0091845 - std::thread::local::LocalKey<T>::with::headb35e05fa41fab
                               at /home/pimeys/.rustup/toolchains/stable-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/src/libstd/thread/local.rs:239
  40:     0x55f6b02f7ee0 - async_global_executor::block_on::h13eb69a060da3402
                               at /home/pimeys/.cargo/registry/src/github.com-1ecc6299db9ec823/async-global-executor-1.3.0/src/lib.rs:179
  41:     0x55f6b01ab8ab - async_std::task::builder::Builder::blocking::{{closure}}::{{closure}}::h8ce56e42b4a651ce
                               at /home/pimeys/.cargo/registry/src/github.com-1ecc6299db9ec823/async-std-1.6.5/src/task/builder.rs:171
  42:     0x55f6b01e6f9a - async_std::task::task_locals_wrapper::TaskLocalsWrapper::set_current::{{closure}}::h7e827a3b9f989c97
                               at /home/pimeys/.cargo/registry/src/github.com-1ecc6299db9ec823/async-std-1.6.5/src/task/task_locals_wrapper.rs:60
  43:     0x55f6b009cea1 - std::thread::local::LocalKey<T>::try_with::h2b7cd734ad2bfc51
                               at /home/pimeys/.rustup/toolchains/stable-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/src/libstd/thread/local.rs:263
  44:     0x55f6b007e8c5 - std::thread::local::LocalKey<T>::with::h1b5335748a459c1e
                               at /home/pimeys/.rustup/toolchains/stable-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/src/libstd/thread/local.rs:239
  45:     0x55f6b01e0cb5 - async_std::task::task_locals_wrapper::TaskLocalsWrapper::set_current::h52e3c6d593cdc45f
                               at /home/pimeys/.cargo/registry/src/github.com-1ecc6299db9ec823/async-std-1.6.5/src/task/task_locals_wrapper.rs:55
  46:     0x55f6b01a8467 - async_std::task::builder::Builder::blocking::{{closure}}::hefc8a66421fbf332
                               at /home/pimeys/.cargo/registry/src/github.com-1ecc6299db9ec823/async-std-1.6.5/src/task/builder.rs:168
  47:     0x55f6b00d69cd - std::thread::local::LocalKey<T>::try_with::hfe7cb36aa29f4083
                               at /home/pimeys/.rustup/toolchains/stable-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/src/libstd/thread/local.rs:263
  48:     0x55f6b0086eb5 - std::thread::local::LocalKey<T>::with::h6fb1471021bc304a
                               at /home/pimeys/.rustup/toolchains/stable-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/src/libstd/thread/local.rs:239
  49:     0x55f6b019b72c - async_std::task::builder::Builder::blocking::h6b201419829dfbb8
                               at /home/pimeys/.cargo/registry/src/github.com-1ecc6299db9ec823/async-std-1.6.5/src/task/builder.rs:161
  50:     0x55f6b0201b27 - async_std::task::block_on::block_on::h17621ea76d951fe8
                               at /home/pimeys/.cargo/registry/src/github.com-1ecc6299db9ec823/async-std-1.6.5/src/task/block_on.rs:33
  51:     0x55f6b03283c2 - query::transactions_async_std::h891bf3802642b022
                               at tests/query.rs:50
  52:     0x55f6b03be5a1 - query::transactions_async_std::{{closure}}::h17ead2905b73b6af
                               at tests/query.rs:50
  53:     0x55f6b04e0e7e - core::ops::function::FnOnce::call_once::he8d8373c6c2f303b
                               at /home/pimeys/.rustup/toolchains/stable-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/src/libcore/ops/function.rs:233
  54:     0x55f6b0764bec - <alloc::boxed::Box<F> as core::ops::function::FnOnce<A>>::call_once::h6633cb15d0d76942
                               at /rustc/04488afe34512aa4c33566eb16d8c912a3ae04f9/src/liballoc/boxed.rs:1081
  55:     0x55f6b0764bec - <std::panic::AssertUnwindSafe<F> as core::ops::function::FnOnce<()>>::call_once::h1e20120def172c5c
                               at /rustc/04488afe34512aa4c33566eb16d8c912a3ae04f9/src/libstd/panic.rs:318
  56:     0x55f6b0764bec - std::panicking::try::do_call::hcc2ec3bbb75e9316
                               at /rustc/04488afe34512aa4c33566eb16d8c912a3ae04f9/src/libstd/panicking.rs:348
  57:     0x55f6b0764bec - std::panicking::try::h94eaebaaa7dd6f41
                               at /rustc/04488afe34512aa4c33566eb16d8c912a3ae04f9/src/libstd/panicking.rs:325
  58:     0x55f6b0764bec - std::panic::catch_unwind::h151c07c08497cf8b
                               at /rustc/04488afe34512aa4c33566eb16d8c912a3ae04f9/src/libstd/panic.rs:394
  59:     0x55f6b0764bec - test::run_test_in_process::hd082de93b1922c89
                               at src/libtest/lib.rs:541
  60:     0x55f6b0764bec - test::run_test::run_test_inner::{{closure}}::h22369c9424e5ab3a
                               at src/libtest/lib.rs:450
  61:     0x55f6b073cb66 - std::sys_common::backtrace::__rust_begin_short_backtrace::h0660a89f67243e05
                               at /rustc/04488afe34512aa4c33566eb16d8c912a3ae04f9/src/libstd/sys_common/backtrace.rs:130
  62:     0x55f6b0741c15 - std::thread::Builder::spawn_unchecked::{{closure}}::{{closure}}::h8bb2049509aa1add
                               at /rustc/04488afe34512aa4c33566eb16d8c912a3ae04f9/src/libstd/thread/mod.rs:475
  63:     0x55f6b0741c15 - <std::panic::AssertUnwindSafe<F> as core::ops::function::FnOnce<()>>::call_once::hb49f3484cb9c3dd3
                               at /rustc/04488afe34512aa4c33566eb16d8c912a3ae04f9/src/libstd/panic.rs:318
  64:     0x55f6b0741c15 - std::panicking::try::do_call::ha910a12d1577339b
                               at /rustc/04488afe34512aa4c33566eb16d8c912a3ae04f9/src/libstd/panicking.rs:348
  65:     0x55f6b0741c15 - std::panicking::try::hd8b3d620360e55fa
                               at /rustc/04488afe34512aa4c33566eb16d8c912a3ae04f9/src/libstd/panicking.rs:325
  66:     0x55f6b0741c15 - std::panic::catch_unwind::h475454730ea43154
                               at /rustc/04488afe34512aa4c33566eb16d8c912a3ae04f9/src/libstd/panic.rs:394
  67:     0x55f6b0741c15 - std::thread::Builder::spawn_unchecked::{{closure}}::h2407d9379d805151
                               at /rustc/04488afe34512aa4c33566eb16d8c912a3ae04f9/src/libstd/thread/mod.rs:474
  68:     0x55f6b0741c15 - core::ops::function::FnOnce::call_once{{vtable.shim}}::haef9f772dfab225e
                               at /rustc/04488afe34512aa4c33566eb16d8c912a3ae04f9/src/libcore/ops/function.rs:233
  69:     0x55f6b0a0b1aa - <alloc::boxed::Box<F> as core::ops::function::FnOnce<A>>::call_once::hd2b3bc04af94a84f
                               at /rustc/04488afe34512aa4c33566eb16d8c912a3ae04f9/src/liballoc/boxed.rs:1081
  70:     0x55f6b0a0b1aa - <alloc::boxed::Box<F> as core::ops::function::FnOnce<A>>::call_once::h1044417e186e567a
                               at /rustc/04488afe34512aa4c33566eb16d8c912a3ae04f9/src/liballoc/boxed.rs:1081
  71:     0x55f6b0a0b1aa - std::sys::unix::thread::Thread::new::thread_start::h276e6ca033938925
                               at src/libstd/sys/unix/thread.rs:87
  72:     0x7fd8698f3609 - start_thread
                               at /build/glibc-ZN95T4/glibc-2.31/nptl/pthread_create.c:477
  73:     0x7fd8697fd293 - __clone
  74:                0x0 - <unknown>
@ghost
Copy link

ghost commented Sep 29, 2020

How can I run tests on my own? I tried running tiberius tests but got errors like:

---- read_nullable_i64_async_std stdout ----
Error: Io { kind: ConnectionRefused, message: "Connection refused (os error 61)" }
thread 'read_nullable_i64_async_std' panicked at 'assertion failed: `(left == right)`
  left: `1`,
 right: `0`: the test returned a termination value with a non-zero status code (1) which indicates a failure', /Users/stjepan/.rustup/toolchains/nightly-x86_64-apple-darwin/lib/rustlib/src/rust/library/test/src/lib.rs:191:5

@pimeys
Copy link
Author

pimeys commented Sep 29, 2020 •
edited
Loading

docker-compose.yml

version: "3"
services:
  mssql-2019:
    image: mcr.microsoft.com/mssql/server:2019-latest
    restart: always
    environment:
      ACCEPT_EULA: Y
      SA_PASSWORD: "<YourStrong@Passw0rd>"
    ports:
      - "1433:1433"
    networks:
      - databases

networks:
  databases:
> docker-compose up
> export TIBERIUS_TEST_CONNECTION_STRING="server=tcp:localhost,1433;user=SA;password=<YourStrong@Passw0rd>;TrustServerCertificate=true"
> cargo test --all-features

You can change async-std version from 1.6.3 to 1.6.4 to see some tests randomly failing to the WouldBlock.

@ghost
Copy link

ghost commented Sep 29, 2020 •
edited by ghost
Loading

When I run docker-compose up, the command hangs at this point:

2020-09-29 13:54:58.34 spid12s     [2]. Feature Status: PVS: 0. CTR: 0. ConcurrentPFSUpdate: 1.
2020-09-29 13:54:58.35 spid12s     Starting up database 'tempdb'.
2020-09-29 13:54:58.59 spid12s     The tempdb database has 1 data file(s).
2020-09-29 13:54:58.61 spid31s     The Service Broker endpoint is in disabled or stopped state.
2020-09-29 13:54:58.62 spid31s     The Database Mirroring endpoint is in disabled or stopped state.
2020-09-29 13:54:58.64 spid31s     Service Broker manager has started.
2020-09-29 13:54:58.66 spid9s      Database 'msdb' running the upgrade step from version 902 to version 903.
2020-09-29 13:54:58.67 spid9s      Database 'msdb' running the upgrade step from version 903 to version 904.
2020-09-29 13:54:58.82 spid9s      Recovery is complete. This is an informational message only. No user action is required.
2020-09-29 13:54:58.86 spid27s     The default language (LCID 0) has been set for engine and full-text services.
2020-09-29 13:55:00.45 spid27s     The tempdb database has 4 data file(s).

Is this normal? Do I just need to wait for a while for docker-compose up to finish?

Also, if I run cargo test --all-features at this point all query tests (with both tokio and async-std) seem to hang forever.

I'm using macos if that's relevant.

@pimeys
Copy link
Author

pimeys commented Sep 29, 2020

Ah, yeah, the TLS certificate in the docker image will not work together with macOS Catalina. Damn, it's Linux/Windows only :(

@pimeys
Copy link
Author

pimeys commented Sep 29, 2020

And, if you run docker-compose up -d, it'll run it as a daemon. Otherwise it'll just block the current session. The problem here is that the docker image has too small certificate and Apple doesn't allow them anymore when using native-tls.

@yoshuawuyts yoshuawuyts mentioned this issue Sep 29, 2020
Closed
@tailhook
Copy link

We have the same issue with code that is basically surf::get(...).await?.body_bytes().await?. But I can't it reproduce on simple example. It often happens when we run test suite using docker that involves starting and stopping containers (which often slows down and interrupts network requests in other containers). So I can't cut this down to a simple example, but this may give you more context.

@ghost
Copy link

ghost commented Sep 29, 2020

Thanks for the help! This should be fixed in the latest release now, but let me know if you run into any issues.

The problem was in that random yielding inside AsyncRead/AsyncWrite (which is supposed to prevent task starvation when I/O never returns the WouldBlock error) doesn't play nice with the TLS protocol. It seems that TLS handshake fails if a write errors with WouldBlock.

@ghost ghost closed this as completed Sep 29, 2020
@ghost
Copy link

ghost commented Sep 29, 2020

@tailhook Can you do cargo update and try again?

@pimeys
Copy link
Author

pimeys commented Sep 29, 2020

Fixed in Tiberius too, no more errors bubbling up. Thank you @stjepang.

@tailhook
Copy link

tailhook commented Sep 29, 2020 •
edited
Loading

Got failed to lookup address information: Try again which is probably the actual error that was happening. Thanks for a quick fix!

notgull added a commit that referenced this issue May 6, 2023
@notgull
Gracefully handle the inability to spawn threads, take 2 (#31)
dbdef7e 
* Gracefully handle the inability to spawn threads

* Ensure the thread limit is never zero
This issue was closed.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@pimeys @tailhook