tracing-test
tracing-test copied to clipboard
dbrgn
panic with tokio_unstable
I just enabled tokio_unstable in my application and I see tests that make use of logs_contain are now panicking.
Here is the line at which the code panicked in my code:
assert!(logs_contain(
"invalid return status code: 500 Internal Server Error"
));
And here is the full backtrace from the panic:
thread 'search::tests::test_one_search_returns_500' panicked at src/search.rs:1544:9:
assertion failed: logs_contain("invalid return status code: 500 Internal Server Error")
stack backtrace:
0: 0x560c374857b6 - std::backtrace_rs::backtrace::libunwind::trace::h0c16a9a5fd0ce731
at /rustc/25ef9e3d85d934b27d9dada2f9dd52b1dc63bb04/library/std/src/../../backtrace/src/backtrace/libunwind.rs:104:5
1: 0x560c374857b6 - std::backtrace_rs::backtrace::trace_unsynchronized::h6083a17e5cdc8f46
at /rustc/25ef9e3d85d934b27d9dada2f9dd52b1dc63bb04/library/std/src/../../backtrace/src/backtrace/mod.rs:66:5
2: 0x560c374857b6 - std::sys_common::backtrace::_print_fmt::h6e3aa6aae5040d41
at /rustc/25ef9e3d85d934b27d9dada2f9dd52b1dc63bb04/library/std/src/sys_common/backtrace.rs:68:5
3: 0x560c374857b6 - <std::sys_common::backtrace::_print::DisplayBacktrace as core::fmt::Display>::fmt::h1d77460a0cf9e8ca
at /rustc/25ef9e3d85d934b27d9dada2f9dd52b1dc63bb04/library/std/src/sys_common/backtrace.rs:44:22
4: 0x560c374b6170 - core::fmt::rt::Argument::fmt::hb6935a4fe5049635
at /rustc/25ef9e3d85d934b27d9dada2f9dd52b1dc63bb04/library/core/src/fmt/rt.rs:142:9
5: 0x560c374b6170 - core::fmt::write::h9154f2c2c3250acc
at /rustc/25ef9e3d85d934b27d9dada2f9dd52b1dc63bb04/library/core/src/fmt/mod.rs:1120:17
6: 0x560c3748199f - std::io::Write::write_fmt::h6839d4aa333e3013
at /rustc/25ef9e3d85d934b27d9dada2f9dd52b1dc63bb04/library/std/src/io/mod.rs:1846:15
7: 0x560c37485594 - std::sys_common::backtrace::_print::h400cc0cd14952063
at /rustc/25ef9e3d85d934b27d9dada2f9dd52b1dc63bb04/library/std/src/sys_common/backtrace.rs:47:5
8: 0x560c37485594 - std::sys_common::backtrace::print::he60b58f54398afb0
at /rustc/25ef9e3d85d934b27d9dada2f9dd52b1dc63bb04/library/std/src/sys_common/backtrace.rs:34:9
9: 0x560c37487307 - std::panicking::default_hook::{{closure}}::ha43dca9f1334df98
10: 0x560c37486fed - std::panicking::default_hook::h3f9cfb4e9e654b5d
at /rustc/25ef9e3d85d934b27d9dada2f9dd52b1dc63bb04/library/std/src/panicking.rs:289:9
11: 0x560c34ea9f47 - <alloc::boxed::Box<F,A> as core::ops::function::Fn<Args>>::call::h3f851ad6e4f45e32
at /rustc/25ef9e3d85d934b27d9dada2f9dd52b1dc63bb04/library/alloc/src/boxed.rs:2029:9
12: 0x560c34ea9f47 - test::test_main::{{closure}}::hd9a9e5d41996e123
at /rustc/25ef9e3d85d934b27d9dada2f9dd52b1dc63bb04/library/test/src/lib.rs:138:21
13: 0x560c37487926 - <alloc::boxed::Box<F,A> as core::ops::function::Fn<Args>>::call::h7b9c1790ed9b9193
at /rustc/25ef9e3d85d934b27d9dada2f9dd52b1dc63bb04/library/alloc/src/boxed.rs:2029:9
14: 0x560c37487926 - std::panicking::rust_panic_with_hook::hca92acdbd4afbd68
at /rustc/25ef9e3d85d934b27d9dada2f9dd52b1dc63bb04/library/std/src/panicking.rs:785:13
15: 0x560c37487639 - std::panicking::begin_panic_handler::{{closure}}::he9552720204f03c7
at /rustc/25ef9e3d85d934b27d9dada2f9dd52b1dc63bb04/library/std/src/panicking.rs:651:13
16: 0x560c37485cb6 - std::sys_common::backtrace::__rust_end_short_backtrace::ha6b7dc707f991d64
at /rustc/25ef9e3d85d934b27d9dada2f9dd52b1dc63bb04/library/std/src/sys_common/backtrace.rs:171:18
17: 0x560c374873c4 - rust_begin_unwind
at /rustc/25ef9e3d85d934b27d9dada2f9dd52b1dc63bb04/library/std/src/panicking.rs:647:5
18: 0x560c347ad565 - core::panicking::panic_fmt::h38be0c5719254657
at /rustc/25ef9e3d85d934b27d9dada2f9dd52b1dc63bb04/library/core/src/panicking.rs:72:14
19: 0x560c347ad623 - core::panicking::panic::h28a279db0e70bd6a
at /rustc/25ef9e3d85d934b27d9dada2f9dd52b1dc63bb04/library/core/src/panicking.rs:144:5
20: 0x560c34b2d8dc - mycrate[c8865fc2c878b7fc]::search::tests::test_one_search_returns_500::{closure#1}
at /workplace/myname/myworkspace/src/myfolder/src/search.rs:1544:9
21: 0x560c34b684c3 - <core[6584200c4e8678d7]::pin::Pin<&mut dyn core[6584200c4e8678d7]::future::future::Future<Output = ()>> as core[6584200c4e8678d7]::future::future::Future>::poll
at /rustc/25ef9e3d85d934b27d9dada2f9dd52b1dc63bb04/library/core/src/future/future.rs:124:9
22: 0x560c34b48ce2 - <tracing[a93014b945c16acc]::instrument::Instrumented<core[6584200c4e8678d7]::pin::Pin<&mut dyn core[6584200c4e8678d7]::future::future::Future<Output = ()>>> as core[6584200c4e8678d7]::future::future::Future>::poll
at /workplace/myname/myworkspace/src/myfolder/build/private/cargo-home/registry/src/-de3412cb74aa8435/tracing-0.1.40/src/instrument.rs:321:9
23: 0x560c34b68506 - <core[6584200c4e8678d7]::pin::Pin<&mut tracing[a93014b945c16acc]::instrument::Instrumented<core[6584200c4e8678d7]::pin::Pin<&mut dyn core[6584200c4e8678d7]::future::future::Future<Output = ()>>>> as core[6584200c4e8678d7]::future::future::Future>::poll
at /rustc/25ef9e3d85d934b27d9dada2f9dd52b1dc63bb04/library/core/src/future/future.rs:124:9
24: 0x560c348abf9c - <tokio[c15b7bb703a3576d]::runtime::scheduler::current_thread::CoreGuard>::block_on::<core[6584200c4e8678d7]::pin::Pin<&mut tracing[a93014b945c16acc]::instrument::Instrumented<core[6584200c4e8678d7]::pin::Pin<&mut dyn core[6584200c4e8678d7]::future::future::Future<Output = ()>>>>>::{closure#0}::{closure#0}::{closure#0}
at /workplace/myname/myworkspace/src/myfolder/build/private/cargo-home/registry/src/-de3412cb74aa8435/tokio-1.37.0/src/runtime/scheduler/current_thread/mod.rs:659:57
25: 0x560c348abeb2 - tokio[c15b7bb703a3576d]::runtime::coop::with_budget::<core[6584200c4e8678d7]::task::poll::Poll<()>, <tokio[c15b7bb703a3576d]::runtime::scheduler::current_thread::CoreGuard>::block_on<core[6584200c4e8678d7]::pin::Pin<&mut tracing[a93014b945c16acc]::instrument::Instrumented<core[6584200c4e8678d7]::pin::Pin<&mut dyn core[6584200c4e8678d7]::future::future::Future<Output = ()>>>>>::{closure#0}::{closure#0}::{closure#0}>
at /workplace/myname/myworkspace/src/myfolder/build/private/cargo-home/registry/src/-de3412cb74aa8435/tokio-1.37.0/src/runtime/coop.rs:107:5
26: 0x560c348abeb2 - tokio[c15b7bb703a3576d]::runtime::coop::budget::<core[6584200c4e8678d7]::task::poll::Poll<()>, <tokio[c15b7bb703a3576d]::runtime::scheduler::current_thread::CoreGuard>::block_on<core[6584200c4e8678d7]::pin::Pin<&mut tracing[a93014b945c16acc]::instrument::Instrumented<core[6584200c4e8678d7]::pin::Pin<&mut dyn core[6584200c4e8678d7]::future::future::Future<Output = ()>>>>>::{closure#0}::{closure#0}::{closure#0}>
at /workplace/myname/myworkspace/src/myfolder/build/private/cargo-home/registry/src/-de3412cb74aa8435/tokio-1.37.0/src/runtime/coop.rs:73:5
27: 0x560c348abeb2 - <tokio[c15b7bb703a3576d]::runtime::scheduler::current_thread::CoreGuard>::block_on::<core[6584200c4e8678d7]::pin::Pin<&mut tracing[a93014b945c16acc]::instrument::Instrumented<core[6584200c4e8678d7]::pin::Pin<&mut dyn core[6584200c4e8678d7]::future::future::Future<Output = ()>>>>>::{closure#0}::{closure#0}
at /workplace/myname/myworkspace/src/myfolder/build/private/cargo-home/registry/src/-de3412cb74aa8435/tokio-1.37.0/src/runtime/scheduler/current_thread/mod.rs:659:25
28: 0x560c348a7c04 - <tokio[c15b7bb703a3576d]::runtime::scheduler::current_thread::Context>::enter::<core[6584200c4e8678d7]::task::poll::Poll<()>, <tokio[c15b7bb703a3576d]::runtime::scheduler::current_thread::CoreGuard>::block_on<core[6584200c4e8678d7]::pin::Pin<&mut tracing[a93014b945c16acc]::instrument::Instrumented<core[6584200c4e8678d7]::pin::Pin<&mut dyn core[6584200c4e8678d7]::future::future::Future<Output = ()>>>>>::{closure#0}::{closure#0}>
at /workplace/myname/myworkspace/src/myfolder/build/private/cargo-home/registry/src/-de3412cb74aa8435/tokio-1.37.0/src/runtime/scheduler/current_thread/mod.rs:404:19
29: 0x560c348ab55f - <tokio[c15b7bb703a3576d]::runtime::scheduler::current_thread::CoreGuard>::block_on::<core[6584200c4e8678d7]::pin::Pin<&mut tracing[a93014b945c16acc]::instrument::Instrumented<core[6584200c4e8678d7]::pin::Pin<&mut dyn core[6584200c4e8678d7]::future::future::Future<Output = ()>>>>>::{closure#0}
at /workplace/myname/myworkspace/src/myfolder/build/private/cargo-home/registry/src/-de3412cb74aa8435/tokio-1.37.0/src/runtime/scheduler/current_thread/mod.rs:658:36
30: 0x560c348ab2f3 - <tokio[c15b7bb703a3576d]::runtime::scheduler::current_thread::CoreGuard>::enter::<<tokio[c15b7bb703a3576d]::runtime::scheduler::current_thread::CoreGuard>::block_on<core[6584200c4e8678d7]::pin::Pin<&mut tracing[a93014b945c16acc]::instrument::Instrumented<core[6584200c4e8678d7]::pin::Pin<&mut dyn core[6584200c4e8678d7]::future::future::Future<Output = ()>>>>>::{closure#0}, core[6584200c4e8678d7]::option::Option<()>>::{closure#0}
at /workplace/myname/myworkspace/src/myfolder/build/private/cargo-home/registry/src/-de3412cb74aa8435/tokio-1.37.0/src/runtime/scheduler/current_thread/mod.rs:737:68
31: 0x560c347e7e25 - <tokio[c15b7bb703a3576d]::runtime::context::scoped::Scoped<tokio[c15b7bb703a3576d]::runtime::scheduler::Context>>::set::<<tokio[c15b7bb703a3576d]::runtime::scheduler::current_thread::CoreGuard>::enter<<tokio[c15b7bb703a3576d]::runtime::scheduler::current_thread::CoreGuard>::block_on<core[6584200c4e8678d7]::pin::Pin<&mut tracing[a93014b945c16acc]::instrument::Instrumented<core[6584200c4e8678d7]::pin::Pin<&mut dyn core[6584200c4e8678d7]::future::future::Future<Output = ()>>>>>::{closure#0}, core[6584200c4e8678d7]::option::Option<()>>::{closure#0}, (alloc[6e42329bfff9709f]::boxed::Box<tokio[c15b7bb703a3576d]::runtime::scheduler::current_thread::Core>, core[6584200c4e8678d7]::option::Option<()>)>
at /workplace/myname/myworkspace/src/myfolder/build/private/cargo-home/registry/src/-de3412cb74aa8435/tokio-1.37.0/src/runtime/context/scoped.rs:40:9
32: 0x560c34809d03 - tokio[c15b7bb703a3576d]::runtime::context::set_scheduler::<(alloc[6e42329bfff9709f]::boxed::Box<tokio[c15b7bb703a3576d]::runtime::scheduler::current_thread::Core>, core[6584200c4e8678d7]::option::Option<()>), <tokio[c15b7bb703a3576d]::runtime::scheduler::current_thread::CoreGuard>::enter<<tokio[c15b7bb703a3576d]::runtime::scheduler::current_thread::CoreGuard>::block_on<core[6584200c4e8678d7]::pin::Pin<&mut tracing[a93014b945c16acc]::instrument::Instrumented<core[6584200c4e8678d7]::pin::Pin<&mut dyn core[6584200c4e8678d7]::future::future::Future<Output = ()>>>>>::{closure#0}, core[6584200c4e8678d7]::option::Option<()>>::{closure#0}>::{closure#0}
at /workplace/myname/myworkspace/src/myfolder/build/private/cargo-home/registry/src/-de3412cb74aa8435/tokio-1.37.0/src/runtime/context.rs:176:26
33: 0x560c34a67492 - <std[f1de64b5245c199f]::thread::local::LocalKey<tokio[c15b7bb703a3576d]::runtime::context::Context>>::try_with::<tokio[c15b7bb703a3576d]::runtime::context::set_scheduler<(alloc[6e42329bfff9709f]::boxed::Box<tokio[c15b7bb703a3576d]::runtime::scheduler::current_thread::Core>, core[6584200c4e8678d7]::option::Option<()>), <tokio[c15b7bb703a3576d]::runtime::scheduler::current_thread::CoreGuard>::enter<<tokio[c15b7bb703a3576d]::runtime::scheduler::current_thread::CoreGuard>::block_on<core[6584200c4e8678d7]::pin::Pin<&mut tracing[a93014b945c16acc]::instrument::Instrumented<core[6584200c4e8678d7]::pin::Pin<&mut dyn core[6584200c4e8678d7]::future::future::Future<Output = ()>>>>>::{closure#0}, core[6584200c4e8678d7]::option::Option<()>>::{closure#0}>::{closure#0}, (alloc[6e42329bfff9709f]::boxed::Box<tokio[c15b7bb703a3576d]::runtime::scheduler::current_thread::Core>, core[6584200c4e8678d7]::option::Option<()>)>
at /rustc/25ef9e3d85d934b27d9dada2f9dd52b1dc63bb04/library/std/src/thread/local.rs:286:16
34: 0x560c34a6722a - <std[f1de64b5245c199f]::thread::local::LocalKey<tokio[c15b7bb703a3576d]::runtime::context::Context>>::with::<tokio[c15b7bb703a3576d]::runtime::context::set_scheduler<(alloc[6e42329bfff9709f]::boxed::Box<tokio[c15b7bb703a3576d]::runtime::scheduler::current_thread::Core>, core[6584200c4e8678d7]::option::Option<()>), <tokio[c15b7bb703a3576d]::runtime::scheduler::current_thread::CoreGuard>::enter<<tokio[c15b7bb703a3576d]::runtime::scheduler::current_thread::CoreGuard>::block_on<core[6584200c4e8678d7]::pin::Pin<&mut tracing[a93014b945c16acc]::instrument::Instrumented<core[6584200c4e8678d7]::pin::Pin<&mut dyn core[6584200c4e8678d7]::future::future::Future<Output = ()>>>>>::{closure#0}, core[6584200c4e8678d7]::option::Option<()>>::{closure#0}>::{closure#0}, (alloc[6e42329bfff9709f]::boxed::Box<tokio[c15b7bb703a3576d]::runtime::scheduler::current_thread::Core>, core[6584200c4e8678d7]::option::Option<()>)>
at /rustc/25ef9e3d85d934b27d9dada2f9dd52b1dc63bb04/library/std/src/thread/local.rs:262:9
35: 0x560c348098e7 - tokio[c15b7bb703a3576d]::runtime::context::set_scheduler::<(alloc[6e42329bfff9709f]::boxed::Box<tokio[c15b7bb703a3576d]::runtime::scheduler::current_thread::Core>, core[6584200c4e8678d7]::option::Option<()>), <tokio[c15b7bb703a3576d]::runtime::scheduler::current_thread::CoreGuard>::enter<<tokio[c15b7bb703a3576d]::runtime::scheduler::current_thread::CoreGuard>::block_on<core[6584200c4e8678d7]::pin::Pin<&mut tracing[a93014b945c16acc]::instrument::Instrumented<core[6584200c4e8678d7]::pin::Pin<&mut dyn core[6584200c4e8678d7]::future::future::Future<Output = ()>>>>>::{closure#0}, core[6584200c4e8678d7]::option::Option<()>>::{closure#0}>
at /workplace/myname/myworkspace/src/myfolder/build/private/cargo-home/registry/src/-de3412cb74aa8435/tokio-1.37.0/src/runtime/context.rs:176:9
36: 0x560c348aaae8 - <tokio[c15b7bb703a3576d]::runtime::scheduler::current_thread::CoreGuard>::enter::<<tokio[c15b7bb703a3576d]::runtime::scheduler::current_thread::CoreGuard>::block_on<core[6584200c4e8678d7]::pin::Pin<&mut tracing[a93014b945c16acc]::instrument::Instrumented<core[6584200c4e8678d7]::pin::Pin<&mut dyn core[6584200c4e8678d7]::future::future::Future<Output = ()>>>>>::{closure#0}, core[6584200c4e8678d7]::option::Option<()>>
at /workplace/myname/myworkspace/src/myfolder/build/private/cargo-home/registry/src/-de3412cb74aa8435/tokio-1.37.0/src/runtime/scheduler/current_thread/mod.rs:737:27
37: 0x560c348aad55 - <tokio[c15b7bb703a3576d]::runtime::scheduler::current_thread::CoreGuard>::block_on::<core[6584200c4e8678d7]::pin::Pin<&mut tracing[a93014b945c16acc]::instrument::Instrumented<core[6584200c4e8678d7]::pin::Pin<&mut dyn core[6584200c4e8678d7]::future::future::Future<Output = ()>>>>>
at /workplace/myname/myworkspace/src/myfolder/build/private/cargo-home/registry/src/-de3412cb74aa8435/tokio-1.37.0/src/runtime/scheduler/current_thread/mod.rs:646:19
38: 0x560c348aae8f - <tokio[c15b7bb703a3576d]::runtime::scheduler::current_thread::CurrentThread>::block_on::<tracing[a93014b945c16acc]::instrument::Instrumented<core[6584200c4e8678d7]::pin::Pin<&mut dyn core[6584200c4e8678d7]::future::future::Future<Output = ()>>>>::{closure#0}
at /workplace/myname/myworkspace/src/myfolder/build/private/cargo-home/registry/src/-de3412cb74aa8435/tokio-1.37.0/src/runtime/scheduler/current_thread/mod.rs:175:28
39: 0x560c348b33ff - tokio[c15b7bb703a3576d]::runtime::context::runtime::enter_runtime::<<tokio[c15b7bb703a3576d]::runtime::scheduler::current_thread::CurrentThread>::block_on<tracing[a93014b945c16acc]::instrument::Instrumented<core[6584200c4e8678d7]::pin::Pin<&mut dyn core[6584200c4e8678d7]::future::future::Future<Output = ()>>>>::{closure#0}, ()>
at /workplace/myname/myworkspace/src/myfolder/build/private/cargo-home/registry/src/-de3412cb74aa8435/tokio-1.37.0/src/runtime/context/runtime.rs:65:16
40: 0x560c348a7a1c - <tokio[c15b7bb703a3576d]::runtime::scheduler::current_thread::CurrentThread>::block_on::<tracing[a93014b945c16acc]::instrument::Instrumented<core[6584200c4e8678d7]::pin::Pin<&mut dyn core[6584200c4e8678d7]::future::future::Future<Output = ()>>>>
at /workplace/myname/myworkspace/src/myfolder/build/private/cargo-home/registry/src/-de3412cb74aa8435/tokio-1.37.0/src/runtime/scheduler/current_thread/mod.rs:167:9
41: 0x560c34d6e08c - <tokio[c15b7bb703a3576d]::runtime::runtime::Runtime>::block_on::<core[6584200c4e8678d7]::pin::Pin<&mut dyn core[6584200c4e8678d7]::future::future::Future<Output = ()>>>
at /workplace/myname/myworkspace/src/myfolder/build/private/cargo-home/registry/src/-de3412cb74aa8435/tokio-1.37.0/src/runtime/runtime.rs:349:47
42: 0x560c348b09e1 - mycrate[c8865fc2c878b7fc]::search::tests::test_one_search_returns_500
at /workplace/myname/myworkspace/src/myfolder/src/search.rs:1544:9
43: 0x560c34b2af77 - mycrate[c8865fc2c878b7fc]::search::tests::test_one_search_returns_500::{closure#0}
at /workplace/myname/myworkspace/src/myfolder/src/search.rs:1459:43
44: 0x560c349f89a6 - <mycrate[c8865fc2c878b7fc]::search::tests::test_one_search_returns_500::{closure#0} as core[6584200c4e8678d7]::ops::function::FnOnce<()>>::call_once
at /rustc/25ef9e3d85d934b27d9dada2f9dd52b1dc63bb04/library/core/src/ops/function.rs:250:5
45: 0x560c34eafb3f - core::ops::function::FnOnce::call_once::h74f55dd6e810aa08
at /rustc/25ef9e3d85d934b27d9dada2f9dd52b1dc63bb04/library/core/src/ops/function.rs:250:5
46: 0x560c34eafb3f - test::__rust_begin_short_backtrace::h3e4db3b6b5a6d16b
at /rustc/25ef9e3d85d934b27d9dada2f9dd52b1dc63bb04/library/test/src/lib.rs:621:18
47: 0x560c34eae961 - test::run_test_in_process::{{closure}}::hde98f86cda0a8d80
at /rustc/25ef9e3d85d934b27d9dada2f9dd52b1dc63bb04/library/test/src/lib.rs:644:60
48: 0x560c34eae961 - <core::panic::unwind_safe::AssertUnwindSafe<F> as core::ops::function::FnOnce<()>>::call_once::hd61d7b3d31a2227f
at /rustc/25ef9e3d85d934b27d9dada2f9dd52b1dc63bb04/library/core/src/panic/unwind_safe.rs:272:9
49: 0x560c34eae961 - std::panicking::try::do_call::h76a1481c0aa1cb29
at /rustc/25ef9e3d85d934b27d9dada2f9dd52b1dc63bb04/library/std/src/panicking.rs:554:40
50: 0x560c34eae961 - std::panicking::try::h1fc811fc39995144
at /rustc/25ef9e3d85d934b27d9dada2f9dd52b1dc63bb04/library/std/src/panicking.rs:518:19
51: 0x560c34eae961 - std::panic::catch_unwind::h586bd22465fe4588
at /rustc/25ef9e3d85d934b27d9dada2f9dd52b1dc63bb04/library/std/src/panic.rs:142:14
52: 0x560c34eae961 - test::run_test_in_process::h9859bfbe1049ef5c
at /rustc/25ef9e3d85d934b27d9dada2f9dd52b1dc63bb04/library/test/src/lib.rs:644:27
53: 0x560c34eae961 - test::run_test::{{closure}}::h31223704de8864a0
at /rustc/25ef9e3d85d934b27d9dada2f9dd52b1dc63bb04/library/test/src/lib.rs:567:43
54: 0x560c34e75de6 - test::run_test::{{closure}}::hd69c4ad12ef66403
at /rustc/25ef9e3d85d934b27d9dada2f9dd52b1dc63bb04/library/test/src/lib.rs:595:41
55: 0x560c34e75de6 - std::sys_common::backtrace::__rust_begin_short_backtrace::h2d0594884bf616a3
at /rustc/25ef9e3d85d934b27d9dada2f9dd52b1dc63bb04/library/std/src/sys_common/backtrace.rs:155:18
56: 0x560c34e7ae27 - std::thread::Builder::spawn_unchecked_::{{closure}}::{{closure}}::h2fd341fe969e5352
at /rustc/25ef9e3d85d934b27d9dada2f9dd52b1dc63bb04/library/std/src/thread/mod.rs:529:17
57: 0x560c34e7ae27 - <core::panic::unwind_safe::AssertUnwindSafe<F> as core::ops::function::FnOnce<()>>::call_once::hb54f35200ef16dfc
at /rustc/25ef9e3d85d934b27d9dada2f9dd52b1dc63bb04/library/core/src/panic/unwind_safe.rs:272:9
58: 0x560c34e7ae27 - std::panicking::try::do_call::he8f8fd2bc0ce95b4
at /rustc/25ef9e3d85d934b27d9dada2f9dd52b1dc63bb04/library/std/src/panicking.rs:554:40
59: 0x560c34e7ae27 - std::panicking::try::hf212e51eb780e0af
at /rustc/25ef9e3d85d934b27d9dada2f9dd52b1dc63bb04/library/std/src/panicking.rs:518:19
60: 0x560c34e7ae27 - std::panic::catch_unwind::hb6edbb86fffda6d5
at /rustc/25ef9e3d85d934b27d9dada2f9dd52b1dc63bb04/library/std/src/panic.rs:142:14
61: 0x560c34e7ae27 - std::thread::Builder::spawn_unchecked_::{{closure}}::h0f65696ce12b1fa2
at /rustc/25ef9e3d85d934b27d9dada2f9dd52b1dc63bb04/library/std/src/thread/mod.rs:528:30
62: 0x560c34e7ae27 - core::ops::function::FnOnce::call_once{{vtable.shim}}::h3f65e5d6eb8d62f9
at /rustc/25ef9e3d85d934b27d9dada2f9dd52b1dc63bb04/library/core/src/ops/function.rs:250:5
63: 0x560c3748c385 - <alloc::boxed::Box<F,A> as core::ops::function::FnOnce<Args>>::call_once::h3b632e8d2f38c91e
at /rustc/25ef9e3d85d934b27d9dada2f9dd52b1dc63bb04/library/alloc/src/boxed.rs:2015:9
64: 0x560c3748c385 - <alloc::boxed::Box<F,A> as core::ops::function::FnOnce<Args>>::call_once::h175e5a9d4f9da23e
at /rustc/25ef9e3d85d934b27d9dada2f9dd52b1dc63bb04/library/alloc/src/boxed.rs:2015:9
65: 0x560c3748c385 - std::sys::pal::unix::thread::Thread::new::thread_start::h8a5cd49e24db9256
at /rustc/25ef9e3d85d934b27d9dada2f9dd52b1dc63bb04/library/std/src/sys/pal/unix/thread.rs:108:17
66: 0x7f8ee14fa44b - start_thread
67: 0x7f8ee0ef552f - __clone
68: 0x0 - <unknown>
I am trying to enable tokio_unstable for use with tokio-console.
Has anyone seen this issue before?
Looking at my logs further, I think I missed the actual error?
[tracing-subscriber] Unable to write an event to the Writer for this Subscriber! Error: other error
So we are trying to look for something in the logs, and it doesn't appear to be there because it was unable to write an event after adding the tokio_unstable flag.
~~Hm, I don't really know where this is looking from. The traceback doesn't even contain a mention of tracing_test, but that is to be expected since it's a macro which is expanded inside the calling crate.~~
Ah, I think now I understood your second comment. Yeah, I think you're right, the logs_contain function seems to be working as expected. The source of the panic is that the expected log actually isn't there.
The subscriber that tracing-test is using, is just a standard FmtSubscriber:
https://github.com/dbrgn/tracing-test/blob/5d645cb8ef31aee22023c4590b6ee14cbe7577a5/tracing-test/src/subscriber.rs#L60-L65
So I'm not really sure what could be causing this. But it's probably coming from tracing_subscriber?
Thanks! So I think I see where the error is happening, but I'm not quite sure on why its happening yet. The error is related to the mock_writer used in that above code snippet.
Looking at the full error message ([tracing-subscriber] Unable to write an event to the Writer for this Subscriber! Error: other error), the last part (other error), gives us a clue that this is the line causing the error:
https://github.com/dbrgn/tracing-test/blob/5d645cb8ef31aee22023c4590b6ee14cbe7577a5/tracing-test/src/subscriber.rs#L21-L28
We can see in the rust source that io::ErrorKind::Other maps to the string "other error" here.
So for whatever reason, we are erroring out while waiting on the lock.
Reading the docs for std::sync::Mutex::lock it says:
Errors
If another user of this mutex panicked while holding the mutex, then this call will return an error once the mutex is acquired.
Panics
This function might panic when called if the lock is already held by the current thread.
I am able to isolate that this is not related to my test runner (cargo nextest) and I am able to replicate the error when just running a single test:
cargo test test_one_search_returns_500
running 1 test
test search::tests::test_one_search_returns_500 ... FAILED
I even see that the string that it is supposed to be looking for, "invalid return status code: 500 Internal Server Error", is present in the logs:
2024-06-03T01:53:16.354309Z ERROR runtime.spawn{kind=block_on task.name= task.id=1 loc.file="amzn-eureka-broker-node/src/search.rs" loc.line=1558 loc.col=11}:background_work:shard_search_req: amzn_eureka_broker_node::search: error=invalid return status code: 500 Internal Server Error
...
2024-06-03T01:53:16.354665Z ERROR runtime.spawn{kind=block_on task.name= task.id=1 loc.file="amzn-eureka-broker-node/src/search.rs" loc.line=1558 loc.col=11}: amzn_eureka_logging_and_tracing::metrics::reporters: shard_search_req_fail reported due to:invalid return status code: 500 Internal Server Error
...
...
thread 'search::tests::test_one_search_returns_500' panicked at amzn-eureka-broker-node/src/search.rs:1556:9:
assertion failed: logs_contain("invalid return status code: 500 Internal Server Error")
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace
However, when I run this single test, I don't see the "Unable to write an event to the Writer for this Subscriber..." error any longer 🤔
Some progress!
I found that if I remove the no-env-filter feature, only 1 out of my 4 total tests that rely on logs_contain / logs_assert are failing. The only 1 that is failing now is an "integration test" because it lives outside of the module.
Here are the three scenarios I tested:
-
no-env-filter: all tests pass -
no-env-filter+tokio_unstable: all 4 tests fail -
tokio_unstable: only 1 test naturally fails which is an integration test
So I believe there is some interaction between no-env-filter + tokio_unstable that makes it so tracing_test's logs_contain and logs_assert macros can no longer see the logs even when they are being emitted and I can see them in the terminal.