search

n0-computer / iroh

A toolkit for building distributed applications
https://iroh.computer
Apache License 2.0
2.26k stars 145 forks source link

remove pkarr publish backtrace on error #2316

Open divagant-martian opened 3 months ago

divagant-martian commented 3 months ago

at least in ci there is a constant emission of these:

``` 2024-05-21T16:59:39.2526870Z 2024-05-21T16:59:39.2526930Z Stack backtrace: 2024-05-21T16:59:39.2527140Z 0: std::backtrace_rs::backtrace::libunwind::trace 2024-05-21T16:59:39.2527680Z at /rustc/9b00956e56009bab2aa15d7bff10916599e3d6d6/library/std/src/../../backtrace/src/backtrace/libunwind.rs:105:5 2024-05-21T16:59:39.2528220Z 1: std::backtrace_rs::backtrace::trace_unsynchronized 2024-05-21T16:59:39.2528740Z at /rustc/9b00956e56009bab2aa15d7bff10916599e3d6d6/library/std/src/../../backtrace/src/backtrace/mod.rs:66:5 2024-05-21T16:59:39.2529210Z 2: std::backtrace::Backtrace::create 2024-05-21T16:59:39.2529610Z at /rustc/9b00956e56009bab2aa15d7bff10916599e3d6d6/library/std/src/backtrace.rs:331:13 2024-05-21T16:59:39.2530000Z 3: anyhow::kind::Adhoc::new 2024-05-21T16:59:39.2530490Z at /Users/hetzner/.cargo/registry/src/index.crates.io-6f17d22bba15001f/anyhow-1.0.82/src/kind.rs:73:36 2024-05-21T16:59:39.2531070Z 4: iroh_net::discovery::pkarr_publish::PkarrRelayClient::publish::{{closure}} 2024-05-21T16:59:39.2531670Z at /Users/hetzner/actions-runner/_work/iroh/iroh/iroh-net/src/discovery/pkarr_publish.rs:208:13 2024-05-21T16:59:39.2532240Z 5: iroh_net::discovery::pkarr_publish::PublisherService::publish_current::{{closure}} 2024-05-21T16:59:39.2532860Z at /Users/hetzner/actions-runner/_work/iroh/iroh/iroh-net/src/discovery/pkarr_publish.rs:172:51 2024-05-21T16:59:39.2533390Z 6: iroh_net::discovery::pkarr_publish::PublisherService::run::{{closure}} 2024-05-21T16:59:39.2533970Z at /Users/hetzner/actions-runner/_work/iroh/iroh/iroh-net/src/discovery/pkarr_publish.rs:137:62 2024-05-21T16:59:39.2534520Z 7: as core::future::future::Future>::poll 2024-05-21T16:59:39.2535180Z at /Users/hetzner/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tracing-0.1.40/src/instrument.rs:321:9 2024-05-21T16:59:39.2535720Z 8: tokio::runtime::task::core::Core::poll::{{closure}} 2024-05-21T16:59:39.2536350Z at /Users/hetzner/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.37.0/src/runtime/task/core.rs:328:17 2024-05-21T16:59:39.2536900Z 9: tokio::loom::std::unsafe_cell::UnsafeCell::with_mut 2024-05-21T16:59:39.2537520Z at /Users/hetzner/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.37.0/src/loom/std/unsafe_cell.rs:16:9 2024-05-21T16:59:39.2538050Z 10: tokio::runtime::task::core::Core::poll 2024-05-21T16:59:39.2538670Z at /Users/hetzner/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.37.0/src/runtime/task/core.rs:317:13 2024-05-21T16:59:39.2539240Z 11: tokio::runtime::task::harness::poll_future::{{closure}} 2024-05-21T16:59:39.2539860Z at /Users/hetzner/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.37.0/src/runtime/task/harness.rs:485:19 2024-05-21T16:59:39.2540550Z 12: as core::ops::function::FnOnce<()>>::call_once 2024-05-21T16:59:39.2541140Z at /rustc/9b00956e56009bab2aa15d7bff10916599e3d6d6/library/core/src/panic/unwind_safe.rs:272:9 2024-05-21T16:59:39.2541560Z 13: std::panicking::try::do_call 2024-05-21T16:59:39.2541940Z at /rustc/9b00956e56009bab2aa15d7bff10916599e3d6d6/library/std/src/panicking.rs:552:40 2024-05-21T16:59:39.2542310Z 14: ___rust_try 2024-05-21T16:59:39.2542480Z 15: std::panicking::try 2024-05-21T16:59:39.2542830Z at /rustc/9b00956e56009bab2aa15d7bff10916599e3d6d6/library/std/src/panicking.rs:516:19 2024-05-21T16:59:39.2543260Z 16: std::panic::catch_unwind 2024-05-21T16:59:39.2543620Z at /rustc/9b00956e56009bab2aa15d7bff10916599e3d6d6/library/std/src/panic.rs:146:14 2024-05-21T16:59:39.2544020Z 17: tokio::runtime::task::harness::poll_future 2024-05-21T16:59:39.2544620Z at /Users/hetzner/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.37.0/src/runtime/task/harness.rs:473:18 2024-05-21T16:59:39.2545190Z 18: tokio::runtime::task::harness::Harness::poll_inner 2024-05-21T16:59:39.2545810Z at /Users/hetzner/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.37.0/src/runtime/task/harness.rs:208:27 2024-05-21T16:59:39.2546360Z 19: tokio::runtime::task::harness::Harness::poll 2024-05-21T16:59:39.2550400Z at /Users/hetzner/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.37.0/src/runtime/task/harness.rs:153:15 2024-05-21T16:59:39.2550910Z 20: tokio::runtime::task::raw::poll 2024-05-21T16:59:39.2551460Z at /Users/hetzner/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.37.0/src/runtime/task/raw.rs:271:5 2024-05-21T16:59:39.2551970Z 21: tokio::runtime::task::raw::RawTask::poll 2024-05-21T16:59:39.2552540Z at /Users/hetzner/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.37.0/src/runtime/task/raw.rs:201:18 2024-05-21T16:59:39.2553070Z 22: tokio::runtime::task::LocalNotified::run 2024-05-21T16:59:39.2553640Z at /Users/hetzner/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.37.0/src/runtime/task/mod.rs:427:9 2024-05-21T16:59:39.2554290Z 23: tokio::runtime::scheduler::current_thread::CoreGuard::block_on::{{closure}}::{{closure}} 2024-05-21T16:59:39.2555080Z at /Users/hetzner/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.37.0/src/runtime/scheduler/current_thread/mod.rs:700:25 2024-05-21T16:59:39.2555650Z 24: tokio::runtime::coop::with_budget 2024-05-21T16:59:39.2556190Z at /Users/hetzner/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.37.0/src/runtime/coop.rs:107:5 2024-05-21T16:59:39.2556660Z 25: tokio::runtime::coop::budget 2024-05-21T16:59:39.2557180Z at /Users/hetzner/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.37.0/src/runtime/coop.rs:73:5 2024-05-21T16:59:39.2557760Z 26: tokio::runtime::scheduler::current_thread::Context::run_task::{{closure}} 2024-05-21T16:59:39.2558500Z at /Users/hetzner/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.37.0/src/runtime/scheduler/current_thread/mod.rs:343:43 2024-05-21T16:59:39.2559170Z 27: tokio::runtime::scheduler::current_thread::Context::enter 2024-05-21T16:59:39.2559870Z at /Users/hetzner/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.37.0/src/runtime/scheduler/current_thread/mod.rs:404:19 2024-05-21T16:59:39.2560510Z 28: tokio::runtime::scheduler::current_thread::Context::run_task 2024-05-21T16:59:39.2561290Z at /Users/hetzner/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.37.0/src/runtime/scheduler/current_thread/mod.rs:343:23 2024-05-21T16:59:39.2561980Z 29: tokio::runtime::scheduler::current_thread::CoreGuard::block_on::{{closure}} 2024-05-21T16:59:39.2562720Z at /Users/hetzner/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.37.0/src/runtime/scheduler/current_thread/mod.rs:699:35 2024-05-21T16:59:39.2563390Z 30: tokio::runtime::scheduler::current_thread::CoreGuard::enter::{{closure}} 2024-05-21T16:59:39.2564130Z at /Users/hetzner/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.37.0/src/runtime/scheduler/current_thread/mod.rs:737:68 2024-05-21T16:59:39.2564730Z 31: tokio::runtime::context::scoped::Scoped::set 2024-05-21T16:59:39.2565330Z at /Users/hetzner/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.37.0/src/runtime/context/scoped.rs:40:9 2024-05-21T16:59:39.2565890Z 32: tokio::runtime::context::set_scheduler::{{closure}} 2024-05-21T16:59:39.2566530Z at /Users/hetzner/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.37.0/src/runtime/context.rs:176:26 2024-05-21T16:59:39.2567050Z 33: std::thread::local::LocalKey::try_with 2024-05-21T16:59:39.2567470Z at /rustc/9b00956e56009bab2aa15d7bff10916599e3d6d6/library/std/src/thread/local.rs:284:16 2024-05-21T16:59:39.2567880Z 34: std::thread::local::LocalKey::with 2024-05-21T16:59:39.2568290Z at /rustc/9b00956e56009bab2aa15d7bff10916599e3d6d6/library/std/src/thread/local.rs:260:9 2024-05-21T16:59:39.2568700Z 35: tokio::runtime::context::set_scheduler 2024-05-21T16:59:39.2569260Z at /Users/hetzner/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.37.0/src/runtime/context.rs:176:9 2024-05-21T16:59:39.2569830Z 36: tokio::runtime::scheduler::current_thread::CoreGuard::enter 2024-05-21T16:59:39.2570530Z at /Users/hetzner/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.37.0/src/runtime/scheduler/current_thread/mod.rs:737:27 2024-05-21T16:59:39.2571180Z 37: tokio::runtime::scheduler::current_thread::CoreGuard::block_on 2024-05-21T16:59:39.2571890Z at /Users/hetzner/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.37.0/src/runtime/scheduler/current_thread/mod.rs:646:19 2024-05-21T16:59:39.2572590Z 38: tokio::runtime::scheduler::current_thread::CurrentThread::block_on::{{closure}} 2024-05-21T16:59:39.2573340Z at /Users/hetzner/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.37.0/src/runtime/scheduler/current_thread/mod.rs:175:28 2024-05-21T16:59:39.2573940Z 39: tokio::runtime::context::runtime::enter_runtime 2024-05-21T16:59:39.2574550Z at /Users/hetzner/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.37.0/src/runtime/context/runtime.rs:65:16 2024-05-21T16:59:39.2575160Z 40: tokio::runtime::scheduler::current_thread::CurrentThread::block_on 2024-05-21T16:59:39.2575890Z at /Users/hetzner/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.37.0/src/runtime/scheduler/current_thread/mod.rs:167:9 2024-05-21T16:59:39.2576480Z 41: tokio::runtime::runtime::Runtime::block_on 2024-05-21T16:59:39.2577060Z at /Users/hetzner/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.37.0/src/runtime/runtime.rs:349:47 2024-05-21T16:59:39.2577550Z 42: sync::test_download_policies 2024-05-21T16:59:39.2577770Z at ./tests/sync.rs:850:5 2024-05-21T16:59:39.2578030Z 43: sync::test_download_policies::{{closure}} 2024-05-21T16:59:39.2578280Z at ./tests/sync.rs:713:38 2024-05-21T16:59:39.2578530Z 44: core::ops::function::FnOnce::call_once 2024-05-21T16:59:39.2578950Z at /rustc/9b00956e56009bab2aa15d7bff10916599e3d6d6/library/core/src/ops/function.rs:250:5 2024-05-21T16:59:39.2579360Z 45: core::ops::function::FnOnce::call_once 2024-05-21T16:59:39.2579780Z at /rustc/9b00956e56009bab2aa15d7bff10916599e3d6d6/library/core/src/ops/function.rs:250:5 2024-05-21T16:59:39.2580180Z 46: test::__rust_begin_short_backtrace 2024-05-21T16:59:39.2580600Z at /rustc/9b00956e56009bab2aa15d7bff10916599e3d6d6/library/test/src/lib.rs:621:18 2024-05-21T16:59:39.2580990Z 47: test::run_test_in_process::{{closure}} 2024-05-21T16:59:39.2581380Z at /rustc/9b00956e56009bab2aa15d7bff10916599e3d6d6/library/test/src/lib.rs:644:60 2024-05-21T16:59:39.2581930Z 48: as core::ops::function::FnOnce<()>>::call_once 2024-05-21T16:59:39.2582520Z at /rustc/9b00956e56009bab2aa15d7bff10916599e3d6d6/library/core/src/panic/unwind_safe.rs:272:9 2024-05-21T16:59:39.2582940Z 49: std::panicking::try::do_call 2024-05-21T16:59:39.2583320Z at /rustc/9b00956e56009bab2aa15d7bff10916599e3d6d6/library/std/src/panicking.rs:552:40 2024-05-21T16:59:39.2583700Z 50: std::panicking::try 2024-05-21T16:59:39.2584050Z at /rustc/9b00956e56009bab2aa15d7bff10916599e3d6d6/library/std/src/panicking.rs:516:19 2024-05-21T16:59:39.2584530Z 51: std::panic::catch_unwind 2024-05-21T16:59:39.2584890Z at /rustc/9b00956e56009bab2aa15d7bff10916599e3d6d6/library/std/src/panic.rs:146:14 2024-05-21T16:59:39.2585260Z 52: test::run_test_in_process 2024-05-21T16:59:39.2585620Z at /rustc/9b00956e56009bab2aa15d7bff10916599e3d6d6/library/test/src/lib.rs:644:27 2024-05-21T16:59:39.2585990Z 53: test::run_test::{{closure}} 2024-05-21T16:59:39.2586350Z at /rustc/9b00956e56009bab2aa15d7bff10916599e3d6d6/library/test/src/lib.rs:567:43 2024-05-21T16:59:39.2586720Z 54: test::run_test::{{closure}} 2024-05-21T16:59:39.2587070Z at /rustc/9b00956e56009bab2aa15d7bff10916599e3d6d6/library/test/src/lib.rs:595:41 2024-05-21T16:59:39.2587510Z 55: std::sys_common::backtrace::__rust_begin_short_backtrace 2024-05-21T16:59:39.2587990Z at /rustc/9b00956e56009bab2aa15d7bff10916599e3d6d6/library/std/src/sys_common/backtrace.rs:155:18 2024-05-21T16:59:39.2588510Z 56: std::thread::Builder::spawn_unchecked_::{{closure}}::{{closure}} 2024-05-21T16:59:39.2589000Z at /rustc/9b00956e56009bab2aa15d7bff10916599e3d6d6/library/std/src/thread/mod.rs:528:17 2024-05-21T16:59:39.2589570Z 57: as core::ops::function::FnOnce<()>>::call_once 2024-05-21T16:59:39.2590150Z at /rustc/9b00956e56009bab2aa15d7bff10916599e3d6d6/library/core/src/panic/unwind_safe.rs:272:9 2024-05-21T16:59:39.2590570Z 58: std::panicking::try::do_call 2024-05-21T16:59:39.2590940Z at /rustc/9b00956e56009bab2aa15d7bff10916599e3d6d6/library/std/src/panicking.rs:552:40 2024-05-21T16:59:39.2591330Z 59: std::panicking::try 2024-05-21T16:59:39.2591670Z at /rustc/9b00956e56009bab2aa15d7bff10916599e3d6d6/library/std/src/panicking.rs:516:19 2024-05-21T16:59:39.2592060Z 60: std::panic::catch_unwind 2024-05-21T16:59:39.2592410Z at /rustc/9b00956e56009bab2aa15d7bff10916599e3d6d6/library/std/src/panic.rs:146:14 2024-05-21T16:59:39.2592840Z 61: std::thread::Builder::spawn_unchecked_::{{closure}} 2024-05-21T16:59:39.2593280Z at /rustc/9b00956e56009bab2aa15d7bff10916599e3d6d6/library/std/src/thread/mod.rs:527:30 2024-05-21T16:59:39.2593740Z 62: core::ops::function::FnOnce::call_once{{vtable.shim}} 2024-05-21T16:59:39.2594210Z at /rustc/9b00956e56009bab2aa15d7bff10916599e3d6d6/library/core/src/ops/function.rs:250:5 2024-05-21T16:59:39.2594720Z 63: as core::ops::function::FnOnce>::call_once 2024-05-21T16:59:39.2595240Z at /rustc/9b00956e56009bab2aa15d7bff10916599e3d6d6/library/alloc/src/boxed.rs:2020:9 2024-05-21T16:59:39.2595730Z 64: as core::ops::function::FnOnce>::call_once 2024-05-21T16:59:39.2596220Z at /rustc/9b00956e56009bab2aa15d7bff10916599e3d6d6/library/alloc/src/boxed.rs:2020:9 2024-05-21T16:59:39.2596660Z 65: std::sys::pal::unix::thread::Thread::new::thread_start 2024-05-21T16:59:39.2597220Z at /rustc/9b00956e56009bab2aa15d7bff10916599e3d6d6/library/std/src/sys/pal/unix/thread.rs:108:17 2024-05-21T16:59:39.2597800Z 66: __pthread_deallocate url=https://dns.iroh.link/pkarr ```

