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

Spawned task is stuck during flushing in File.drop() #900

Open
link2xt opened this issue Oct 22, 2020 · 18 comments · May be fixed by #1033
Open

Spawned task is stuck during flushing in File.drop() #900

link2xt opened this issue Oct 22, 2020 · 18 comments · May be fixed by #1033

Comments

@link2xt
Copy link

link2xt commented Oct 22, 2020

Original issue is deltachat/deltachat-core-rust#2032

I have prepared a minimal example demonstrating the bug, which depends only on async-std 1.6.5.

An example which you can unpack and run with cargo run: filedrop.tar.gz

The source code for reference:

use async_std::prelude::*;
async fn create_file() {
    let mut file = async_std::fs::OpenOptions::new()
        .create(true)
        .write(true)
        .open("foo.txt")
        .await
        .unwrap();
    file.write_all(b"foobarbaz").await.unwrap();
    //file.flush().await.unwrap();
    eprintln!("before drop");
}

async fn test() {
    let tsk = async_std::task::spawn(async move {
        create_file().await;
        eprintln!("after drop");
    });
    tsk.await;
}

fn main() {
    async_std::task::block_on(test());
}

I built this example in the following configuration:

  1. Debian sid as a host machine.
  2. NetBSD 9.1 as a guest, installed in qemu (kvm)
  3. Rust 1.47.0 installed on NetBSD via rustup.

When I execute cargo run, the program prints before drop and gets stuck. Apparently the problem is that despite what comment says, executor does not handle blocking operation in Drop correctly:

async-std/src/fs/file.rs

Line 314 in 11196c8

// We need to flush the file on drop. Unfortunately, that is not possible to do in a

After waiting a minute and terminating the program, the file foo.txt is created, but is empty.

When I uncomment the line file.flush().await.unwrap();, the program prints

before drop
after drop

and exits.

On my Linux machine this works correctly. It is not a QEMU bug, as the same problem is experienced on some Android phones, see original issue deltachat/deltachat-core-rust#2032
@link2xt
Copy link
Author

link2xt commented Oct 22, 2020 •
edited
Loading

Collected the backtraces of the stuck process:

localhost$ gdb -p 1305
GNU gdb (GDB) 8.3
Copyright (C) 2019 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law.
Type "show copying" and "show warranty" for details.
This GDB was configured as "x86_64--netbsd".
Type "show configuration" for configuration details.
For bug reporting instructions, please see:
<http://www.gnu.org/software/gdb/bugs/>.
Find the GDB manual and other documentation resources online at:
    <http://www.gnu.org/software/gdb/documentation/>.

