eyre-rs / color-eyre

Custom hooks for colorful human oriented error reports via panics and the eyre crate
Other
958 stars 57 forks source link

should info! events be captured and printed as part of the SpanTrace? #136

Closed matthewgapp closed 7 months ago

matthewgapp commented 11 months ago

I expect to see span events (info!, warn!, etc) in the printed spantrace. Am I missing some config or is that something that's not supported?

Minimal repro

use tracing::{error, info, instrument, warn};
use tracing_subscriber::{prelude::__tracing_subscriber_SubscriberExt, util::SubscriberInitExt};

fn setup_tracing() {
    tracing_subscriber::registry()
        .with(
            tracing_subscriber::EnvFilter::try_from_default_env()
                .unwrap_or_else(|_| "example_websockets=debug,tower_http=debug".into()),
        )
        .with(tracing_error::ErrorLayer::default())
        .with(tracing_subscriber::fmt::layer().pretty())
        .init();
}

#[instrument]
async fn broken_func(input: i32) {
    info!("input: {}", input);
    // record some event
    tokio::time::sleep(std::time::Duration::from_secs(1)).await;
    info!("some other event");
    warn!("something bad is happening");
    error!("something really bad is about to happen");
    panic!("panic!");
}

#[tokio::main]
async fn main() {
    setup_tracing();
    color_eyre::install().unwrap();
    println!("Hello, world!");
    broken_func(42).await;
}
> RUST_LOG=trace RUST_BACKTRACE=full cargo run 
   Compiling spantrace v0.1.0 (/Users/matthewgapp/code/scratchpad/spantrace)
    Finished dev [unoptimized + debuginfo] target(s) in 0.42s
     Running `target/debug/spantrace`
Hello, world!
  2023-10-02T18:40:31.662795Z  INFO spantrace: input: 42
    at src/main.rs:17
    in spantrace::broken_func with input: 42

  2023-10-02T18:40:32.664992Z  INFO spantrace: some other event
    at src/main.rs:20
    in spantrace::broken_func with input: 42

  2023-10-02T18:40:32.665056Z  WARN spantrace: something bad is happening
    at src/main.rs:21
    in spantrace::broken_func with input: 42

  2023-10-02T18:40:32.665078Z ERROR spantrace: something really bad is about to happen
    at src/main.rs:22
    in spantrace::broken_func with input: 42

