Stack overflow when updating from 1.5.1 to 1.5.3

[abr-egn]

A specific test has started failing with a stack overflow in the Rust mongodb driver when using async-std without any code change on our part; I've narrowed down that this happens when the dependency tree includes async-executor 1.5.3, but not when it's pinned to 1.5.1. This can be reproduced by running this test against a replica set topology:

$ cargo test --no-default-features --features tracing-unstable,async-std-runtime test::spec::retryable_writes::run_legacy
    Finished test [unoptimized + debuginfo] target(s) in 0.16s
     Running unittests src/lib.rs (target/debug/deps/mongodb-a10b17d95b5decb5)

running 1 test

thread 'test::spec::retryable_writes::run_legacy' has overflowed its stack
fatal runtime error: stack overflow
error: test failed, to rerun pass `--lib`

Caused by:
  process didn't exit successfully: `/Users/abraham.egnor/src/mongo-rust-driver/debug_stack-overflow-async-executor/target/debug/deps/mongodb-a10b17d95b5decb5 'test::spec::retryable_writes::run_legacy'` (signal: 6, SIGABRT: process abort signal)

Unfortunately, I haven't had much success constructing a minimal reproduction - I strongly suspect some badly-behaved unsafe code is at the root of this, since changes that affect memory layout (unrelated struct fields) have caused this behavior to unpredictably fail to occur. Let me know if there's more information I can provide that would be useful!

[abr-egn]

Update: it's a little easier to reproduce in that it doesn't actually need a mongodb deployment. Running

MONGODB_URI=mongodb://localhost:27017,localhost:27018,localhost:27019/?replicaSet=replset cargo test --no-default-features --features tracing-unstable,async-std-runtime test::spec::retryable_writes::run_legacy

triggers the behavior without needing a test instance.

[notgull]

No time to check this at the moment. My best guess is that some function is calling itself recursively, as this crate shouldn't use that much stack space.

Do you have more information on where, exactly, this stack overflow occurs? Knowing the conditions that cause this would go a long way towards figuring out what was added that went wrong.

[abr-egn]

There's no recursion involved, and it's worth noting that the same test runs under tokio with no issues. Where exactly the error happens depends on the presence of debugging statements; without them, the lldb stacktrace is below. ClientOptions::validate is an entirely innocuous method and AFAICT the failure happens on method invocation rather than anywhere in the method body.