if this is ever triggered for an user this is more than 120 lines in a single warn that look like a panic. In ci this is very annoying, for an user this would look terribly worrisome and provides imo no actual extra information that can be used to know why the publish failed

This is emitted in

discovery service produced error

and

Failed to publish to pkarr

rklaehn commented 2 months ago

This is a new feature of anyhow. It now will always attach backtraces and print them when RUST_BACKTRACE=1 is set.

From https://crates.io/crates/anyhow:

If using Rust ≥ 1.65, a backtrace is captured and printed with the error if the underlying error type does not already provide its own. In order to see backtraces, they must be enabled through the environment variables described in std::backtrace:

If you want panics and errors to both have backtraces, set RUST_BACKTRACE=1;
If you want only errors to have backtraces, set RUST_LIB_BACKTRACE=1;
If you want only panics to have backtraces, set RUST_BACKTRACE=1 and RUST_LIB_BACKTRACE=0.

So we either don't print anyhow errors anymore, or just change CI to set RUST_BACKTRACE=1 and RUST_LIB_BACKTRACE=0 to get rid of it.

I think maybe the latter is the way to go? We got tons of places in the code where we are printing errors in log statements. And people won't run into this if they don't set RUST_BACKTRACE=1.

rklaehn commented 2 months ago

@Arqu this would be just adding RUST_LIB_BACKTRACE=0 to all ci yaml files where RUST_LOG is set, right?

E.g. here:

    - name: build
      # cross tests are currently broken vor armv7 and aarch64
      # see https://github.com/cross-rs/cross/issues/1311.  So on
      # those platforms we only build but do not run tests.
      run: cross build --all --target ${{ matrix.target }}
      env:
        RUST_LOG: ${{ runner.debug && 'TRACE' || 'DEBUG'}}
>       RUST_LIB_BACKTRACE=1
Arqu commented 2 months ago

Yeah, reading the docs you mentioned seems like doing RUST_BACKTRACE=1 and RUST_LIB_BACKTRACE=0 should work for us. And yes, just follow suit on CI yaml files.

It does result in the unfortunate situation where we don't see other lib backtraces, but we already knew that I guess.