The application panicked (crashed).
Message:  panic!
Location: src/main.rs:23

  ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ SPANTRACE ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━

   0: spantrace::broken_func with input=42
      at src/main.rs:15
        13 │ }
        14 │ 
        15 > #[instrument]
        16 │ async fn broken_func(input: i32) {
        17 │     info!("input: {}", input);

  ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ BACKTRACE ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━
                                ⋮ 13 frames hidden ⋮                              
  14: spantrace::broken_func::{{closure}}::{{closure}}::hb00997bca39ade3c
      at /Users/matthewgapp/code/scratchpad/spantrace/src/main.rs:23
        21 │     warn!("something bad is happening");
        22 │     error!("something really bad is about to happen");
        23 >     panic!("panic!");
        24 │ }
        25 │ 
  15: <tracing::instrument::Instrumented<T> as core::future::future::Future>::poll::h350815efce5e1317
      at /Users/matthewgapp/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tracing-0.1.37/src/instrument.rs:272
       270 │         let this = self.project();
       271 │         let _enter = this.span.enter();
       272 >         this.inner.poll(cx)
       273 │     }
       274 │ }
  16: spantrace::broken_func::{{closure}}::h804687abc3c9aa0d
      at /Users/matthewgapp/code/scratchpad/spantrace/src/main.rs:15
        13 │ }
        14 │ 
        15 > #[instrument]
        16 │ async fn broken_func(input: i32) {
        17 │     info!("input: {}", input);
  17: spantrace::main::{{closure}}::h67ebd7653daf64d2
      at /Users/matthewgapp/code/scratchpad/spantrace/src/main.rs:31
        29 │     color_eyre::install().unwrap();
        30 │     println!("Hello, world!");
        31 >     broken_func(42).await;
        32 │ }
  18: tokio::runtime::park::CachedParkThread::block_on::{{closure}}::h3741f31cc889b2f0
      at /Users/matthewgapp/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.32.0/src/runtime/park.rs:282
       280 │ 
       281 │         loop {
       282 >             if let Ready(v) = crate::runtime::coop::budget(|| f.as_mut().poll(&mut cx)) {
       283 │                 return Ok(v);
       284 │             }
  19: tokio::runtime::coop::with_budget::h2c2b31f3d24f6283
      at /Users/matthewgapp/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.32.0/src/runtime/coop.rs:107
       105 │     // The function is called regardless even if the budget is not successfully
       106 │     // set due to the thread-local being destroyed.
       107 >     f()
       108 │ }
       109 │ 
  20: tokio::runtime::coop::budget::ha61c54dd45eb0cae
      at /Users/matthewgapp/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.32.0/src/runtime/coop.rs:73
        71 │ #[inline(always)]
        72 │ pub(crate) fn budget<R>(f: impl FnOnce() -> R) -> R {
        73 >     with_budget(Budget::initial(), f)
        74 │ }
        75 │ 
  21: tokio::runtime::park::CachedParkThread::block_on::h71f6992b0f6cd6e8
      at /Users/matthewgapp/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.32.0/src/runtime/park.rs:282
       280 │ 
       281 │         loop {
       282 >             if let Ready(v) = crate::runtime::coop::budget(|| f.as_mut().poll(&mut cx)) {
       283 │                 return Ok(v);
       284 │             }
  22: tokio::runtime::context::blocking::BlockingRegionGuard::block_on::hb72818db363ef2f5
      at /Users/matthewgapp/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.32.0/src/runtime/context/blocking.rs:66
        64 │ 
        65 │         let mut park = CachedParkThread::new();
        66 >         park.block_on(f)
        67 │     }
        68 │ 
  23: tokio::runtime::scheduler::multi_thread::MultiThread::block_on::{{closure}}::h8d355821959c63d0
      at /Users/matthewgapp/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.32.0/src/runtime/scheduler/multi_thread/mod.rs:87
        85 │     {
        86 │         crate::runtime::context::enter_runtime(handle, true, |blocking| {
        87 >             blocking.block_on(future).expect("failed to park thread")
        88 │         })
        89 │     }
  24: tokio::runtime::context::runtime::enter_runtime::h53f32f8544610c83
      at /Users/matthewgapp/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.32.0/src/runtime/context/runtime.rs:65
        63 │ 
        64 │     if let Some(mut guard) = maybe_guard {
        65 >         return f(&mut guard.blocking);
        66 │     }
        67 │ 
  25: tokio::runtime::scheduler::multi_thread::MultiThread::block_on::h3a650532bd926ee1
      at /Users/matthewgapp/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.32.0/src/runtime/scheduler/multi_thread/mod.rs:86
        84 │         F: Future,
        85 │     {
        86 >         crate::runtime::context::enter_runtime(handle, true, |blocking| {
        87 │             blocking.block_on(future).expect("failed to park thread")
        88 │         })
  26: tokio::runtime::runtime::Runtime::block_on::h71d196302c1a053d
      at /Users/matthewgapp/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.32.0/src/runtime/runtime.rs:349
       347 │             Scheduler::CurrentThread(exec) => exec.block_on(&self.handle.inner, future),
       348 │             #[cfg(all(feature = "rt-multi-thread", not(target_os = "wasi")))]
       349 >             Scheduler::MultiThread(exec) => exec.block_on(&self.handle.inner, future),
       350 │             #[cfg(all(tokio_unstable, feature = "rt-multi-thread", not(target_os = "wasi")))]
       351 │             Scheduler::MultiThreadAlt(exec) => exec.block_on(&self.handle.inner, future),
  27: spantrace::main::h75f903e868ffb7eb
      at /Users/matthewgapp/code/scratchpad/spantrace/src/main.rs:31
        29 │     color_eyre::install().unwrap();
        30 │     println!("Hello, world!");
        31 >     broken_func(42).await;
        32 │ }
  28: core::ops::function::FnOnce::call_once::h66d9f89c9003d21d
      at /rustc/d5c2e9c342b358556da91d61ed4133f6f50fc0c3/library/core/src/ops/function.rs:250
                                ⋮ 13 frames hidden ⋮                              

Run with COLORBT_SHOW_HIDDEN=1 environment variable to disable frame filtering.
matthewgapp commented 11 months ago

Did some digging on this. I think the answer is no, because, based on my preliminary research, SpanTraces don't contain event information because spans don't embed events within the physical span. For context, events are usually correlated to an active span within a Subscriber impl.