For help, type "help".
Type "apropos word" to search for commands related to "word".
Attaching to process 1305
Reading symbols from /home/user/filedrop/target/debug/./filedrop...
[New LWP 2 of process 1305]
[New LWP 1 of process 1305]
Reading symbols from /usr/lib/libpthread.so.1...
(No debugging symbols found in /usr/lib/libpthread.so.1)
Reading symbols from /usr/lib/libgcc_s.so.1...
(No debugging symbols found in /usr/lib/libgcc_s.so.1)
Reading symbols from /usr/lib/libc.so.12...
(No debugging symbols found in /usr/lib/libc.so.12)
Reading symbols from /usr/libexec/ld.elf_so...
(No debugging symbols found in /usr/libexec/ld.elf_so)
[Switching to LWP 3 of process 1305]
0x00006fc97cea1faa in ___lwp_park60 () from /usr/lib/libc.so.12
warning: Unsupported auto-load script at offset 0 in section .debug_gdb_scripts
of file /home/user/filedrop/target/debug/filedrop.
Use `info auto-load python-scripts [REGEXP]' to list them.
(gdb) info threads
  Id   Target Id                               Frame 
* 1    LWP 3 of process 1305 "async-io"        0x00006fc97cea1faa in ___lwp_park60 () from /usr/lib/libc.so.12
  2    LWP 2 of process 1305 "async-std/runti" 0x00006fc97cea1faa in ___lwp_park60 () from /usr/lib/libc.so.12
  3    LWP 1 of process 1305 ""                0x00006fc97ce42b8a in _sys___kevent50 () from /usr/lib/libc.so.12
(gdb) bt
#0  0x00006fc97cea1faa in ___lwp_park60 () from /usr/lib/libc.so.12
#1  0x00006fc97d8095a6 in ?? () from /usr/lib/libpthread.so.1
#2  0x000000015c0a86ed in std::sys::unix::mutex::Mutex::lock (
    self=0x6fc97db1b3c0)
    at /rustc/18bf6b4f01a6feaf7259ba7cdae58031af1b7b39/library/std/src/sys/unix/mutex.rs:63
#3  0x000000015c0a7f1a in std::sys_common::mutex::Mutex::raw_lock (
    self=0x6fc97db1b3c0)
    at /rustc/18bf6b4f01a6feaf7259ba7cdae58031af1b7b39/library/std/src/sys_common/mutex.rs:42
#4  0x000000015c09dca6 in std::sync::mutex::Mutex<T>::lock (
    self=0x15c37d1b0 <async_io::reactor::Reactor::get::REACTOR+128>)
    at /rustc/18bf6b4f01a6feaf7259ba7cdae58031af1b7b39/library/std/src/sync/mutex.rs:269
#5  0x000000015c099c2b in async_io::reactor::Reactor::lock (
    self=0x15c37d138 <async_io::reactor::Reactor::get::REACTOR+8>)
    at /home/user/.cargo/registry/src/github.com-1ecc6299db9ec823/async-io-1.1.10/src/reactor.rs:163
#6  0x000000015c0b26f3 in async_io::driver::main_loop (parker=...)
    at /home/user/.cargo/registry/src/github.com-1ecc6299db9ec823/async-io-1.1.10/src/driver.rs:54
#7  0x000000015c0b240a in async_io::driver::UNPARKER::{{closure}}::{{closure}}
    ()
    at /home/user/.cargo/registry/src/github.com-1ecc6299db9ec823/async-io-1.1.10/src/driver.rs:29
#8  0x000000015c0a85ee in std::sys_common::backtrace::__rust_begin_short_backtrace (f=...)
    at /rustc/18bf6b4f01a6feaf7259ba7cdae58031af1b7b39/library/std/src/sys_common/backtrace.rs:137
#9  0x000000015c0aeb2b in std::thread::Builder::spawn_unchecked::{{closure}}::{{closure}} ()
    at /rustc/18bf6b4f01a6feaf7259ba7cdae58031af1b7b39/library/std/src/thread/mod.rs:458
#10 0x000000015c0ae18f in <std::panic::AssertUnwindSafe<F> as core::ops::function::FnOnce<()>>::call_once (self=..., _args=())
    at /rustc/18bf6b4f01a6feaf7259ba7cdae58031af1b7b39/library/std/src/panic.rs:308
#11 0x000000015c09c1cc in std::panicking::try::do_call (
    data=0x6fc97c5efe30 <error reading variable>)
    at /rustc/18bf6b4f01a6feaf7259ba7cdae58031af1b7b39/library/std/src/panicking.rs:373
#12 0x000000015c09d6ad in __rust_try ()
#13 0x000000015c09c137 in std::panicking::try (f=...)
    at /rustc/18bf6b4f01a6feaf7259ba7cdae58031af1b7b39/library/std/src/panicking.rs:337
#14 0x000000015c0ae23f in std::panic::catch_unwind (f=...)
    at /rustc/18bf6b4f01a6feaf7259ba7cdae58031af1b7b39/library/std/src/panic.rs:379
#15 0x000000015c0ae942 in std::thread::Builder::spawn_unchecked::{{closure}} ()
    at /rustc/18bf6b4f01a6feaf7259ba7cdae58031af1b7b39/library/std/src/thread/mod.rs:457
#16 0x000000015c0a262f in core::ops::function::FnOnce::call_once{{vtable-shim}}
    ()
    at /rustc/18bf6b4f01a6feaf7259ba7cdae58031af1b7b39/library/core/src/ops/function.rs:227
#17 0x000000015c10408a in <alloc::boxed::Box<F> as core::ops::function::FnOnce<A>>::call_once ()
    at /rustc/18bf6b4f01a6feaf7259ba7cdae58031af1b7b39/library/alloc/src/boxed.rs:1042
#18 <alloc::boxed::Box<F> as core::ops::function::FnOnce<A>>::call_once ()
    at /rustc/18bf6b4f01a6feaf7259ba7cdae58031af1b7b39/library/alloc/src/boxed.rs:1042
#19 std::sys::unix::thread::Thread::new::thread_start ()
    at library/std/src/sys/unix/thread.rs:87
#20 0x00006fc97d80c072 in ?? () from /usr/lib/libpthread.so.1
#21 0x00006fc97ce87bb0 in ?? () from /usr/lib/libc.so.12
#22 0x0000000000000000 in ?? ()
(gdb) thread 2
[Switching to thread 2 (LWP 2 of process 1305)]
#0  0x00006fc97cea1faa in ___lwp_park60 () from /usr/lib/libc.so.12
(gdb) bt 
#0  0x00006fc97cea1faa in ___lwp_park60 () from /usr/lib/libc.so.12
#1  0x00006fc97d80a71f in pthread_cond_timedwait ()
   from /usr/lib/libpthread.so.1
#2  0x000000015c0e278d in std::sys::unix::condvar::Condvar::wait (
    self=0x6fc97db1c5c0, mutex=0x6fc97db1c590)
    at /rustc/18bf6b4f01a6feaf7259ba7cdae58031af1b7b39/library/std/src/sys/unix/condvar.rs:69
#3  0x000000015c0e0450 in std::sys_common::condvar::Condvar::wait (
    self=0x6fc97db1c5c0, mutex=0x6fc97db1c590)
    at /rustc/18bf6b4f01a6feaf7259ba7cdae58031af1b7b39/library/std/src/sys_common/condvar.rs:50
#4  0x000000015c0e1c54 in std::sync::condvar::Condvar::wait (
    self=0x6fc97dac60e8, guard=...)
    at /rustc/18bf6b4f01a6feaf7259ba7cdae58031af1b7b39/library/std/src/sync/condvar.rs:199
#5  0x000000015c0df1ca in parking::Inner::park (self=0x6fc97dac60d0, 
    timeout=...)
    at /home/user/.cargo/registry/src/github.com-1ecc6299db9ec823/parking-2.0.0/src/lib.rs:305
#6  0x000000015c0de9ea in parking::Parker::park (self=0x6fc97db1c570)
    at /home/user/.cargo/registry/src/github.com-1ecc6299db9ec823/parking-2.0.0/src/lib.rs:103
#7  0x000000015c047bd7 in futures_lite::future::block_on::{{closure}} (
    cache=0x6fc97db1c568)
    at /home/user/.cargo/registry/src/github.com-1ecc6299db9ec823/futures-lite-1.11.2/src/future.rs:91
#8  0x000000015c04d234 in std::thread::local::LocalKey<T>::try_with (
    self=0x15c3710f8, f=...)
    at /rustc/18bf6b4f01a6feaf7259ba7cdae58031af1b7b39/library/std/src/thread/local.rs:265
#9  0x000000015c04cd09 in std::thread::local::LocalKey<T>::with (
    self=0x15c3710f8, f=...)
    at /rustc/18bf6b4f01a6feaf7259ba7cdae58031af1b7b39/library/std/src/thread/local.rs:241
#10 0x000000015c047a30 in futures_lite::future::block_on (future=...)
    at /home/user/.cargo/registry/src/github.com-1ecc6299db9ec823/futures-lite-1.11.2/src/future.rs:79
#11 0x000000015c056554 in <async_std::fs::file::File as core::ops::drop::Drop>::drop (self=0x6fc97dafa298)
    at /home/user/.cargo/registry/src/github.com-1ecc6299db9ec823/async-std-1.6.5/src/fs/file.rs:318
#12 0x000000015c04d7c6 in core::ptr::drop_in_place ()
    at /rustc/18bf6b4f01a6feaf7259ba7cdae58031af1b7b39/library/core/src/ptr/mod.rs:184
#13 0x000000015c01dc4d in filedrop::create_file::{{closure}} ()
    at src/main.rs:12
#14 0x000000015c021559 in <core::future::from_generator::GenFuture<T> as core::future::future::Future>::poll (self=..., cx=0x6fc97c7fe2d0)
    at /rustc/18bf6b4f01a6feaf7259ba7cdae58031af1b7b39/library/core/src/future/mod.rs:79
#15 0x000000015c01dee8 in filedrop::test::{{closure}}::{{closure}} ()
    at src/main.rs:16
#16 0x000000015c0214c9 in <core::future::from_generator::GenFuture<T> as core::future::future::Future>::poll (self=..., cx=0x6fc97c7fe2d0)
    at /rustc/18bf6b4f01a6feaf7259ba7cdae58031af1b7b39/library/core/src/future/mod.rs:79
#17 0x000000015c0220c9 in <async_std::task::builder::SupportTaskLocals<F> as core::future::future::Future>::poll::{{closure}} ()
    at /home/user/.cargo/registry/src/github.com-1ecc6299db9ec823/async-std-1.6.5/src/task/builder.rs:199
#18 0x000000015c0208f3 in async_std::task::task_locals_wrapper::TaskLocalsWrapper::set_current::{{closure}} (current=0x6fc97db19d48)
    at /home/user/.cargo/registry/src/github.com-1ecc6299db9ec823/async-std-1.6.5/src/task/task_locals_wrapper.rs:60
#19 0x000000015c023fa1 in std::thread::local::LocalKey<T>::try_with (
    self=0x15c370718, f=...)
    at /rustc/18bf6b4f01a6feaf7259ba7cdae58031af1b7b39/library/std/src/thread/local.rs:265
#20 0x000000015c023dbd in std::thread::local::LocalKey<T>::with (
    self=0x15c370718, f=...)
    at /rustc/18bf6b4f01a6feaf7259ba7cdae58031af1b7b39/library/std/src/thread/local.rs:241
#21 0x000000015c020638 in async_std::task::task_locals_wrapper::TaskLocalsWrapper::set_current (task=0x6fc97dafa258, f=...)
    at /home/user/.cargo/registry/src/github.com-1ecc6299db9ec823/async-std-1.6.5/src/task/task_locals_wrapper.rs:55
#22 0x000000015c022028 in <async_std::task::builder::SupportTaskLocals<F> as core::future::future::Future>::poll (self=..., cx=0x6fc97c7fe2d0)
    at /home/user/.cargo/registry/src/github.com-1ecc6299db9ec823/async-std-1.6.5/src/task/builder.rs:197
#23 0x000000015c028f45 in async_executor::Executor::spawn::{{closure}} ()
    at /home/user/.cargo/registry/src/github.com-1ecc6299db9ec823/async-executor-1.3.0/src/lib.rs:116
#24 0x000000015c021949 in <core::future::from_generator::GenFuture<T> as core::future::future::Future>::poll (self=..., cx=0x6fc97c7fe2d0)
    at /rustc/18bf6b4f01a6feaf7259ba7cdae58031af1b7b39/library/core/src/future/mod.rs:79
#25 0x000000015c033c8d in async_task::raw::RawTask<F,T,S>::run (
    ptr=0x6fc97dafa180)
    at /home/user/.cargo/registry/src/github.com-1ecc6299db9ec823/async-task-4.0.3/src/raw.rs:489
#26 0x000000015c097ed6 in async_task::runnable::Runnable::run (self=...)
    at /home/user/.cargo/registry/src/github.com-1ecc6299db9ec823/async-task-4.0.3/src/runnable.rs:309
#27 0x000000015c0823c2 in async_executor::Executor::run::{{closure}}::{{closure}} ()
    at /home/user/.cargo/registry/src/github.com-1ecc6299db9ec823/async-executor-1.3.0/src/lib.rs:207
#28 0x000000015c0763ab in <core::future::from_generator::GenFuture<T> as core::future::future::Future>::poll (self=..., cx=0x6fc97c7fed10)
    at /rustc/18bf6b4f01a6feaf7259ba7cdae58031af1b7b39/library/core/src/future/mod.rs:79
#29 0x000000015c07a37d in <futures_lite::future::Or<F1,F2> as core::future::future::Future>::poll (self=..., cx=0x6fc97c7fed10)
    at /home/user/.cargo/registry/src/github.com-1ecc6299db9ec823/futures-lite-1.11.2/src/future.rs:529
#30 0x000000015c081fa4 in async_executor::Executor::run::{{closure}} ()
    at /home/user/.cargo/registry/src/github.com-1ecc6299db9ec823/async-executor-1.3.0/src/lib.rs:214
#31 0x000000015c07656b in <core::future::from_generator::GenFuture<T> as core::future::future::Future>::poll (self=..., cx=0x6fc97c7fed10)
    at /rustc/18bf6b4f01a6feaf7259ba7cdae58031af1b7b39/library/core/src/future/mod.rs:79
#32 0x000000015c07a2cd in <futures_lite::future::Or<F1,F2> as core::future::future::Future>::poll (self=..., cx=0x6fc97c7fed10)
    at /home/user/.cargo/registry/src/github.com-1ecc6299db9ec823/futures-lite-1.11.2/src/future.rs:529
#33 0x000000015c082a7c in async_io::driver::block_on (future=...)
    at /home/user/.cargo/registry/src/github.com-1ecc6299db9ec823/async-io-1.1.10/src/driver.rs:142
#34 0x000000015c07b7f6 in async_global_executor::reactor::block_on::{{closure}}
    ()
    at /home/user/.cargo/registry/src/github.com-1ecc6299db9ec823/async-global-executor-1.4.2/src/lib.rs:48
#35 0x000000015c07b7b0 in async_global_executor::reactor::block_on (future=...)
    at /home/user/.cargo/registry/src/github.com-1ecc6299db9ec823/async-global-executor-1.4.2/src/lib.rs:55
#36 0x000000015c076edc in async_global_executor::init_with_config::{{closure}}::{{closure}}::{{closure}} (executor=0x6fc97db1c2c8)
    at /home/user/.cargo/registry/src/github.com-1ecc6299db9ec823/async-global-executor-1.4.2/src/lib.rs:175
#37 0x000000015c075c1e in std::thread::local::LocalKey<T>::try_with (
    self=0x15c371c18, f=...)
    at /rustc/18bf6b4f01a6feaf7259ba7cdae58031af1b7b39/library/std/src/thread/local.rs:265
#38 0x000000015c07525f in std::thread::local::LocalKey<T>::with (
    self=0x15c371c18, f=...)
    at /rustc/18bf6b4f01a6feaf7259ba7cdae58031af1b7b39/library/std/src/thread/local.rs:241
#39 0x000000015c076f41 in async_global_executor::init_with_config::{{closure}}::{{closure}} ()
    at /home/user/.cargo/registry/src/github.com-1ecc6299db9ec823/async-global-executor-1.4.2/src/lib.rs:172
#40 0x000000015c077a9e in std::panicking::try::do_call (
    data=0x6fc97c7ffc98 <error reading variable>)
    at /rustc/18bf6b4f01a6feaf7259ba7cdae58031af1b7b39/library/std/src/panicking.rs:373
#41 0x000000015c077c4d in __rust_try ()
#42 0x000000015c077a14 in std::panicking::try (f=...)
    at /rustc/18bf6b4f01a6feaf7259ba7cdae58031af1b7b39/library/std/src/panicking.rs:337
#43 0x000000015c07a98a in std::panic::catch_unwind (f=...)
    at /rustc/18bf6b4f01a6feaf7259ba7cdae58031af1b7b39/library/std/src/panic.rs:379
#44 0x000000015c076f5d in async_global_executor::init_with_config::{{closure}}
    ()
    at /home/user/.cargo/registry/src/github.com-1ecc6299db9ec823/async-global-executor-1.4.2/src/lib.rs:171
#45 0x000000015c07f049 in std::sys_common::backtrace::__rust_begin_short_backtrace (f=...)
    at /rustc/18bf6b4f01a6feaf7259ba7cdae58031af1b7b39/library/std/src/sys_common/backtrace.rs:137
#46 0x000000015c077907 in std::thread::Builder::spawn_unchecked::{{closure}}::{{closure}} ()
    at /rustc/18bf6b4f01a6feaf7259ba7cdae58031af1b7b39/library/std/src/thread/mod.rs:458
#47 0x000000015c07a77a in <std::panic::AssertUnwindSafe<F> as core::ops::function::FnOnce<()>>::call_once (self=..., _args=())
    at /rustc/18bf6b4f01a6feaf7259ba7cdae58031af1b7b39/library/std/src/panic.rs:308
#48 0x000000015c077acf in std::panicking::try::do_call (
    data=0x6fc97c7ffe38 <error reading variable>)
    at /rustc/18bf6b4f01a6feaf7259ba7cdae58031af1b7b39/library/std/src/panicking.rs:373
#49 0x000000015c077c4d in __rust_try ()
#50 0x000000015c077984 in std::panicking::try (f=...)
    at /rustc/18bf6b4f01a6feaf7259ba7cdae58031af1b7b39/library/std/src/panicking.rs:337
#51 0x000000015c07a95a in std::panic::catch_unwind (f=...)
    at /rustc/18bf6b4f01a6feaf7259ba7cdae58031af1b7b39/library/std/src/panic.rs:379
#52 0x000000015c07774c in std::thread::Builder::spawn_unchecked::{{closure}} ()
    at /rustc/18bf6b4f01a6feaf7259ba7cdae58031af1b7b39/library/std/src/thread/mod.rs:457
#53 0x000000015c074469 in core::ops::function::FnOnce::call_once{{vtable-shim}}
    ()
    at /rustc/18bf6b4f01a6feaf7259ba7cdae58031af1b7b39/library/core/src/ops/function.rs:227
#54 0x000000015c10408a in <alloc::boxed::Box<F> as core::ops::function::FnOnce<A>>::call_once ()
    at /rustc/18bf6b4f01a6feaf7259ba7cdae58031af1b7b39/library/alloc/src/boxed.rs:1042
#55 <alloc::boxed::Box<F> as core::ops::function::FnOnce<A>>::call_once ()
    at /rustc/18bf6b4f01a6feaf7259ba7cdae58031af1b7b39/library/alloc/src/boxed.rs:1042
#56 std::sys::unix::thread::Thread::new::thread_start ()
    at library/std/src/sys/unix/thread.rs:87
#57 0x00006fc97d80c072 in ?? () from /usr/lib/libpthread.so.1
#58 0x00006fc97ce87bb0 in ?? () from /usr/lib/libc.so.12
#59 0x0000000000400000 in ?? ()
#60 0x00006fc97cc00000 in ?? ()
#61 0x0000001003a0efff in ?? ()
#62 0x00006fc97ca000c0 in ?? ()
#63 0x00000000001fff40 in ?? ()
#64 0x0000000000000000 in ?? ()
(gdb) thread 3
[Switching to thread 3 (LWP 1 of process 1305)]
#0  0x00006fc97ce42b8a in _sys___kevent50 () from /usr/lib/libc.so.12
(gdb) bt
#0  0x00006fc97ce42b8a in _sys___kevent50 () from /usr/lib/libc.so.12
#1  0x00006fc97d807879 in __kevent50 () from /usr/lib/libpthread.so.1
#2  0x000000015c0ca30c in polling::kqueue::Poller::wait (
    self=0x15c37d160 <async_io::reactor::Reactor::get::REACTOR+48>, 
    events=0x15c37d148 <async_io::reactor::Reactor::get::REACTOR+24>, 
    timeout=...)
    at /home/user/.cargo/registry/src/github.com-1ecc6299db9ec823/polling-2.0.2/src/kqueue.rs:144
#3  0x000000015c0d08aa in polling::Poller::wait (
    self=0x15c37d138 <async_io::reactor::Reactor::get::REACTOR+8>, 
    events=0x15c37d1c0 <async_io::reactor::Reactor::get::REACTOR+144>, 
    timeout=...)
    at /home/user/.cargo/registry/src/github.com-1ecc6299db9ec823/polling-2.0.2/src/lib.rs:385
#4  0x000000015c09ac80 in async_io::reactor::ReactorLock::react (
    self=0x7f7fff8ba4a0, timeout=...)
    at /home/user/.cargo/registry/src/github.com-1ecc6299db9ec823/async-io-1.1.10/src/reactor.rs:261
#5  0x000000015c02a7e7 in async_io::driver::block_on (future=...)
    at /home/user/.cargo/registry/src/github.com-1ecc6299db9ec823/async-io-1.1.10/src/driver.rs:188
#6  0x000000015c02c603 in async_global_executor::reactor::block_on::{{closure}}
    ()
    at /home/user/.cargo/registry/src/github.com-1ecc6299db9ec823/async-global-executor-1.4.2/src/lib.rs:48
#7  0x000000015c02c5c0 in async_global_executor::reactor::block_on (future=...)
    at /home/user/.cargo/registry/src/github.com-1ecc6299db9ec823/async-global-executor-1.4.2/src/lib.rs:55
#8  0x000000015c0252ac in async_global_executor::block_on::{{closure}} (
    executor=0x6fc97db1b0f8)
    at /home/user/.cargo/registry/src/github.com-1ecc6299db9ec823/async-global-executor-1.4.2/src/lib.rs:212
#9  0x000000015c024354 in std::thread::local::LocalKey<T>::try_with (
    self=0x15c370878, f=...)
    at /rustc/18bf6b4f01a6feaf7259ba7cdae58031af1b7b39/library/std/src/thread/local.rs:265
#10 0x000000015c023cd7 in std::thread::local::LocalKey<T>::with (
    self=0x15c370878, f=...)
    at /rustc/18bf6b4f01a6feaf7259ba7cdae58031af1b7b39/library/std/src/thread/local.rs:241
#11 0x000000015c025243 in async_global_executor::block_on (future=...)
    at /home/user/.cargo/registry/src/github.com-1ecc6299db9ec823/async-global-executor-1.4.2/src/lib.rs:212
#12 0x000000015c0237fe in async_std::task::builder::Builder::blocking::{{closure--Type <RET> for more, q to quit, c to continue without paging--
}}::{{closure}} ()
    at /home/user/.cargo/registry/src/github.com-1ecc6299db9ec823/async-std-1.6.5/src/task/builder.rs:171
#13 0x000000015c0207d9 in async_std::task::task_locals_wrapper::TaskLocalsWrapper::set_current::{{closure}} (current=0x6fc97db19048)
    at /home/user/.cargo/registry/src/github.com-1ecc6299db9ec823/async-std-1.6.5/src/task/task_locals_wrapper.rs:60
#14 0x000000015c024b00 in std::thread::local::LocalKey<T>::try_with (
    self=0x15c370718, f=...)
    at /rustc/18bf6b4f01a6feaf7259ba7cdae58031af1b7b39/library/std/src/thread/local.rs:265
#15 0x000000015c023a4d in std::thread::local::LocalKey<T>::with (
    self=0x15c370718, f=...)
    at /rustc/18bf6b4f01a6feaf7259ba7cdae58031af1b7b39/library/std/src/thread/local.rs:241
#16 0x000000015c0206ed in async_std::task::task_locals_wrapper::TaskLocalsWrapper::set_current (task=0x7f7fff8bb4f0, f=...)
    at /home/user/.cargo/registry/src/github.com-1ecc6299db9ec823/async-std-1.6.5/src/task/task_locals_wrapper.rs:55
#17 0x000000015c0236fd in async_std::task::builder::Builder::blocking::{{closure}} (num_nested_blocking=0x6fc97db19008)
    at /home/user/.cargo/registry/src/github.com-1ecc6299db9ec823/async-std-1.6.--Type <RET> for more, q to quit, c to continue without paging--
5/src/task/builder.rs:168
#18 0x000000015c02471c in std::thread::local::LocalKey<T>::try_with (
    self=0x15c370808, f=...)
    at /rustc/18bf6b4f01a6feaf7259ba7cdae58031af1b7b39/library/std/src/thread/local.rs:265
#19 0x000000015c023e37 in std::thread::local::LocalKey<T>::with (
    self=0x15c370808, f=...)
    at /rustc/18bf6b4f01a6feaf7259ba7cdae58031af1b7b39/library/std/src/thread/local.rs:241
#20 0x000000015c0235a9 in async_std::task::builder::Builder::blocking (
    self=..., future=...)
    at /home/user/.cargo/registry/src/github.com-1ecc6299db9ec823/async-std-1.6.5/src/task/builder.rs:161
#21 0x000000015c037a26 in async_std::task::block_on::block_on (future=...)
    at /home/user/.cargo/registry/src/github.com-1ecc6299db9ec823/async-std-1.6.5/src/task/block_on.rs:33
#22 0x000000015c021cd8 in filedrop::main () at src/main.rs:23
(gdb) quit
A debugging session is active.

        Inferior 1 [process 1305] will be detached.

Quit anyway? (y or n) y
Detaching from program: /home/user/filedrop/target/debug/filedrop, process 1305
[Inferior 1 (process 1305) detached]

@link2xt
Copy link
Author

link2xt commented Oct 22, 2020

Sidenote: there is a third alternative to dropping unwritten data and flushing it in a blocking way. It's possible to spawn a new task that will do the flushing sometime later. If user did not care to flush the file, it can be postponed.

@r10s r10s mentioned this issue Oct 23, 2020
Merged
@link2xt
Copy link
Author

link2xt commented Oct 23, 2020

Maybe this can be reproduced more reliably and converted into a test? Is it possible to cause File to become unflushed in deterministic way? This is probably caused by slow qemu device built on top of HDD and old android SD card.

@dignifiedquire
Copy link
Member

We likely need to stop flushing automatically in the drop impl, and add to the docs that flushing is required to be manual. This is what tokio::fs::File does, and likely the only way to be sure it works, as long as AsyncDrop is not yet there.

@link2xt
Copy link
Author

link2xt commented Oct 23, 2020

It's possible to remove Drop, but isn't it a workaround? What is the reason for panic in the first thread? What if I implement a File wrapper that does flush in drop, why shouldn't it work?

@link2xt
Copy link
Author

link2xt commented Oct 23, 2020

Here is a way to create unflushed file:

async-std/src/fs/file.rs

Line 411 in 11196c8

File::new(file, false)

I'll try to use it and see what happens.

@link2xt
Copy link
Author

link2xt commented Oct 23, 2020

This code does not fail on Linux:

use async_std::prelude::*;
use std::io::prelude::*;

async fn create_file() {
    let mut file = std::fs::File::create("foo.txt").unwrap();
    file.write_all(b"foobarbaz").unwrap();
    let mut afile: async_std::fs::File = file.into();
    afile.write_all(b"foobarbaz").await.unwrap();
    eprintln!("before drop");
}

async fn test() {
    let tsk = async_std::task::spawn(async move {
        create_file().await;
        eprintln!("after drop");
    });
    tsk.await;
}

fn main() {
    async_std::task::block_on(test());
}

But maybe because write operation never actually blocks.

@link2xt
Copy link
Author

link2xt commented Oct 26, 2020 •
edited
Loading

Reproduced on Alpine linux under qemu, running on top of qcow2 disk backed by HDD. Dumped the core, copied to the host system and loaded it in gdb. On the host system same binary successfully writes the file by the way. So it is reproducible both with kqueue and epoll, on NetBSD and Alpine Linux running in KVM and on real Android.

Stacktraces with epoll, produced on Debian from binary and core file downloaded from Alpine 
(gdb) info threads
  Id   Target Id         Frame 
* 1    LWP 2257          0x00007f2406a40fcd in sccp ()
  2    LWP 2211          0x00007f2406a3cead in epoll_pwait ()
  3    LWP 2256          0x00007f2406a40fcd in sccp ()
(gdb) bt
#0  0x00007f2406a40fcd in sccp ()
#1  0x00007f2406a43b93 in __timedwait_cp ()
#2  0x0000000000000000 in ?? ()
(gdb) thread 3
[Switching to thread 3 (LWP 2256)]
#0  0x00007f2406a40fcd in sccp ()
(gdb) bt
#0  0x00007f2406a40fcd in sccp ()
#1  0x00007f2406a43b93 in __timedwait_cp ()
#2  0x0000000000000000 in ?? ()
(gdb) thread 2
[Switching to thread 2 (LWP 2211)]
#0  0x00007f2406a3cead in epoll_pwait ()
(gdb) bt
#0  0x00007f2406a3cead in epoll_pwait ()
#1  0x0000000000000001 in ?? ()
#2  0x00007f24069e3021 in polling::epoll::Poller::wait (self=0x7f2406ab50d8 <async_io::reactor::Reactor::get::REACTOR+48>, events=0x7f2406ab50c0 <async_io::reactor::Reactor::get::REACTOR+24>, timeout=...)
    at /home/user/.cargo/registry/src/github.com-1ecc6299db9ec823/polling-2.0.2/src/epoll.rs:157
#3  0x00007f24069ea19a in polling::Poller::wait (self=0x7f2406ab50b0 <async_io::reactor::Reactor::get::REACTOR+8>, events=0x7f2406ab5140 <async_io::reactor::Reactor::get::REACTOR+152>, timeout=...)
    at /home/user/.cargo/registry/src/github.com-1ecc6299db9ec823/polling-2.0.2/src/lib.rs:385
#4  0x00007f24069b3550 in async_io::reactor::ReactorLock::react (self=0x7ffe348afac0, timeout=...) at /home/user/.cargo/registry/src/github.com-1ecc6299db9ec823/async-io-1.1.10/src/reactor.rs:261
#5  0x00007f2406926f77 in async_io::driver::block_on (future=...) at /home/user/.cargo/registry/src/github.com-1ecc6299db9ec823/async-io-1.1.10/src/driver.rs:188
#6  0x00007f2406934093 in async_global_executor::reactor::block_on::{{closure}} () at /home/user/.cargo/registry/src/github.com-1ecc6299db9ec823/async-global-executor-1.4.2/src/lib.rs:48
#7  0x00007f2406934050 in async_global_executor::reactor::block_on (future=...) at /home/user/.cargo/registry/src/github.com-1ecc6299db9ec823/async-global-executor-1.4.2/src/lib.rs:55
#8  0x00007f240692d69c in async_global_executor::block_on::{{closure}} (executor=0x7f2406907078) at /home/user/.cargo/registry/src/github.com-1ecc6299db9ec823/async-global-executor-1.4.2/src/lib.rs:212
#9  0x00007f24069368c4 in std::thread::local::LocalKey<T>::try_with (self=0x7f2406aa7ed0, f=...) at /rustc/18bf6b4f01a6feaf7259ba7cdae58031af1b7b39/library/std/src/thread/local.rs:265
#10 0x00007f2406936037 in std::thread::local::LocalKey<T>::with (self=0x7f2406aa7ed0, f=...) at /rustc/18bf6b4f01a6feaf7259ba7cdae58031af1b7b39/library/std/src/thread/local.rs:241
#11 0x00007f240692d633 in async_global_executor::block_on (future=...) at /home/user/.cargo/registry/src/github.com-1ecc6299db9ec823/async-global-executor-1.4.2/src/lib.rs:212
#12 0x00007f24069396ce in async_std::task::builder::Builder::blocking::{{closure}}::{{closure}} () at /home/user/.cargo/registry/src/github.com-1ecc6299db9ec823/async-std-1.6.5/src/task/builder.rs:171
#13 0x00007f240693bb59 in async_std::task::task_locals_wrapper::TaskLocalsWrapper::set_current::{{closure}} (current=0x7f2406907060)
    at /home/user/.cargo/registry/src/github.com-1ecc6299db9ec823/async-std-1.6.5/src/task/task_locals_wrapper.rs:60
#14 0x00007f2406936da0 in std::thread::local::LocalKey<T>::try_with (self=0x7f2406aa8260, f=...) at /rustc/18bf6b4f01a6feaf7259ba7cdae58031af1b7b39/library/std/src/thread/local.rs:265
#15 0x00007f240693611d in std::thread::local::LocalKey<T>::with (self=0x7f2406aa8260, f=...) at /rustc/18bf6b4f01a6feaf7259ba7cdae58031af1b7b39/library/std/src/thread/local.rs:241
#16 0x00007f240693ba6d in async_std::task::task_locals_wrapper::TaskLocalsWrapper::set_current (task=0x7ffe348b0b10, f=...) at /home/user/.cargo/registry/src/github.com-1ecc6299db9ec823/async-std-1.6.5/src/task/task_locals_wrapper.rs:55
#17 0x00007f24069395cd in async_std::task::builder::Builder::blocking::{{closure}} (num_nested_blocking=0x7f2406907048) at /home/user/.cargo/registry/src/github.com-1ecc6299db9ec823/async-std-1.6.5/src/task/builder.rs:168
#18 0x00007f240693625c in std::thread::local::LocalKey<T>::try_with (self=0x7f2406aa81b8, f=...) at /rustc/18bf6b4f01a6feaf7259ba7cdae58031af1b7b39/library/std/src/thread/local.rs:265
#19 0x00007f2406935fb7 in std::thread::local::LocalKey<T>::with (self=0x7f2406aa81b8, f=...) at /rustc/18bf6b4f01a6feaf7259ba7cdae58031af1b7b39/library/std/src/thread/local.rs:241
#20 0x00007f2406939479 in async_std::task::builder::Builder::blocking (self=..., future=...) at /home/user/.cargo/registry/src/github.com-1ecc6299db9ec823/async-std-1.6.5/src/task/builder.rs:161
#21 0x00007f2406933166 in async_std::task::block_on::block_on (future=...) at /home/user/.cargo/registry/src/github.com-1ecc6299db9ec823/async-std-1.6.5/src/task/block_on.rs:33
#22 0x00007f24069399c8 in filedrop::main () at src/main.rs:23
strace -f on Alpine Linux (program deadlocks) 
execve("./filedrop", ["./filedrop"], 0x7ffdeead6e68 /* 14 vars */) = 0
mmap(NULL, 624, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fb22f437000
arch_prctl(ARCH_SET_FS, 0x7fb22f437180) = 0
set_tid_address(0x7fb22f5e6f40)         = 2248
rt_sigaction(SIGPIPE, {sa_handler=SIG_IGN, sa_mask=[], sa_flags=SA_RESTORER|SA_RESTART, sa_restorer=0x7fb22f56ea27}, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
rt_sigaction(SIGSEGV, NULL, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
rt_sigprocmask(SIG_UNBLOCK, [RT_1 RT_2], NULL, 8) = 0
rt_sigaction(SIGSEGV, {sa_handler=0x7fb22f54bc00, sa_mask=[], sa_flags=SA_RESTORER|SA_ONSTACK|SA_SIGINFO, sa_restorer=0x7fb22f56ea27}, NULL, 8) = 0
rt_sigaction(SIGBUS, NULL, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
rt_sigaction(SIGBUS, {sa_handler=0x7fb22f54bc00, sa_mask=[], sa_flags=SA_RESTORER|SA_ONSTACK|SA_SIGINFO, sa_restorer=0x7fb22f56ea27}, NULL, 8) = 0
sigaltstack(NULL, {ss_sp=NULL, ss_flags=SS_DISABLE, ss_size=0}) = 0
mmap(NULL, 12288, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fb22f434000
mprotect(0x7fb22f434000, 4096, PROT_NONE) = 0
sigaltstack({ss_sp=0x7fb22f435000, ss_flags=0, ss_size=8192}, NULL) = 0
brk(NULL)                               = 0x555557186000
brk(0x555557187000)                     = 0x555557187000
rt_sigprocmask(SIG_BLOCK, ~[RTMIN RT_1 RT_2], [], 8) = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
open("/proc/self/cgroup", O_RDONLY|O_CLOEXEC) = 3
fcntl(3, F_SETFD, FD_CLOEXEC)           = 0
brk(0x55555718a000)                     = 0x55555718a000
read(3, "", 8192)                       = 0
close(3)                                = 0
sched_getaffinity(0, 128, [0])          = 32
rt_sigprocmask(SIG_UNBLOCK, [RT_1 RT_2], NULL, 8) = 0
mmap(NULL, 2109440, PROT_NONE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fb22f231000
mprotect(0x7fb22f233000, 2101248, PROT_READ|PROT_WRITE) = 0
rt_sigprocmask(SIG_BLOCK, ~[RTMIN RT_1 RT_2], [], 8) = 0
clone(child_stack=0x7fb22f433968, flags=CLONE_VM|CLONE_FS|CLONE_FILES|CLONE_SIGHAND|CLONE_THREAD|CLONE_SYSVSEM|CLONE_SETTLS|CLONE_PARENT_SETTID|CLONE_CHILD_CLEARTID|0x400000, parent_tid=[2249], tls=0x7fb22f433b20, child_tidptr=0x7fb22f5e6f40) = 2249
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
mmap(NULL, 2109440, PROT_NONE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fb22f02e000
mprotect(0x7fb22f030000, 2101248, PROT_READ|PROT_WRITE) = 0
rt_sigprocmask(SIG_BLOCK, ~[RTMIN RT_1 RT_2], [], 8) = 0
clone(child_stack=0x7fb22f230968, flags=CLONE_VM|CLONE_FS|CLONE_FILES|CLONE_SIGHAND|CLONE_THREAD|CLONE_SYSVSEM|CLONE_SETTLS|CLONE_PARENT_SETTID|CLONE_CHILD_CLEARTID|0x400000, parent_tid=[2250], tls=0x7fb22f230b20, child_tidptr=0x7fb22f5e6f40) = 2250
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
epoll_create1(EPOLL_CLOEXEC)            = 3
eventfd2(0, EFD_CLOEXEC|EFD_NONBLOCK)   = 4
timerfd_create(CLOCK_MONOTONIC, TFD_CLOEXEC|TFD_NONBLOCK) = 5
epoll_ctl(3, EPOLL_CTL_ADD, 5, {EPOLLONESHOT, {u32=4294967295, u64=18446744073709551615}}) = 0
epoll_ctl(3, EPOLL_CTL_ADD, 4, {EPOLLIN|EPOLLPRI|EPOLLERR|EPOLLHUP|EPOLLRDHUP|EPOLLONESHOT, {u32=4294967295, u64=18446744073709551615}}) = 0
brk(0x55555718d000)                     = 0x55555718d000
brk(0x55555719b000)                     = 0x55555719b000
timerfd_settime(5, 0, {it_interval={tv_sec=0, tv_nsec=0}, it_value={tv_sec=0, tv_nsec=0}}, NULL) = 0
epoll_ctl(3, EPOLL_CTL_MOD, 5, {EPOLLIN|EPOLLPRI|EPOLLERR|EPOLLHUP|EPOLLRDHUP|EPOLLONESHOT, {u32=4294967295, u64=18446744073709551615}}) = 0
epoll_pwait(3, strace: Process 2250 attached
 <unfinished ...>
[pid  2250] rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
[pid  2250] sigaltstack(NULL, {ss_sp=NULL, ss_flags=SS_DISABLE, ss_size=0}) = 0
[pid  2250] mmap(NULL, 12288, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fb22f02b000
[pid  2250] mprotect(0x7fb22f02b000, 4096, PROT_NONE) = 0
[pid  2250] sigaltstack({ss_sp=0x7fb22f02c000, ss_flags=0, ss_size=8192}, NULL) = 0
[pid  2250] prctl(PR_SET_NAME, "async-io") = 0
[pid  2250] futex(0x7fb22f22fcb4, FUTEX_WAIT_PRIVATE, 2, {tv_sec=0, tv_nsec=49768}strace: Process 2249 attached
 <unfinished ...>
[pid  2249] rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
[pid  2249] sigaltstack(NULL, {ss_sp=NULL, ss_flags=SS_DISABLE, ss_size=0}) = 0
[pid  2250] <... futex resumed>)        = -1 ETIMEDOUT (Operation timed out)
[pid  2250] futex(0x7fb22f22fcb4, FUTEX_WAIT_PRIVATE, 2, {tv_sec=0, tv_nsec=74852} <unfinished ...>
[pid  2249] mmap(NULL, 12288, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fb22f028000
[pid  2249] mprotect(0x7fb22f028000, 4096, PROT_NONE) = 0
[pid  2249] sigaltstack({ss_sp=0x7fb22f029000, ss_flags=0, ss_size=8192}, NULL) = 0
[pid  2249] prctl(PR_SET_NAME, "async-std/runti"... <unfinished ...>
[pid  2250] <... futex resumed>)        = -1 ETIMEDOUT (Operation timed out)
[pid  2250] futex(0x7fb22f22fcb4, FUTEX_WAIT_PRIVATE, 2, {tv_sec=0, tv_nsec=99876} <unfinished ...>
[pid  2249] <... prctl resumed>)        = 0
[pid  2249] brk(0x55555719e000)         = 0x55555719e000
[pid  2249] brk(0x5555571a1000)         = 0x5555571a1000
[pid  2250] <... futex resumed>)        = -1 ETIMEDOUT (Operation timed out)
[pid  2250] futex(0x7fb22f22fcb4, FUTEX_WAIT_PRIVATE, 2, {tv_sec=0, tv_nsec=249852} <unfinished ...>
[pid  2249] mmap(NULL, 2109440, PROT_NONE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fb22ee25000
[pid  2249] mprotect(0x7fb22ee27000, 2101248, PROT_READ|PROT_WRITE <unfinished ...>
[pid  2250] <... futex resumed>)        = -1 ETIMEDOUT (Operation timed out)
[pid  2250] futex(0x7fb22f22fcb4, FUTEX_WAIT_PRIVATE, 2, {tv_sec=0, tv_nsec=499859} <unfinished ...>
[pid  2249] <... mprotect resumed>)     = 0
[pid  2249] rt_sigprocmask(SIG_BLOCK, ~[RTMIN RT_1 RT_2], [], 8) = 0
[pid  2249] clone(child_stack=0x7fb22f027968, flags=CLONE_VM|CLONE_FS|CLONE_FILES|CLONE_SIGHAND|CLONE_THREAD|CLONE_SYSVSEM|CLONE_SETTLS|CLONE_PARENT_SETTID|CLONE_CHILD_CLEARTID|0x400000, parent_tid=[2251], tls=0x7fb22f027b20, child_tidptr=0x7fb22f5e6f40) = 2251
[pid  2249] rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
[pid  2249] futex(0x7fb22f431e34, FUTEX_WAIT_PRIVATE, 2, NULLstrace: Process 2251 attached
 <unfinished ...>
[pid  2251] rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
[pid  2251] sigaltstack(NULL, {ss_sp=NULL, ss_flags=SS_DISABLE, ss_size=0}) = 0
[pid  2251] mmap(NULL, 12288, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fb22ee22000
[pid  2251] mprotect(0x7fb22ee22000, 4096, PROT_NONE) = 0
[pid  2251] sigaltstack({ss_sp=0x7fb22ee23000, ss_flags=0, ss_size=8192}, NULL) = 0
[pid  2251] prctl(PR_SET_NAME, "blocking-1") = 0
[pid  2251] open("foo.txt", O_WRONLY|O_CREAT|O_CLOEXEC, 0666) = 6
[pid  2251] fcntl(6, F_SETFD, FD_CLOEXEC) = 0
[pid  2251] futex(0x7fb22f431e34, FUTEX_WAKE_PRIVATE, 1 <unfinished ...>
[pid  2250] <... futex resumed>)        = -1 ETIMEDOUT (Operation timed out)
[pid  2250] futex(0x7fb22f22fcb4, FUTEX_WAIT_PRIVATE, 2, {tv_sec=0, tv_nsec=749838} <unfinished ...>
[pid  2251] <... futex resumed>)        = 1
[pid  2249] <... futex resumed>)        = 0
[pid  2249] write(2, "before drop\n", 12before drop
) = 12
[pid  2249] futex(0x7fb22f430b74, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...>
[pid  2251] futex(0x7fb22f0272a4, FUTEX_WAIT_PRIVATE, 2, {tv_sec=0, tv_nsec=499999870} <unfinished ...>
[pid  2250] <... futex resumed>)        = -1 ETIMEDOUT (Operation timed out)
[pid  2250] futex(0x7fb22f22fcb4, FUTEX_WAIT_PRIVATE, 2, {tv_sec=0, tv_nsec=999896}) = -1 ETIMEDOUT (Operation timed out)
[pid  2250] futex(0x7fb22f22fcb4, FUTEX_WAIT_PRIVATE, 2, {tv_sec=0, tv_nsec=2499902}) = -1 ETIMEDOUT (Operation timed out)
[pid  2250] futex(0x7fb22f22fcb4, FUTEX_WAIT_PRIVATE, 2, {tv_sec=0, tv_nsec=4999573}) = -1 ETIMEDOUT (Operation timed out)
[pid  2250] futex(0x7fb22f22fcb4, FUTEX_WAIT_PRIVATE, 2, {tv_sec=0, tv_nsec=9999472}) = -1 ETIMEDOUT (Operation timed out)
[pid  2250] futex(0x55555718c504, FUTEX_WAIT_PRIVATE, 2147483664, NULL <unfinished ...>
[pid  2251] <... futex resumed>)        = -1 ETIMEDOUT (Operation timed out)
[pid  2251] sigaltstack({ss_sp=NULL, ss_flags=SS_DISABLE, ss_size=8192}, NULL) = 0
[pid  2251] munmap(0x7fb22ee22000, 12288) = 0
[pid  2251] rt_sigprocmask(SIG_BLOCK, ~[RTMIN RT_1 RT_2], [], 8) = 0
[pid  2251] rt_sigprocmask(SIG_BLOCK, ~[], ~[KILL STOP RTMIN RT_1 RT_2], 8) = 0
[pid  2251] munmap(0x7fb22ee25000, 2109440) = 0
[pid  2251] exit(0)                     = ?
[pid  2251] +++ exited with 0 +++
strace -f on host Debian GNU/Linux (program finishes) 
execve("./filedrop", ["./filedrop"], 0x7ffcc492dd68 /* 40 vars */) = 0
mmap(NULL, 624, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f4c11a99000
arch_prctl(ARCH_SET_FS, 0x7f4c11a99180) = 0
set_tid_address(0x7f4c11c48f40)         = 82368
rt_sigaction(SIGPIPE, {sa_handler=SIG_IGN, sa_mask=[], sa_flags=SA_RESTORER|SA_RESTART, sa_restorer=0x7f4c11bd0a27}, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
rt_sigaction(SIGSEGV, NULL, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
rt_sigprocmask(SIG_UNBLOCK, [RT_1 RT_2], NULL, 8) = 0
rt_sigaction(SIGSEGV, {sa_handler=0x7f4c11badc00, sa_mask=[], sa_flags=SA_RESTORER|SA_ONSTACK|SA_SIGINFO, sa_restorer=0x7f4c11bd0a27}, NULL, 8) = 0
rt_sigaction(SIGBUS, NULL, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
rt_sigaction(SIGBUS, {sa_handler=0x7f4c11badc00, sa_mask=[], sa_flags=SA_RESTORER|SA_ONSTACK|SA_SIGINFO, sa_restorer=0x7f4c11bd0a27}, NULL, 8) = 0
sigaltstack(NULL, {ss_sp=NULL, ss_flags=SS_DISABLE, ss_size=0}) = 0
mmap(NULL, 12288, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f4c11a96000
mprotect(0x7f4c11a96000, 4096, PROT_NONE) = 0
sigaltstack({ss_sp=0x7f4c11a97000, ss_flags=0, ss_size=8192}, NULL) = 0
brk(NULL)                               = 0x555555a1b000
brk(0x555555a1c000)                     = 0x555555a1c000
rt_sigprocmask(SIG_BLOCK, ~[RTMIN RT_1 RT_2], [], 8) = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
open("/proc/self/cgroup", O_RDONLY|O_CLOEXEC) = 3
fcntl(3, F_SETFD, FD_CLOEXEC)           = 0
brk(0x555555a1f000)                     = 0x555555a1f000
read(3, "11:devices:/user.slice\n10:freeze"..., 8192) = 332
close(3)                                = 0
open("/proc/self/mountinfo", O_RDONLY|O_CLOEXEC) = 3
fcntl(3, F_SETFD, FD_CLOEXEC)           = 0
read(3, "22 27 0:20 / /sys rw,nosuid,node"..., 8192) = 3298
close(3)                                = 0
open("/sys/fs/cgroup/cpu,cpuacct/cpu.cfs_quota_us", O_RDONLY|O_CLOEXEC) = 3
fcntl(3, F_SETFD, FD_CLOEXEC)           = 0
read(3, "-1\n", 32)                     = 3
read(3, "", 29)                         = 0
close(3)                                = 0
sched_getaffinity(0, 128, [0, 1, 2, 3]) = 64
rt_sigprocmask(SIG_UNBLOCK, [RT_1 RT_2], NULL, 8) = 0
mmap(NULL, 2109440, PROT_NONE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f4c11893000
mprotect(0x7f4c11895000, 2101248, PROT_READ|PROT_WRITE) = 0
rt_sigprocmask(SIG_BLOCK, ~[RTMIN RT_1 RT_2], [], 8) = 0
clone(child_stack=0x7f4c11a95968, flags=CLONE_VM|CLONE_FS|CLONE_FILES|CLONE_SIGHAND|CLONE_THREAD|CLONE_SYSVSEM|CLONE_SETTLS|CLONE_PARENT_SETTID|CLONE_CHILD_CLEARTID|0x400000, parent_tid=[82369], tls=0x7f4c11a95b20, child_tidptr=0x7f4c11c48f40) = 82369
strace: Process 82369 attached
[pid 82368] rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
[pid 82368] mmap(NULL, 2109440, PROT_NONE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0 <unfinished ...>
[pid 82369] rt_sigprocmask(SIG_SETMASK, [],  <unfinished ...>
[pid 82368] <... mmap resumed>)         = 0x7f4c11690000
[pid 82368] mprotect(0x7f4c11692000, 2101248, PROT_READ|PROT_WRITE <unfinished ...>
[pid 82369] <... rt_sigprocmask resumed>NULL, 8) = 0
[pid 82368] <... mprotect resumed>)     = 0
[pid 82368] rt_sigprocmask(SIG_BLOCK, ~[RTMIN RT_1 RT_2], [], 8) = 0
[pid 82369] sigaltstack(NULL,  <unfinished ...>
[pid 82368] clone(child_stack=0x7f4c11892968, flags=CLONE_VM|CLONE_FS|CLONE_FILES|CLONE_SIGHAND|CLONE_THREAD|CLONE_SYSVSEM|CLONE_SETTLS|CLONE_PARENT_SETTID|CLONE_CHILD_CLEARTID|0x400000 <unfinished ...>
[pid 82369] <... sigaltstack resumed>{ss_sp=NULL, ss_flags=SS_DISABLE, ss_size=0}) = 0
[pid 82369] mmap(NULL, 12288, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0strace: Process 82370 attached
 <unfinished ...>
[pid 82368] <... clone resumed>, parent_tid=[82370], tls=0x7f4c11892b20, child_tidptr=0x7f4c11c48f40) = 82370
[pid 82369] <... mmap resumed>)         = 0x7f4c1168d000
[pid 82368] rt_sigprocmask(SIG_SETMASK, [],  <unfinished ...>
[pid 82369] mprotect(0x7f4c1168d000, 4096, PROT_NONE <unfinished ...>
[pid 82368] <... rt_sigprocmask resumed>NULL, 8) = 0
[pid 82370] rt_sigprocmask(SIG_SETMASK, [],  <unfinished ...>
[pid 82369] <... mprotect resumed>)     = 0
[pid 82368] mmap(NULL, 2109440, PROT_NONE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0 <unfinished ...>
[pid 82370] <... rt_sigprocmask resumed>NULL, 8) = 0
[pid 82369] sigaltstack({ss_sp=0x7f4c1168e000, ss_flags=0, ss_size=8192},  <unfinished ...>
[pid 82368] <... mmap resumed>)         = 0x7f4c1148a000
[pid 82370] sigaltstack(NULL,  <unfinished ...>
[pid 82369] <... sigaltstack resumed>NULL) = 0
[pid 82368] mprotect(0x7f4c1148c000, 2101248, PROT_READ|PROT_WRITE <unfinished ...>
[pid 82370] <... sigaltstack resumed>{ss_sp=NULL, ss_flags=SS_DISABLE, ss_size=0}) = 0
[pid 82368] <... mprotect resumed>)     = 0
[pid 82369] prctl(PR_SET_NAME, "async-std/runti"... <unfinished ...>
[pid 82370] mmap(NULL, 12288, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0 <unfinished ...>
[pid 82368] rt_sigprocmask(SIG_BLOCK, ~[RTMIN RT_1 RT_2],  <unfinished ...>
[pid 82369] <... prctl resumed>)        = 0
[pid 82368] <... rt_sigprocmask resumed>[], 8) = 0
[pid 82370] <... mmap resumed>)         = 0x7f4c11487000
[pid 82368] clone(child_stack=0x7f4c1168c968, flags=CLONE_VM|CLONE_FS|CLONE_FILES|CLONE_SIGHAND|CLONE_THREAD|CLONE_SYSVSEM|CLONE_SETTLS|CLONE_PARENT_SETTID|CLONE_CHILD_CLEARTID|0x400000 <unfinished ...>
[pid 82370] mprotect(0x7f4c11487000, 4096, PROT_NONE) = 0
[pid 82368] <... clone resumed>, parent_tid=[82371], tls=0x7f4c1168cb20, child_tidptr=0x7f4c11c48f40) = 82371
[pid 82370] sigaltstack({ss_sp=0x7f4c11488000, ss_flags=0, ss_size=8192}, strace: Process 82371 attached
 <unfinished ...>
[pid 82368] rt_sigprocmask(SIG_SETMASK, [],  <unfinished ...>
[pid 82370] <... sigaltstack resumed>NULL) = 0
[pid 82371] rt_sigprocmask(SIG_SETMASK, [],  <unfinished ...>
[pid 82370] prctl(PR_SET_NAME, "async-std/runti"... <unfinished ...>
[pid 82371] <... rt_sigprocmask resumed>NULL, 8) = 0
[pid 82370] <... prctl resumed>)        = 0
[pid 82369] brk(0x555555a22000 <unfinished ...>
[pid 82371] sigaltstack(NULL,  <unfinished ...>
[pid 82368] <... rt_sigprocmask resumed>NULL, 8) = 0
[pid 82369] <... brk resumed>)          = 0x555555a22000
[pid 82371] <... sigaltstack resumed>{ss_sp=NULL, ss_flags=SS_DISABLE, ss_size=0}) = 0
[pid 82370] futex(0x7f4c11c47e00, FUTEX_WAIT_PRIVATE, 1, NULL <unfinished ...>
[pid 82368] mmap(NULL, 2109440, PROT_NONE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0 <unfinished ...>
[pid 82371] mmap(NULL, 12288, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0 <unfinished ...>
[pid 82370] <... futex resumed>)        = -1 EAGAIN (Resource temporarily unavailable)
[pid 82369] futex(0x7f4c11c47e00, FUTEX_WAKE_PRIVATE, 1 <unfinished ...>
[pid 82368] <... mmap resumed>)         = 0x7f4c11284000
[pid 82371] <... mmap resumed>)         = 0x7f4c11281000
[pid 82370] brk(0x555555a25000 <unfinished ...>
[pid 82368] mprotect(0x7f4c11286000, 2101248, PROT_READ|PROT_WRITE <unfinished ...>
[pid 82369] <... futex resumed>)        = 0
[pid 82368] <... mprotect resumed>)     = 0
[pid 82371] mprotect(0x7f4c11281000, 4096, PROT_NONE <unfinished ...>
[pid 82370] <... brk resumed>)          = 0x555555a25000
[pid 82371] <... mprotect resumed>)     = 0
[pid 82368] rt_sigprocmask(SIG_BLOCK, ~[RTMIN RT_1 RT_2],  <unfinished ...>
[pid 82371] sigaltstack({ss_sp=0x7f4c11282000, ss_flags=0, ss_size=8192},  <unfinished ...>
[pid 82370] brk(0x555555a26000 <unfinished ...>
[pid 82369] mmap(NULL, 2109440, PROT_NONE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0 <unfinished ...>
[pid 82368] <... rt_sigprocmask resumed>[], 8) = 0
[pid 82371] <... sigaltstack resumed>NULL) = 0
[pid 82370] <... brk resumed>)          = 0x555555a26000
[pid 82369] <... mmap resumed>)         = 0x7f4c1107e000
[pid 82368] clone(child_stack=0x7f4c11486968, flags=CLONE_VM|CLONE_FS|CLONE_FILES|CLONE_SIGHAND|CLONE_THREAD|CLONE_SYSVSEM|CLONE_SETTLS|CLONE_PARENT_SETTID|CLONE_CHILD_CLEARTID|0x400000 <unfinished ...>
[pid 82371] prctl(PR_SET_NAME, "async-std/runti"... <unfinished ...>
[pid 82369] mprotect(0x7f4c11080000, 2101248, PROT_READ|PROT_WRITE <unfinished ...>
[pid 82368] <... clone resumed>, parent_tid=[82372], tls=0x7f4c11486b20, child_tidptr=0x7f4c11c48f40) = 82372
[pid 82369] <... mprotect resumed>)     = 0
[pid 82368] rt_sigprocmask(SIG_SETMASK, [],  <unfinished ...>
[pid 82369] rt_sigprocmask(SIG_BLOCK, ~[RTMIN RT_1 RT_2],  <unfinished ...>
[pid 82368] <... rt_sigprocmask resumed>NULL, 8) = 0
strace: Process 82372 attached
[pid 82371] <... prctl resumed>)        = 0
[pid 82370] futex(0x7f4c11890fe4, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...>
[pid 82369] <... rt_sigprocmask resumed>[], 8) = 0
[pid 82368] brk(0x555555a27000 <unfinished ...>
[pid 82372] rt_sigprocmask(SIG_SETMASK, [],  <unfinished ...>
[pid 82369] clone(child_stack=0x7f4c11280968, flags=CLONE_VM|CLONE_FS|CLONE_FILES|CLONE_SIGHAND|CLONE_THREAD|CLONE_SYSVSEM|CLONE_SETTLS|CLONE_PARENT_SETTID|CLONE_CHILD_CLEARTID|0x400000 <unfinished ...>
[pid 82368] <... brk resumed>)          = 0x555555a27000
[pid 82372] <... rt_sigprocmask resumed>NULL, 8) = 0
[pid 82371] futex(0x7f4c11c47e00, FUTEX_WAIT_PRIVATE, 1, NULLstrace: Process 82373 attached
 <unfinished ...>
[pid 82368] futex(0x7f4c11c47e00, FUTEX_WAKE_PRIVATE, 1 <unfinished ...>
[pid 82372] sigaltstack(NULL,  <unfinished ...>
[pid 82371] <... futex resumed>)        = -1 EAGAIN (Resource temporarily unavailable)
[pid 82368] <... futex resumed>)        = 0
[pid 82373] rt_sigprocmask(SIG_SETMASK, [],  <unfinished ...>
[pid 82372] <... sigaltstack resumed>{ss_sp=NULL, ss_flags=SS_DISABLE, ss_size=0}) = 0
[pid 82371] brk(0x555555a2a000 <unfinished ...>
[pid 82368] futex(0x7f4c11c47e00, FUTEX_WAIT_PRIVATE, 1, NULL <unfinished ...>
[pid 82373] <... rt_sigprocmask resumed>NULL, 8) = 0
[pid 82372] mmap(NULL, 12288, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0 <unfinished ...>
[pid 82371] <... brk resumed>)          = 0x555555a2a000
[pid 82369] <... clone resumed>, parent_tid=[82373], tls=0x7f4c11280b20, child_tidptr=0x7f4c11c48f40) = 82373
[pid 82372] <... mmap resumed>)         = 0x7f4c1107b000
[pid 82371] futex(0x7f4c11c47e00, FUTEX_WAKE_PRIVATE, 1 <unfinished ...>
[pid 82369] rt_sigprocmask(SIG_SETMASK, [],  <unfinished ...>
[pid 82373] sigaltstack(NULL,  <unfinished ...>
[pid 82372] mprotect(0x7f4c1107b000, 4096, PROT_NONE <unfinished ...>
[pid 82371] <... futex resumed>)        = 1
[pid 82368] <... futex resumed>)        = 0
[pid 82369] <... rt_sigprocmask resumed>NULL, 8) = 0
[pid 82368] brk(0x555555a2d000 <unfinished ...>
[pid 82373] <... sigaltstack resumed>{ss_sp=NULL, ss_flags=SS_DISABLE, ss_size=0}) = 0
[pid 82372] <... mprotect resumed>)     = 0
[pid 82368] <... brk resumed>)          = 0x555555a2d000
[pid 82373] mmap(NULL, 12288, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0 <unfinished ...>
[pid 82369] epoll_create1(EPOLL_CLOEXEC <unfinished ...>
[pid 82372] sigaltstack({ss_sp=0x7f4c1107c000, ss_flags=0, ss_size=8192}, NULL) = 0
[pid 82369] <... epoll_create1 resumed>) = 3
[pid 82372] prctl(PR_SET_NAME, "async-std/runti"... <unfinished ...>
[pid 82369] eventfd2(0, EFD_CLOEXEC|EFD_NONBLOCK <unfinished ...>
[pid 82372] <... prctl resumed>)        = 0
[pid 82369] <... eventfd2 resumed>)     = 4
[pid 82368] futex(0x7ffd5be0c904, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...>
[pid 82373] <... mmap resumed>)         = 0x7f4c11078000
[pid 82371] brk(0x555555a2e000 <unfinished ...>
[pid 82373] mprotect(0x7f4c11078000, 4096, PROT_NONE <unfinished ...>
[pid 82372] futex(0x7f4c11c47e00, FUTEX_WAIT_PRIVATE, 1, NULL <unfinished ...>
[pid 82369] timerfd_create(CLOCK_MONOTONIC, TFD_CLOEXEC|TFD_NONBLOCK <unfinished ...>
[pid 82371] <... brk resumed>)          = 0x555555a2e000
[pid 82373] <... mprotect resumed>)     = 0
[pid 82369] <... timerfd_create resumed>) = 5
[pid 82371] futex(0x7f4c11c47e00, FUTEX_WAKE_PRIVATE, 1 <unfinished ...>
[pid 82369] epoll_ctl(3, EPOLL_CTL_ADD, 5, {EPOLLONESHOT, {u32=4294967295, u64=18446744073709551615}} <unfinished ...>
[pid 82373] sigaltstack({ss_sp=0x7f4c11079000, ss_flags=0, ss_size=8192},  <unfinished ...>
[pid 82372] <... futex resumed>)        = 0
[pid 82371] <... futex resumed>)        = 1
[pid 82373] <... sigaltstack resumed>NULL) = 0
[pid 82369] <... epoll_ctl resumed>)    = 0
[pid 82372] brk(0x555555a2f000 <unfinished ...>
[pid 82369] epoll_ctl(3, EPOLL_CTL_ADD, 4, {EPOLLIN|EPOLLPRI|EPOLLERR|EPOLLHUP|EPOLLRDHUP|EPOLLONESHOT, {u32=4294967295, u64=18446744073709551615}} <unfinished ...>
[pid 82371] mmap(NULL, 2109440, PROT_NONE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0 <unfinished ...>
[pid 82373] prctl(PR_SET_NAME, "async-io" <unfinished ...>
[pid 82372] <... brk resumed>)          = 0x555555a2f000
[pid 82369] <... epoll_ctl resumed>)    = 0
[pid 82373] <... prctl resumed>)        = 0
[pid 82371] <... mmap resumed>)         = 0x7f4c10e75000
[pid 82372] brk(0x555555a32000 <unfinished ...>
[pid 82369] futex(0x7f4c11c47e00, FUTEX_WAIT_PRIVATE, 1, NULL <unfinished ...>
[pid 82371] mprotect(0x7f4c10e77000, 2101248, PROT_READ|PROT_WRITE <unfinished ...>
[pid 82373] futex(0x7f4c1127ff94, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...>
[pid 82372] <... brk resumed>)          = 0x555555a32000
[pid 82371] <... mprotect resumed>)     = 0
[pid 82372] futex(0x7f4c11c47e00, FUTEX_WAKE_PRIVATE, 1 <unfinished ...>
[pid 82371] rt_sigprocmask(SIG_BLOCK, ~[RTMIN RT_1 RT_2],  <unfinished ...>
[pid 82372] <... futex resumed>)        = 1
[pid 82369] <... futex resumed>)        = 0
[pid 82371] <... rt_sigprocmask resumed>[], 8) = 0
[pid 82369] brk(0x555555a35000 <unfinished ...>
[pid 82371] clone(child_stack=0x7f4c11077968, flags=CLONE_VM|CLONE_FS|CLONE_FILES|CLONE_SIGHAND|CLONE_THREAD|CLONE_SYSVSEM|CLONE_SETTLS|CLONE_PARENT_SETTID|CLONE_CHILD_CLEARTID|0x400000 <unfinished ...>
[pid 82369] <... brk resumed>)          = 0x555555a35000
strace: Process 82374 attached
[pid 82371] <... clone resumed>, parent_tid=[82374], tls=0x7f4c11077b20, child_tidptr=0x7f4c11c48f40) = 82374
[pid 82374] rt_sigprocmask(SIG_SETMASK, [],  <unfinished ...>
[pid 82372] futex(0x7f4c11484fe4, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...>
[pid 82371] rt_sigprocmask(SIG_SETMASK, [],  <unfinished ...>
[pid 82374] <... rt_sigprocmask resumed>NULL, 8) = 0
[pid 82369] brk(0x555555a43000 <unfinished ...>
[pid 82374] sigaltstack(NULL,  <unfinished ...>
[pid 82371] <... rt_sigprocmask resumed>NULL, 8) = 0
[pid 82374] <... sigaltstack resumed>{ss_sp=NULL, ss_flags=SS_DISABLE, ss_size=0}) = 0
[pid 82369] <... brk resumed>)          = 0x555555a43000
[pid 82374] mmap(NULL, 12288, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0 <unfinished ...>
[pid 82371] futex(0x7f4c1168afe4, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...>
[pid 82374] <... mmap resumed>)         = 0x7f4c10e72000
[pid 82369] futex(0x7f4c1168afe4, FUTEX_WAKE_PRIVATE, 1 <unfinished ...>
[pid 82374] mprotect(0x7f4c10e72000, 4096, PROT_NONE <unfinished ...>
[pid 82371] <... futex resumed>)        = 0
[pid 82369] <... futex resumed>)        = 1
[pid 82374] <... mprotect resumed>)     = 0
[pid 82369] futex(0x7f4c11484fe4, FUTEX_WAKE_PRIVATE, 1 <unfinished ...>
[pid 82374] sigaltstack({ss_sp=0x7f4c10e73000, ss_flags=0, ss_size=8192},  <unfinished ...>
[pid 82371] timerfd_settime(5, 0, {it_interval={tv_sec=0, tv_nsec=0}, it_value={tv_sec=0, tv_nsec=0}},  <unfinished ...>
[pid 82374] <... sigaltstack resumed>NULL) = 0
[pid 82372] <... futex resumed>)        = 0
[pid 82369] <... futex resumed>)        = 1
[pid 82371] <... timerfd_settime resumed>NULL) = 0
[pid 82374] prctl(PR_SET_NAME, "blocking-1" <unfinished ...>
[pid 82372] futex(0x7f4c11484e34, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...>
[pid 82369] futex(0x7f4c1127ff94, FUTEX_WAKE_PRIVATE, 1 <unfinished ...>
[pid 82371] epoll_ctl(3, EPOLL_CTL_MOD, 5, {EPOLLIN|EPOLLPRI|EPOLLERR|EPOLLHUP|EPOLLRDHUP|EPOLLONESHOT, {u32=4294967295, u64=18446744073709551615}} <unfinished ...>
[pid 82374] <... prctl resumed>)        = 0
[pid 82373] <... futex resumed>)        = 0
[pid 82371] <... epoll_ctl resumed>)    = 0
[pid 82369] <... futex resumed>)        = 1
[pid 82374] open("foo.txt", O_WRONLY|O_CREAT|O_CLOEXEC, 0666 <unfinished ...>
[pid 82373] futex(0x7f4c1127fcb4, FUTEX_WAIT_PRIVATE, 2, {tv_sec=0, tv_nsec=49892} <unfinished ...>
[pid 82371] epoll_pwait(3,  <unfinished ...>
[pid 82369] futex(0x7ffd5be0c904, FUTEX_WAKE_PRIVATE, 1 <unfinished ...>
[pid 82374] <... open resumed>)         = 6
[pid 82371] <... epoll_pwait resumed>[], 1000, 0, NULL, 8) = 0
[pid 82374] fcntl(6, F_SETFD, FD_CLOEXEC <unfinished ...>
[pid 82369] <... futex resumed>)        = 1
[pid 82374] <... fcntl resumed>)        = 0
[pid 82371] read(4,  <unfinished ...>
[pid 82369] futex(0x7f4c11890fe4, FUTEX_WAKE_PRIVATE, 1 <unfinished ...>
[pid 82374] futex(0x7f4c110772a4, FUTEX_WAIT_PRIVATE, 2, {tv_sec=0, tv_nsec=499999801} <unfinished ...>
[pid 82371] <... read resumed>0x7f4c1168a990, 8) = -1 EAGAIN (Resource temporarily unavailable)
[pid 82370] <... futex resumed>)        = 0
[pid 82369] <... futex resumed>)        = 1
[pid 82371] epoll_ctl(3, EPOLL_CTL_MOD, 4, {EPOLLIN|EPOLLPRI|EPOLLERR|EPOLLHUP|EPOLLRDHUP|EPOLLONESHOT, {u32=4294967295, u64=18446744073709551615}} <unfinished ...>
[pid 82369] futex(0x7f4c11a93e34, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...>
[pid 82371] <... epoll_ctl resumed>)    = 0
[pid 82368] <... futex resumed>)        = 0
[pid 82368] timerfd_settime(5, 0, {it_interval={tv_sec=0, tv_nsec=0}, it_value={tv_sec=0, tv_nsec=0}},  <unfinished ...>
[pid 82373] <... futex resumed>)        = -1 ETIMEDOUT (Connection timed out)
[pid 82371] futex(0x7f4c1168ae34, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...>
[pid 82370] write(2, "before drop\n", 12before drop
 <unfinished ...>
[pid 82368] <... timerfd_settime resumed>NULL) = 0
[pid 82373] futex(0x7f4c1127fcb4, FUTEX_WAIT_PRIVATE, 2, {tv_sec=0, tv_nsec=74860} <unfinished ...>
[pid 82368] epoll_ctl(3, EPOLL_CTL_MOD, 5, {EPOLLIN|EPOLLPRI|EPOLLERR|EPOLLHUP|EPOLLRDHUP|EPOLLONESHOT, {u32=4294967295, u64=18446744073709551615}} <unfinished ...>
[pid 82370] <... write resumed>)        = 12
[pid 82368] <... epoll_ctl resumed>)    = 0
[pid 82368] epoll_pwait(3,  <unfinished ...>
[pid 82370] futex(0x7f4c1168ae34, FUTEX_WAKE_PRIVATE, 1 <unfinished ...>
[pid 82371] <... futex resumed>)        = 0
[pid 82370] <... futex resumed>)        = 1
[pid 82371] futex(0x7f4c11484e34, FUTEX_WAKE_PRIVATE, 1 <unfinished ...>
[pid 82370] futex(0x7f4c1188fb74, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...>
[pid 82372] <... futex resumed>)        = 0
[pid 82371] <... futex resumed>)        = 1
[pid 82372] futex(0x7f4c11484e34, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...>
[pid 82371] futex(0x7f4c110772a4, FUTEX_WAKE_PRIVATE, 1 <unfinished ...>
[pid 82373] <... futex resumed>)        = -1 ETIMEDOUT (Connection timed out)
[pid 82374] <... futex resumed>)        = 0
[pid 82371] <... futex resumed>)        = 1
[pid 82374] futex(0x555555a2cf04, FUTEX_WAIT_PRIVATE, 2147483664, NULL <unfinished ...>
[pid 82373] futex(0x7f4c1127fcb4, FUTEX_WAIT_PRIVATE, 2, {tv_sec=0, tv_nsec=99890} <unfinished ...>
[pid 82374] <... futex resumed>)        = -1 EAGAIN (Resource temporarily unavailable)
[pid 82371] futex(0x555555a2cf04, FUTEX_WAKE_PRIVATE, 1 <unfinished ...>
[pid 82374] write(6, "foobarbaz", 9 <unfinished ...>
[pid 82371] <... futex resumed>)        = 0
[pid 82374] <... write resumed>)        = 9
[pid 82371] futex(0x7f4c1168ae34, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...>
[pid 82374] futex(0x7f4c1188fb74, FUTEX_WAKE_PRIVATE, 1) = 1
[pid 82370] <... futex resumed>)        = 0
[pid 82374] futex(0x7f4c1168ae34, FUTEX_WAKE_PRIVATE, 1) = 1
[pid 82371] <... futex resumed>)        = 0
[pid 82370] futex(0x7f4c1188fb74, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...>
[pid 82374] futex(0x7f4c110772a4, FUTEX_WAIT_PRIVATE, 2, {tv_sec=0, tv_nsec=499999892} <unfinished ...>
[pid 82371] futex(0x7f4c11484e34, FUTEX_WAKE_PRIVATE, 1 <unfinished ...>
[pid 82372] <... futex resumed>)        = 0
[pid 82371] <... futex resumed>)        = 1
[pid 82373] <... futex resumed>)        = -1 ETIMEDOUT (Connection timed out)
[pid 82372] futex(0x7f4c11a93e34, FUTEX_WAKE_PRIVATE, 1 <unfinished ...>
[pid 82373] futex(0x7f4c1127fcb4, FUTEX_WAIT_PRIVATE, 2, {tv_sec=0, tv_nsec=249882} <unfinished ...>
[pid 82371] futex(0x7f4c1168ae34, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...>
[pid 82372] <... futex resumed>)        = 1
[pid 82369] <... futex resumed>)        = 0
[pid 82372] futex(0x7f4c110772a4, FUTEX_WAKE_PRIVATE, 1 <unfinished ...>
[pid 82369] futex(0x7f4c11a93e34, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...>
[pid 82374] <... futex resumed>)        = 0
[pid 82372] <... futex resumed>)        = 1
[pid 82374] futex(0x555555a2cf04, FUTEX_WAIT_PRIVATE, 2147483664, NULL <unfinished ...>
[pid 82372] futex(0x555555a2cf04, FUTEX_WAKE_PRIVATE, 1 <unfinished ...>
[pid 82374] <... futex resumed>)        = -1 EAGAIN (Resource temporarily unavailable)
[pid 82372] <... futex resumed>)        = 0
[pid 82374] futex(0x7f4c1188fb74, FUTEX_WAKE_PRIVATE, 1) = 1
[pid 82370] <... futex resumed>)        = 0
[pid 82374] futex(0x7f4c11484e34, FUTEX_WAKE_PRIVATE, 1 <unfinished ...>
[pid 82372] futex(0x7f4c11484e34, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...>
[pid 82370] close(6 <unfinished ...>
[pid 82374] <... futex resumed>)        = 0
[pid 82372] <... futex resumed>)        = -1 EAGAIN (Resource temporarily unavailable)
[pid 82374] futex(0x7f4c110772a4, FUTEX_WAIT_PRIVATE, 2, {tv_sec=0, tv_nsec=499999852} <unfinished ...>
[pid 82370] <... close resumed>)        = 0
[pid 82372] futex(0x7f4c11a93e34, FUTEX_WAKE_PRIVATE, 1) = 1
[pid 82370] write(2, "after drop\n", 11 <unfinished ...>
after drop
[pid 82369] <... futex resumed>)        = 0
[pid 82370] <... write resumed>)        = 11
[pid 82372] futex(0x7f4c11484e34, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...>
[pid 82370] write(4, "\1\0\0\0\0\0\0\0", 8 <unfinished ...>
[pid 82368] <... epoll_pwait resumed>[{EPOLLIN, {u32=4294967295, u64=18446744073709551615}}], 1000, -1, NULL, 8) = 1
[pid 82370] <... write resumed>)        = 8
[pid 82369] futex(0x7f4c11a93e34, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...>
[pid 82368] read(4, "\1\0\0\0\0\0\0\0", 8) = 8
[pid 82370] futex(0x7f4c11890e34, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...>
[pid 82368] epoll_ctl(3, EPOLL_CTL_MOD, 4, {EPOLLIN|EPOLLPRI|EPOLLERR|EPOLLHUP|EPOLLRDHUP|EPOLLONESHOT, {u32=4294967295, u64=18446744073709551615}}) = 0
[pid 82368] futex(0x7f4c1127fcb4, FUTEX_WAKE_PRIVATE, 1) = 1
[pid 82373] <... futex resumed>)        = 0
[pid 82368] sigaltstack({ss_sp=NULL, ss_flags=SS_DISABLE, ss_size=8192},  <unfinished ...>
[pid 82373] timerfd_settime(5, 0, {it_interval={tv_sec=0, tv_nsec=0}, it_value={tv_sec=0, tv_nsec=0}},  <unfinished ...>
[pid 82368] <... sigaltstack resumed>NULL) = 0
[pid 82373] <... timerfd_settime resumed>NULL) = 0
[pid 82368] munmap(0x7f4c11a96000, 12288 <unfinished ...>
[pid 82373] epoll_ctl(3, EPOLL_CTL_MOD, 5, {EPOLLIN|EPOLLPRI|EPOLLERR|EPOLLHUP|EPOLLRDHUP|EPOLLONESHOT, {u32=4294967295, u64=18446744073709551615}} <unfinished ...>
[pid 82368] <... munmap resumed>)       = 0
[pid 82373] <... epoll_ctl resumed>)    = 0
[pid 82368] exit_group(0 <unfinished ...>
[pid 82373] ????( <unfinished ...>
[pid 82368] <... exit_group resumed>)   = ?
[pid 82374] <... futex resumed>)        = ?
[pid 82373] <... ???? resumed>)         = ?
[pid 82372] <... futex resumed>)        = ?
[pid 82371] <... futex resumed>)        = ?
[pid 82370] <... futex resumed>)        = ?
[pid 82369] <... futex resumed>)        = ?
[pid 82374] +++ exited with 0 +++
[pid 82373] +++ exited with 0 +++
[pid 82372] +++ exited with 0 +++
[pid 82371] +++ exited with 0 +++
[pid 82370] +++ exited with 0 +++
[pid 82369] +++ exited with 0 +++
+++ exited with 0 +++

@ghost
Copy link

ghost commented Oct 26, 2020

Can you perhaps try replacing async_std::fs::File with async_fs::File and see if the deadlock goes away?

https://docs.rs/async-fs/1.5.0/async_fs/struct.File.html

Let's if there's a problem in the async file implementtion or somewhere else.

@link2xt
Copy link
Author

link2xt commented Oct 26, 2020 •
edited
Loading

With async_fs::OpenOptions it works on Alpine (in qemu).

@link2xt
Copy link
Author

link2xt commented Oct 26, 2020

strace -f on Alpine under qemu with async_fs::OpenOptions 
execve("./filedrop", ["./filedrop"], 0x7ffcab7ee3f8 /* 14 vars */) = 0
mmap(NULL, 624, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f493da10000
arch_prctl(ARCH_SET_FS, 0x7f493da10180) = 0
set_tid_address(0x7f493da20f40)         = 2897
rt_sigaction(SIGPIPE, {sa_handler=SIG_IGN, sa_mask=[], sa_flags=SA_RESTORER|SA_RESTART, sa_restorer=0x7f493d9ab137}, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
rt_sigaction(SIGSEGV, NULL, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
rt_sigprocmask(SIG_UNBLOCK, [RT_1 RT_2], NULL, 8) = 0
rt_sigaction(SIGSEGV, {sa_handler=0x7f493d988310, sa_mask=[], sa_flags=SA_RESTORER|SA_ONSTACK|SA_SIGINFO, sa_restorer=0x7f493d9ab137}, NULL, 8) = 0
rt_sigaction(SIGBUS, NULL, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
rt_sigaction(SIGBUS, {sa_handler=0x7f493d988310, sa_mask=[], sa_flags=SA_RESTORER|SA_ONSTACK|SA_SIGINFO, sa_restorer=0x7f493d9ab137}, NULL, 8) = 0
sigaltstack(NULL, {ss_sp=NULL, ss_flags=SS_DISABLE, ss_size=0}) = 0
mmap(NULL, 12288, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f493d87c000
mprotect(0x7f493d87c000, 4096, PROT_NONE) = 0
sigaltstack({ss_sp=0x7f493d87d000, ss_flags=0, ss_size=8192}, NULL) = 0
brk(NULL)                               = 0x555555efa000
brk(0x555555efb000)                     = 0x555555efb000
rt_sigprocmask(SIG_BLOCK, ~[RTMIN RT_1 RT_2], [], 8) = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
open("/proc/self/cgroup", O_RDONLY|O_CLOEXEC) = 3
fcntl(3, F_SETFD, FD_CLOEXEC)           = 0
brk(0x555555efe000)                     = 0x555555efe000
read(3, "", 8192)                       = 0
close(3)                                = 0
sched_getaffinity(0, 128, [0])          = 32
rt_sigprocmask(SIG_UNBLOCK, [RT_1 RT_2], NULL, 8) = 0
mmap(NULL, 2109440, PROT_NONE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f493d679000
mprotect(0x7f493d67b000, 2101248, PROT_READ|PROT_WRITE) = 0
rt_sigprocmask(SIG_BLOCK, ~[RTMIN RT_1 RT_2], [], 8) = 0
clone(child_stack=0x7f493d87b968, flags=CLONE_VM|CLONE_FS|CLONE_FILES|CLONE_SIGHAND|CLONE_THREAD|CLONE_SYSVSEM|CLONE_SETTLS|CLONE_PARENT_SETTID|CLONE_CHILD_CLEARTID|0x400000, parent_tid=[2898], tls=0x7f493d87bb20, child_tidptr=0x7f493da20f40) = 2898
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
mmap(NULL, 2109440, PROT_NONE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f493d476000
mprotect(0x7f493d478000, 2101248, PROT_READ|PROT_WRITE) = 0
rt_sigprocmask(SIG_BLOCK, ~[RTMIN RT_1 RT_2], [], 8) = 0
clone(child_stack=0x7f493d678968, flags=CLONE_VM|CLONE_FS|CLONE_FILES|CLONE_SIGHAND|CLONE_THREAD|CLONE_SYSVSEM|CLONE_SETTLS|CLONE_PARENT_SETTID|CLONE_CHILD_CLEARTID|0x400000, parent_tid=[2899], tls=0x7f493d678b20, child_tidptr=0x7f493da20f40) = 2899
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
epoll_create1(EPOLL_CLOEXEC)            = 3
eventfd2(0, EFD_CLOEXEC|EFD_NONBLOCK)   = 4
timerfd_create(CLOCK_MONOTONIC, TFD_CLOEXEC|TFD_NONBLOCK) = 5
epoll_ctl(3, EPOLL_CTL_ADD, 5, {EPOLLONESHOT, {u32=4294967295, u64=18446744073709551615}}) = 0
epoll_ctl(3, EPOLL_CTL_ADD, 4, {EPOLLIN|EPOLLPRI|EPOLLERR|EPOLLHUP|EPOLLRDHUP|EPOLLONESHOT, {u32=4294967295, u64=18446744073709551615}}) = 0
brk(0x555555f01000)                     = 0x555555f01000
brk(0x555555f0f000)                     = 0x555555f0f000
timerfd_settime(5, 0, {it_interval={tv_sec=0, tv_nsec=0}, it_value={tv_sec=0, tv_nsec=0}}, NULL) = 0
epoll_ctl(3, EPOLL_CTL_MOD, 5, {EPOLLIN|EPOLLPRI|EPOLLERR|EPOLLHUP|EPOLLRDHUP|EPOLLONESHOT, {u32=4294967295, u64=18446744073709551615}}) = 0
epoll_pwait(3, strace: Process 2899 attached
 <unfinished ...>
[pid  2899] rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
[pid  2899] sigaltstack(NULL, {ss_sp=NULL, ss_flags=SS_DISABLE, ss_size=0}) = 0
[pid  2899] mmap(NULL, 12288, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f493d473000
[pid  2899] mprotect(0x7f493d473000, 4096, PROT_NONE) = 0
[pid  2899] sigaltstack({ss_sp=0x7f493d474000, ss_flags=0, ss_size=8192}, NULL) = 0
[pid  2899] prctl(PR_SET_NAME, "async-io") = 0
[pid  2899] futex(0x7f493d677cb4, FUTEX_WAIT_PRIVATE, 2, {tv_sec=0, tv_nsec=49460}strace: Process 2898 attached
 <unfinished ...>
[pid  2898] rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
[pid  2899] <... futex resumed>)        = -1 ETIMEDOUT (Operation timed out)
[pid  2899] futex(0x7f493d677cb4, FUTEX_WAIT_PRIVATE, 2, {tv_sec=0, tv_nsec=74860} <unfinished ...>
[pid  2898] sigaltstack(NULL, {ss_sp=NULL, ss_flags=SS_DISABLE, ss_size=0}) = 0
[pid  2898] mmap(NULL, 12288, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f493d470000
[pid  2898] mprotect(0x7f493d470000, 4096, PROT_NONE) = 0
[pid  2899] <... futex resumed>)        = -1 ETIMEDOUT (Operation timed out)
[pid  2899] futex(0x7f493d677cb4, FUTEX_WAIT_PRIVATE, 2, {tv_sec=0, tv_nsec=99936} <unfinished ...>
[pid  2898] sigaltstack({ss_sp=0x7f493d471000, ss_flags=0, ss_size=8192}, NULL) = 0
[pid  2898] prctl(PR_SET_NAME, "async-std/runti"...) = 0
[pid  2898] brk(0x555555f12000)         = 0x555555f12000
[pid  2898] brk(0x555555f15000 <unfinished ...>
[pid  2899] <... futex resumed>)        = -1 ETIMEDOUT (Operation timed out)
[pid  2899] futex(0x7f493d677cb4, FUTEX_WAIT_PRIVATE, 2, {tv_sec=0, tv_nsec=249874} <unfinished ...>
[pid  2898] <... brk resumed>)          = 0x555555f15000
[pid  2898] mmap(NULL, 2109440, PROT_NONE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f493d26d000
[pid  2898] mprotect(0x7f493d26f000, 2101248, PROT_READ|PROT_WRITE) = 0
[pid  2898] rt_sigprocmask(SIG_BLOCK, ~[RTMIN RT_1 RT_2], [], 8) = 0
[pid  2898] clone(child_stack=0x7f493d46f968, flags=CLONE_VM|CLONE_FS|CLONE_FILES|CLONE_SIGHAND|CLONE_THREAD|CLONE_SYSVSEM|CLONE_SETTLS|CLONE_PARENT_SETTID|CLONE_CHILD_CLEARTID|0x400000, parent_tid=[2900], tls=0x7f493d46fb20, child_tidptr=0x7f493da20f40) = 2900
[pid  2899] <... futex resumed>)        = -1 ETIMEDOUT (Operation timed out)
[pid  2899] futex(0x7f493d677cb4, FUTEX_WAIT_PRIVATE, 2, {tv_sec=0, tv_nsec=499865} <unfinished ...>
[pid  2898] rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
[pid  2898] futex(0x7f493d879e34, FUTEX_WAIT_PRIVATE, 2, NULLstrace: Process 2900 attached
 <unfinished ...>
[pid  2900] rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
[pid  2900] sigaltstack(NULL, {ss_sp=NULL, ss_flags=SS_DISABLE, ss_size=0}) = 0
[pid  2900] mmap(NULL, 12288, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f493d26a000
[pid  2900] mprotect(0x7f493d26a000, 4096, PROT_NONE) = 0
[pid  2900] sigaltstack({ss_sp=0x7f493d26b000, ss_flags=0, ss_size=8192}, NULL) = 0
[pid  2900] prctl(PR_SET_NAME, "blocking-1") = 0
[pid  2900] open("foo.txt", O_WRONLY|O_CREAT|O_CLOEXEC, 0666) = 6
[pid  2900] fcntl(6, F_SETFD, FD_CLOEXEC) = 0
[pid  2900] futex(0x7f493d879e34, FUTEX_WAKE_PRIVATE, 1) = 1
[pid  2898] <... futex resumed>)        = 0
[pid  2898] mmap(NULL, 8392704, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0 <unfinished ...>
[pid  2899] <... futex resumed>)        = -1 ETIMEDOUT (Operation timed out)
[pid  2899] futex(0x7f493d677cb4, FUTEX_WAIT_PRIVATE, 2, {tv_sec=0, tv_nsec=749860} <unfinished ...>
[pid  2898] <... mmap resumed>)         = 0x7f493ca69000
[pid  2898] mmap(NULL, 2109440, PROT_NONE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f493c866000
[pid  2898] mprotect(0x7f493c868000, 2101248, PROT_READ|PROT_WRITE) = 0
[pid  2898] rt_sigprocmask(SIG_BLOCK, ~[RTMIN RT_1 RT_2], [], 8) = 0
[pid  2898] clone(child_stack=0x7f493ca68968, flags=CLONE_VM|CLONE_FS|CLONE_FILES|CLONE_SIGHAND|CLONE_THREAD|CLONE_SYSVSEM|CLONE_SETTLS|CLONE_PARENT_SETTID|CLONE_CHILD_CLEARTID|0x400000, parent_tid=[2901], tls=0x7f493ca68b20, child_tidptr=0x7f493da20f40) = 2901
[pid  2898] rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
[pid  2898] write(2, "before drop\n", 12before drop
) = 12
[pid  2898] write(2, "after drop\n", 11after drop
) = 11
[pid  2898] write(4, "\1\0\0\0\0\0\0\0", 8 <unfinished ...>
[pid  2897] <... epoll_pwait resumed>[{EPOLLIN, {u32=4294967295, u64=18446744073709551615}}], 1000, -1, NULL, 8) = 1
[pid  2898] <... write resumed>)        = 8
[pid  2897] read(4,  <unfinished ...>
[pid  2898] futex(0x7f493d879e34, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...>
[pid  2897] <... read resumed>"\1\0\0\0\0\0\0\0", 8) = 8
[pid  2897] epoll_ctl(3, EPOLL_CTL_MOD, 4, {EPOLLIN|EPOLLPRI|EPOLLERR|EPOLLHUP|EPOLLRDHUP|EPOLLONESHOT, {u32=4294967295, u64=18446744073709551615}}) = 0
[pid  2897] futex(0x7f493d677cb4, FUTEX_WAKE_PRIVATE, 1) = 1
[pid  2899] <... futex resumed>)        = 0
[pid  2897] sigaltstack({ss_sp=NULL, ss_flags=SS_DISABLE, ss_size=8192},  <unfinished ...>
[pid  2899] timerfd_settime(5, 0, {it_interval={tv_sec=0, tv_nsec=0}, it_value={tv_sec=0, tv_nsec=0}},  <unfinished ...>
[pid  2897] <... sigaltstack resumed>NULL) = 0
[pid  2899] <... timerfd_settime resumed>NULL) = 0
[pid  2897] munmap(0x7f493d87c000, 12288 <unfinished ...>
[pid  2899] epoll_ctl(3, EPOLL_CTL_MOD, 5, {EPOLLIN|EPOLLPRI|EPOLLERR|EPOLLHUP|EPOLLRDHUP|EPOLLONESHOT, {u32=4294967295, u64=18446744073709551615}} <unfinished ...>
[pid  2897] <... munmap resumed>)       = 0
[pid  2899] <... epoll_ctl resumed>)    = 0
[pid  2897] exit_group(0 <unfinished ...>
[pid  2899] exit_group(0 <unfinished ...>
[pid  2897] <... exit_group resumed>)   = ?
[pid  2899] +++ exited with 0 +++
[pid  2898] <... futex resumed>)        = ?
[pid  2898] +++ exited with 0 +++
[pid  2900] +++ exited with 0 +++
strace: Process 2901 attached
[pid  2901] +++ exited with 0 +++
+++ exited with 0 +++

@link2xt
Copy link
Author

link2xt commented Oct 26, 2020 •
edited
Loading

But async_fs::OpenOptions doesn't implement Drop at all, so it just doesn't trigger the bug. I'm not sure what this experiment shows.

Also, with async_fs the file is empty, there is no write("foobarbaz") syscall in strace output, the file is simply never written.

@link2xt
Copy link
Author

link2xt commented Oct 26, 2020

On Debian, the file is written even with async_fs::OpenOptions.

@link2xt
Copy link
Author

link2xt commented Aug 1, 2021

Probably related problem, cargo gets stuck compiling a package on a GitLab runner running under QEMU: https://gitlab.alpinelinux.org/alpine/aports/-/merge_requests/23790

@harmic
Copy link

harmic commented Jun 27, 2022

I had a case of this today. It occurred in a VM running under Virtualbox, running Rocky Linux 8.

The application I was testing is quite complex, the relevant bit has async tasks which are reading from TCP sockets, processing what they read, and writing the results to a file.

The VM was configured with two CPUs, so there were 2 async runtime threads. Each time I observed it, both runtime threads were stuck trying to drop async_std::fs::File instances. That seemed a little strange, although I can't be sure there were no cases where only one of the threads got stuck - obviously it was more obvious when they both get stuck because the whole application grinds to a halt.

Adding a flush() call just before dropping the file does seem to have fixed it. Interestingly, the test program above did not trigger a problem for me.

There definitely needs to be some documentation about this - I wasted a huge amount of time trying to debug this before stumbling across this ticket.

@link2xt
Copy link
Author

link2xt commented Jun 27, 2022 •
edited
Loading

I think the problem is in Drop implementation calling async flush. poll_flush then tries to spawn another task and wait for its completion, calling poll_drain in turn and so on, and this is likely where we deadlock. Instead of calling async flush, flush() should be implemented using only blocking operations instead of calling this:
https://github.com/async-rs/async-std/blob/11196c853dc42e86d608c4ed29af1a8f0c5c5084/src/fs/file.rs#L841-L861=

In other words, just self.file.write_all(self.cache) (add & and * where needed) directly and do nothing else.

@harmic
Copy link

harmic commented Jun 29, 2022

This makes perfect sense.

You would need to have at least N+1 runtime threads in order to be able to drop N Files simultaneously - which explains why most cases of this have been seen in QEMU or VMs since they would be likely to have few CPUs.

One thing I do not understand though: when I configure my VM with 1 CPU, or instruct async_std to create one runtime thread via ASYNC_GLOBAL_EXECUTOR_THREADS, the reproduction program at the top of this ticket does not trigger a hanging for me.

@link2xt link2xt linked a pull request Jul 17, 2022 that will close this issue
Open
@link2xt
Copy link
Author

link2xt commented Jul 17, 2022

I made a fix #1033 but have not really tested it.

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
Projects
None yet
Milestone
No milestone
Development

Successfully merging a pull request may close this issue.

Simplify Drop implementation for File link2xt/async-std
3 participants
@dignifiedquire @harmic @link2xt