* thread #2, name = 'test::spec::retryable_writes::run_legacy', stop reason = EXC_BAD_ACCESS (code=2, address=0x16fe03460)
  * frame #0: 0x0000000101e7735c mongodb-a10b17d95b5decb5`mongodb::client::options::ClientOptions::validate::h3698939ebd5ca72f(self=0x0000000000000000) at options.rs:1352
    frame #1: 0x000000010034009c mongodb-a10b17d95b5decb5`mongodb::client::Client::with_options::hc75751b2a7e6c453(options=<unavailable>) at client.rs:175:9
    frame #2: 0x0000000100c1cf34 mongodb-a10b17d95b5decb5`mongodb::test::util::TestClientBuilder::build::_$u7b$$u7b$closure$u7d$$u7d$::h39ba7b807873de6a((null)=0x000000016ff0ffa8) at util.rs:162:22
    frame #3: 0x0000000100c1df2c mongodb-a10b17d95b5decb5`mongodb::test::util::TestClient::with_handler::_$u7b$$u7b$closure$u7d$$u7d$::h11935a41a72f7220((null)=0x000000016ff0ffa8) at util.rs:190:13
    frame #4: 0x0000000100c1db4c mongodb-a10b17d95b5decb5`mongodb::test::util::TestClient::with_options::_$u7b$$u7b$closure$u7d$$u7d$::hedfe293a1f943789((null)=0x000000016ff0ffa8) at util.rs:179:42
    frame #5: 0x0000000100c1d5e8 mongodb-a10b17d95b5decb5`mongodb::test::util::TestClient::new::_$u7b$$u7b$closure$u7d$$u7d$::hbab8e983695e1f3a((null)=0x000000016ff0ffa8) at util.rs:175:33
    frame #6: 0x0000000100c24200 mongodb-a10b17d95b5decb5`mongodb::test::util::TestClient::options_for_multiple_mongoses::_$u7b$$u7b$closure$u7d$$u7d$::he99754558aa188c4((null)=0x000000016ff0ffa8) at util.rs:492:23
    frame #7: 0x0000000100c1b444 mongodb-a10b17d95b5decb5`mongodb::test::util::TestClientBuilder::additional_options::_$u7b$$u7b$closure$u7d$$u7d$::h495c664ce8b540fe((null)=0x000000016ff0ffa8) at util.rs:106:91
    frame #8: 0x0000000100e40734 mongodb-a10b17d95b5decb5`mongodb::test::util::event::EventClient::with_additional_options::_$u7b$$u7b$closure$u7d$$u7d$::h613c8e390f6876c1((null)=0x000000016ff0ffa8) at event.rs:596:13
    frame #9: 0x0000000100e52a00 mongodb-a10b17d95b5decb5`mongodb::test::spec::retryable_writes::run_legacy::_$u7b$$u7b$closure$u7d$$u7d$::run_test::_$u7b$$u7b$closure$u7d$$u7d$::ha71e50e5fbf076aa((null)=0x000000016ff0ffa8) at retryable_writes.rs:67:13
    frame #10: 0x0000000100171a7c mongodb-a10b17d95b5decb5`mongodb::test::spec::run_spec_test::_$u7b$$u7b$closure$u7d$$u7d$::h25fea61415888c71((null)=0x000000016ff0ffa8) at spec.rs:120:33
    frame #11: 0x0000000100e5150c mongodb-a10b17d95b5decb5`mongodb::test::spec::retryable_writes::run_legacy::_$u7b$$u7b$closure$u7d$$u7d$::h3bb181efa10fdf1e((null)=0x000000016ff0ffa8) at retryable_writes.rs:182:61
    frame #12: 0x0000000100c85990 mongodb-a10b17d95b5decb5`_$LT$async_std..task..builder..SupportTaskLocals$LT$F$GT$$u20$as$u20$core..future..future..Future$GT$::poll::_$u7b$$u7b$closure$u7d$$u7d$::hec4dd5341b2cf89c at builder.rs:199:17
    frame #13: 0x00000001016a666c mongodb-a10b17d95b5decb5`async_std::task::task_locals_wrapper::TaskLocalsWrapper::set_current::_$u7b$$u7b$closure$u7d$$u7d$::h9dea79d5e64449b7(current=0x0000000107e09888) at task_locals_wrapper.rs:60:13
    frame #14: 0x000000010059a880 mongodb-a10b17d95b5decb5`std::thread::local::LocalKey$LT$T$GT$::try_with::h8da93a7c5b713c7e(self=0x00000001039f52a8, f={closure_env#0}<async_std::task::builder::{impl#1}::poll::{closure_env#0}<mongodb::test::spec::retryable_writes::run_legacy::{async_block_env#0}>, core::task::poll::Poll<()>> @ 0x000000016fe59818) at local.rs:252:16
    frame #15: 0x0000000100498b54 mongodb-a10b17d95b5decb5`std::thread::local::LocalKey$LT$T$GT$::with::h31dcfd38d115aca6(self=0x00000001039f52a8, f=<unavailable>) at local.rs:228:9
    frame #16: 0x000000010168d114 mongodb-a10b17d95b5decb5`async_std::task::task_locals_wrapper::TaskLocalsWrapper::set_current::hf90a361463ab1ab2(task=0x000000016ff15598, f={closure_env#0}<mongodb::test::spec::retryable_writes::run_legacy::{async_block_env#0}> @ 0x000000016fe59830) at task_locals_wrapper.rs:55:9
    frame #17: 0x0000000100c7bb70 mongodb-a10b17d95b5decb5`_$LT$async_std..task..builder..SupportTaskLocals$LT$F$GT$$u20$as$u20$core..future..future..Future$GT$::poll::h6f0b3d4e94f4fdd9(self=Pin<&mut async_std::task::builder::SupportTaskLocals<mongodb::test::spec::retryable_writes::run_legacy::{async_block_env#0}>> @ 0x000000016fe59860, cx=0x000000016ff0ffa8) at builder.rs:197:13
    frame #18: 0x00000001003345b4 mongodb-a10b17d95b5decb5`_$LT$futures_lite..future..Or$LT$F1$C$F2$GT$$u20$as$u20$core..future..future..Future$GT$::poll::h522f60ff187db0e8(self=Pin<&mut futures_lite::future::Or<async_std::task::builder::SupportTaskLocals<mongodb::test::spec::retryable_writes::run_legacy::{async_block_env#0}>, async_executor::{impl#5}::run::{async_fn#0}::{async_block#0}::{async_block_env#0}<(), async_std::task::builder::SupportTaskLocals<mongodb::test::spec::retryable_writes::run_legacy::{async_block_env#0}>>>> @ 0x000000016fe598a8, cx=0x000000016ff0ffa8) at future.rs:526:33
    frame #19: 0x000000010147e8a0 mongodb-a10b17d95b5decb5`async_executor::Executor::run::_$u7b$$u7b$closure$u7d$$u7d$::_$u7b$$u7b$closure$u7d$$u7d$::h96ccbf4d7b86d9e4((null)=0x000000016ff0ffa8) at lib.rs:255:39
    frame #20: 0x000000010135b50c mongodb-a10b17d95b5decb5`async_executor::LocalQueue::with::_$LT$impl$u20$async_executor..LocalQueue$GT$::set::_$u7b$$u7b$closure$u7d$$u7d$::_$u7b$$u7b$closure$u7d$$u7d$::h91a2291f3ed078a2(cx=0x000000016ff0ffa8) at lib.rs:934:21
    frame #21: 0x00000001003274e0 mongodb-a10b17d95b5decb5`_$LT$futures_lite..future..PollFn$LT$F$GT$$u20$as$u20$core..future..future..Future$GT$::poll::h3b6318fc8b1381a8(self=Pin<&mut futures_lite::future::PollFn<async_executor::{impl#19}::with::{impl#0}::set::{async_fn#0}::{closure_env#2}<async_executor::{impl#5}::run::{async_fn#0}::{async_block_env#0}<(), async_std::task::builder::SupportTaskLocals<mongodb::test::spec::retryable_writes::run_legacy::{async_block_env#0}>>>>> @ 0x000000016fe69b90, cx=0x000000016ff0ffa8) at future.rs:246:9
    frame #22: 0x000000010133eb80 mongodb-a10b17d95b5decb5`async_executor::LocalQueue::with::_$LT$impl$u20$async_executor..LocalQueue$GT$::set::_$u7b$$u7b$closure$u7d$$u7d$::hce181efcb9e82fff((null)=0x000000016ff0ffa8) at lib.rs:936:17
    frame #23: 0x00000001014149f8 mongodb-a10b17d95b5decb5`async_executor::Executor::run::_$u7b$$u7b$closure$u7d$$u7d$::h1b574227a73cd340((null)=0x000000016ff0ffa8) at lib.rs:258:9
    frame #24: 0x00000001013dc698 mongodb-a10b17d95b5decb5`async_executor::LocalExecutor::run::_$u7b$$u7b$closure$u7d$$u7d$::h57313a5a84eb831c((null)=0x000000016ff0ffa8) at lib.rs:482:33
    frame #25: 0x00000001018d691c mongodb-a10b17d95b5decb5`async_io::driver::block_on::h56926a759835b36a(future={async_fn_env#0}<(), async_std::task::builder::SupportTaskLocals<mongodb::test::spec::retryable_writes::run_legacy::{async_block_env#0}>> @ 0x000000016ff3b078) at driver.rs:146:33
    frame #26: 0x0000000100c2f158 mongodb-a10b17d95b5decb5`async_global_executor::reactor::block_on::_$u7b$$u7b$closure$u7d$$u7d$::hdf3ccc6825e52a61 at reactor.rs:3:18
    frame #27: 0x0000000100c280a0 mongodb-a10b17d95b5decb5`async_global_executor::reactor::block_on::h915a3da7b653e640(future=<unavailable>) at reactor.rs:12:5
    frame #28: 0x00000001006aa42c mongodb-a10b17d95b5decb5`async_global_executor::executor::block_on::_$u7b$$u7b$closure$u7d$$u7d$::hdac5a498f63cf02d(executor=0x0000000107e098f0) at executor.rs:26:36
    frame #29: 0x000000010060b148 mongodb-a10b17d95b5decb5`std::thread::local::LocalKey$LT$T$GT$::try_with::hd81a02c323ec4d2b(self=0x00000001039d00a8, f={closure_env#0}<async_std::task::builder::SupportTaskLocals<mongodb::test::spec::retryable_writes::run_legacy::{async_block_env#0}>, ()> @ 0x000000016ffc6308) at local.rs:252:16
    frame #30: 0x00000001004ae5e4 mongodb-a10b17d95b5decb5`std::thread::local::LocalKey$LT$T$GT$::with::h9b5141a4bc5f6752(self=0x00000001039d00a8, f=<unavailable>) at local.rs:228:9
    frame #31: 0x00000001006a3290 mongodb-a10b17d95b5decb5`async_global_executor::executor::block_on::hf93e1d178c3537f1(future=<unavailable>) at executor.rs:26:5
    frame #32: 0x0000000100d05d0c mongodb-a10b17d95b5decb5`async_std::task::builder::Builder::blocking::_$u7b$$u7b$closure$u7d$$u7d$::_$u7b$$u7b$closure$u7d$$u7d$::h1ac1371d8f50fa58 at builder.rs:171:25
    frame #33: 0x00000001016b44e8 mongodb-a10b17d95b5decb5`async_std::task::task_locals_wrapper::TaskLocalsWrapper::set_current::_$u7b$$u7b$closure$u7d$$u7d$::hef899cc3053256aa(current=0x0000000107e09888) at task_locals_wrapper.rs:60:13
    frame #34: 0x00000001005bd950 mongodb-a10b17d95b5decb5`std::thread::local::LocalKey$LT$T$GT$::try_with::ha43271e2799f665b(self=0x00000001039f52a8, f={closure_env#0}<async_std::task::builder::{impl#0}::blocking::{closure#0}::{closure_env#0}<mongodb::test::spec::retryable_writes::run_legacy::{async_block_env#0}, ()>, ()> @ 0x000000016ffe0fa0) at local.rs:252:16
    frame #35: 0x00000001004bdd94 mongodb-a10b17d95b5decb5`std::thread::local::LocalKey$LT$T$GT$::with::he32961adc200664a(self=0x00000001039f52a8, f=<unavailable>) at local.rs:228:9
    frame #36: 0x000000010168b36c mongodb-a10b17d95b5decb5`async_std::task::task_locals_wrapper::TaskLocalsWrapper::set_current::hd2ce50586b587450(task=0x000000016fff1078, f=<unavailable>) at task_locals_wrapper.rs:55:9
    frame #37: 0x0000000100cf6578 mongodb-a10b17d95b5decb5`async_std::task::builder::Builder::blocking::_$u7b$$u7b$closure$u7d$$u7d$::h71824fc3851a4733(num_nested_blocking=0x0000000107e098a0) at builder.rs:168:17
    frame #38: 0x0000000100588760 mongodb-a10b17d95b5decb5`std::thread::local::LocalKey$LT$T$GT$::try_with::h8152777cab3917e9(self=0x00000001039de4e8, f={closure_env#0}<mongodb::test::spec::retryable_writes::run_legacy::{async_block_env#0}, ()> @ 0x000000016fff67a0) at local.rs:252:16
    frame #39: 0x00000001004ae67c mongodb-a10b17d95b5decb5`std::thread::local::LocalKey$LT$T$GT$::with::h9b86516b56a680a3(self=0x00000001039de4e8, f=<unavailable>) at local.rs:228:9
    frame #40: 0x0000000100cc781c mongodb-a10b17d95b5decb5`async_std::task::builder::Builder::blocking::h4b284a324e04c107(self=<unavailable>, future=<unavailable>) at builder.rs:161:9
    frame #41: 0x0000000100041d94 mongodb-a10b17d95b5decb5`async_std::task::block_on::block_on::h18e3242f729f3d3d(future={async_block_env#0} @ 0x00000001700012b0) at block_on.rs:33:5
    frame #42: 0x0000000100007aa4 mongodb-a10b17d95b5decb5`mongodb::test::spec::retryable_writes::run_legacy::hc4492bf4de762541 at retryable_writes.rs:48:43
    frame #43: 0x0000000100e51364 mongodb-a10b17d95b5decb5`mongodb::test::spec::retryable_writes::run_legacy::_$u7b$$u7b$closure$u7d$$u7d$::h967cf87614397f42((null)=0x000000017000681e) at retryable_writes.rs:48:43
    frame #44: 0x0000000100ff168c mongodb-a10b17d95b5decb5`core::ops::function::FnOnce::call_once::h471fa604b173f74c((null)={closure_env#0} @ 0x000000017000681e, (null)=<unavailable>) at function.rs:250:5
    frame #45: 0x00000001022a90a8 mongodb-a10b17d95b5decb5`test::__rust_begin_short_backtrace::h8906971520158b86 [inlined] core::ops::function::FnOnce::call_once::hf57ab7414346cd3e at function.rs:250:5 [opt]
    frame #46: 0x00000001022a90a0 mongodb-a10b17d95b5decb5`test::__rust_begin_short_backtrace::h8906971520158b86 at lib.rs:655:18 [opt]
    frame #47: 0x00000001022a80d8 mongodb-a10b17d95b5decb5`test::run_test::run_test_inner::_$u7b$$u7b$closure$u7d$$u7d$::h3c1fd2f20901e638 [inlined] _$LT$alloc..boxed..Box$LT$F$C$A$GT$$u20$as$u20$core..ops..function..FnOnce$LT$Args$GT$$GT$::call_once::h11f245024fa107de at boxed.rs:1973:9 [opt]
    frame #48: 0x00000001022a80c8 mongodb-a10b17d95b5decb5`test::run_test::run_test_inner::_$u7b$$u7b$closure$u7d$$u7d$::h3c1fd2f20901e638 [inlined] _$LT$core..panic..unwind_safe..AssertUnwindSafe$LT$F$GT$$u20$as$u20$core..ops..function..FnOnce$LT$$LP$$RP$$GT$$GT$::call_once::h63f566e6242f22d7 at unwind_safe.rs:271:9 [opt]
    frame #49: 0x00000001022a80c8 mongodb-a10b17d95b5decb5`test::run_test::run_test_inner::_$u7b$$u7b$closure$u7d$$u7d$::h3c1fd2f20901e638 [inlined] std::panicking::try::do_call::ha521304254b2b8a6 at panicking.rs:485:40 [opt]
    frame #50: 0x00000001022a80c8 mongodb-a10b17d95b5decb5`test::run_test::run_test_inner::_$u7b$$u7b$closure$u7d$$u7d$::h3c1fd2f20901e638 [inlined] std::panicking::try::h781279c66bc65dea at panicking.rs:449:19 [opt]
    frame #51: 0x00000001022a80c8 mongodb-a10b17d95b5decb5`test::run_test::run_test_inner::_$u7b$$u7b$closure$u7d$$u7d$::h3c1fd2f20901e638 [inlined] std::panic::catch_unwind::h62f2c0243d7355ff at panic.rs:140:14 [opt]
    frame #52: 0x00000001022a80c8 mongodb-a10b17d95b5decb5`test::run_test::run_test_inner::_$u7b$$u7b$closure$u7d$$u7d$::h3c1fd2f20901e638 [inlined] test::run_test_in_process::h8be0dc8553a2d668 at lib.rs:678:27 [opt]
    frame #53: 0x00000001022a8058 mongodb-a10b17d95b5decb5`test::run_test::run_test_inner::_$u7b$$u7b$closure$u7d$$u7d$::h3c1fd2f20901e638 at lib.rs:572:39 [opt]
    frame #54: 0x000000010227ae84 mongodb-a10b17d95b5decb5`std::sys_common::backtrace::__rust_begin_short_backtrace::h01f0c6c7a98e3e15 [inlined] test::run_test::run_test_inner::_$u7b$$u7b$closure$u7d$$u7d$::ha0406b263a72cd5b at lib.rs:599:37 [opt]
    frame #55: 0x000000010227adf8 mongodb-a10b17d95b5decb5`std::sys_common::backtrace::__rust_begin_short_backtrace::h01f0c6c7a98e3e15 at backtrace.rs:134:18 [opt]
    frame #56: 0x000000010227f938 mongodb-a10b17d95b5decb5`core::ops::function::FnOnce::call_once$u7b$$u7b$vtable.shim$u7d$$u7d$::hf7dcd4587efbbfa3 [inlined] std::thread::Builder::spawn_unchecked_::_$u7b$$u7b$closure$u7d$$u7d$::_$u7b$$u7b$closure$u7d$$u7d$::h160acb161c6a735a at mod.rs:526:17 [opt]
    frame #57: 0x000000010227f930 mongodb-a10b17d95b5decb5`core::ops::function::FnOnce::call_once$u7b$$u7b$vtable.shim$u7d$$u7d$::hf7dcd4587efbbfa3 [inlined] _$LT$core..panic..unwind_safe..AssertUnwindSafe$LT$F$GT$$u20$as$u20$core..ops..function..FnOnce$LT$$LP$$RP$$GT$$GT$::call_once::h9ccec8dfc8841d99 at unwind_safe.rs:271:9 [opt]
    frame #58: 0x000000010227f930 mongodb-a10b17d95b5decb5`core::ops::function::FnOnce::call_once$u7b$$u7b$vtable.shim$u7d$$u7d$::hf7dcd4587efbbfa3 [inlined] std::panicking::try::do_call::h554d349d895c285b at panicking.rs:485:40 [opt]
    frame #59: 0x000000010227f930 mongodb-a10b17d95b5decb5`core::ops::function::FnOnce::call_once$u7b$$u7b$vtable.shim$u7d$$u7d$::hf7dcd4587efbbfa3 [inlined] std::panicking::try::hafe9b48954d647a5 at panicking.rs:449:19 [opt]
    frame #60: 0x000000010227f930 mongodb-a10b17d95b5decb5`core::ops::function::FnOnce::call_once$u7b$$u7b$vtable.shim$u7d$$u7d$::hf7dcd4587efbbfa3 [inlined] std::panic::catch_unwind::h05668823152b5e98 at panic.rs:140:14 [opt]
    frame #61: 0x000000010227f930 mongodb-a10b17d95b5decb5`core::ops::function::FnOnce::call_once$u7b$$u7b$vtable.shim$u7d$$u7d$::hf7dcd4587efbbfa3 [inlined] std::thread::Builder::spawn_unchecked_::_$u7b$$u7b$closure$u7d$$u7d$::ha9617bcc6788886f at mod.rs:525:30 [opt]
    frame #62: 0x000000010227f8cc mongodb-a10b17d95b5decb5`core::ops::function::FnOnce::call_once$u7b$$u7b$vtable.shim$u7d$$u7d$::hf7dcd4587efbbfa3 at function.rs:250:5 [opt]
    frame #63: 0x0000000102a1cafc mongodb-a10b17d95b5decb5`std::sys::unix::thread::Thread::new::thread_start::h7f56b35fafcfec87 [inlined] _$LT$alloc..boxed..Box$LT$F$C$A$GT$$u20$as$u20$core..ops..function..FnOnce$LT$Args$GT$$GT$::call_once::hd96d02f907263858 at boxed.rs:1973:9 [opt]
    frame #64: 0x0000000102a1caf0 mongodb-a10b17d95b5decb5`std::sys::unix::thread::Thread::new::thread_start::h7f56b35fafcfec87 [inlined] _$LT$alloc..boxed..Box$LT$F$C$A$GT$$u20$as$u20$core..ops..function..FnOnce$LT$Args$GT$$GT$::call_once::hfd80494da4543cfb at boxed.rs:1973:9 [opt]
    frame #65: 0x0000000102a1caec mongodb-a10b17d95b5decb5`std::sys::unix::thread::Thread::new::thread_start::h7f56b35fafcfec87 at thread.rs:108:17 [opt]
    frame #66: 0x00000001a460ffa8 libsystem_pthread.dylib`_pthread_start + 148

[notgull]

Interestingly Box::pin on the run_spec_test future fixes this issue. But run_spec_test is around 40k bytes, which is still way under the 8 MB limit. Maybe the stack space is being multiplied somehow?

[notgull]

It seems like Executor::run adds around 700 bytes to the future. Which is still a lot, but that makes my working theory that those 700 bytes were just the straw that broke the camel's back?

[taiki-e]

The issue appears in both debug and release mode.

In that case, it is unlikely to be related to this issue (stack overflow). I've opened a #57 to track the issue you are encountering.