No capture from `std::thread::spawn` or `tokio::task::spawn_blocking`

[elonen]

I'm having difficulties asserting traces from inside an std thread. Is there something I overlooked, or does the capture perhaps generally fail when using std::thread::spawn instead of multi-threading tokio?

The following passes first two tests but fails the third:

use tracing;
use tracing_test::traced_test;

fn hello() {
    tracing::info!("Hello, world!");
}

#[test]
#[traced_test]
fn test_1_singlethread()
{
    tracing::info!("Test thread");
    hello();
    assert!(logs_contain("Test thread"));
    assert!(logs_contain("Hello, world!"));
}

#[tokio::test]
#[traced_test]
async fn test_2_multithread_tokio()
{
    tracing::info!("Test thread");
    tokio::spawn(async { hello(); }).await.unwrap();
    assert!(logs_contain("Test thread"));
    assert!(logs_contain("Hello, world!"));
}

#[test]
#[traced_test]
fn test_3_multithread_std()
{
    tracing::info!("Test thread");
    std::thread::spawn(|| { hello(); }).join().unwrap();
    assert!(logs_contain("Test thread"));
    assert!(logs_contain("Hello, world!"));
}

Results:

[...]
running 3 tests
test test_1_singlethread ... ok
test test_2_multithread_tokio ... ok
test test_3_multithread_std ... FAILED

failures:

---- test_3_multithread_std stdout ----
2023-02-12T08:02:20.047401Z  INFO test_3_multithread_std: r#mod: Test thread
2023-02-12T08:02:20.047625Z  INFO r#mod: Hello, world!
thread 'test_3_multithread_std' panicked at 'assertion failed: logs_contain(\"Hello, world!\")', tests/mod.rs:35:5

Cargo.toml contains no-env-filter:

[package]
name = "tracing-test-problem"
version = "0.1.0"
edition = "2021"

[dependencies]
tracing = "0.1.37"
tokio = { version = "1.25.0", features = ["rt-multi-thread", "macros"] }

[dev-dependencies]
tracing-test = {version="0.2.4", features=["no-env-filter"] }

[elonen]

Oh, looks like tokio::task::spawn_blocking also loses the output. Adding this...

#[tokio::test]
#[traced_test]
async fn test_4_tokio_blocking()
{
    tracing::info!("Test thread");
    tokio::task::spawn_blocking(|| hello() ).await.unwrap();
    assert!(logs_contain("Test thread"));
    assert!(logs_contain("Hello, world!"));
}

...results in:

test test_4_tokio_blocking ... FAILED

failures:
---- test_4_tokio_blocking stdout ----
2023-02-12T08:35:33.086166Z  INFO test_4_tokio_blocking: r#mod: Test thread
2023-02-12T08:35:33.086283Z  INFO r#mod: Hello, world!
thread 'test_4_tokio_blocking' panicked at 'assertion failed: logs_contain(\"Hello, world!\")', tests/mod.rs:46:5

[elonen]

Asserting inside the thread block (instead of after joining it) works, but this doesn't really help with integration tests, where the tested functionality uses multiple threads internally.

[bgw]

This is likely a side-effect of #19. There's no good way to automatically associate tracing events across threads or tasks. The documentation gives a usage example that uses tokio::spawn, but I'm skeptical that it would actually work as documented after the bugfix in #19.

You can associate the spawned code with the current span using Instrument::in_current_span (for async tasks) or Span::or_current (for synchronous threads) which may resolve your issue.

[elonen]

Thank you. Test 2 (tokio::spawn) still works like documented with features=["no-env-filter"], but test 4 (tokio::spawn_blocking) fails.

Passing the span manually into a thread with Span::or_current() indeed fixes the asserts for both std::thread::spawn and tokio::spawn_blocking:

#[test]
#[traced_test]
fn test_5_multithread_std_or_current()
{
    tracing::info!("Test thread");

    let thread_span = tracing::debug_span!("thread").or_current();
    std::thread::spawn(|| { 
        let _entered = thread_span.entered();
        hello();
    }).join().unwrap();
    
    assert!(logs_contain("Test thread"));
    assert!(logs_contain("Hello, world!"));
}

#[tokio::test]
#[traced_test]
async fn test_6_tokio_blocking_or_current()
{
    tracing::info!("Test thread");

    let thread_span = tracing::debug_span!("thread").or_current();
    tokio::task::spawn_blocking(|| { 
        let _entered = thread_span.entered();
        hello() 
    }).await.unwrap();

    assert!(logs_contain("Test thread"));
    assert!(logs_contain("Hello, world!"));
}

Results:

test test_5_multithread_std_or_current ... ok
test test_6_tokio_blocking_or_current ... ok

Interesting gotcha: the guard variable has to be named or it gets immediately dropped. Using plain _ instead of _entered fails the test without any compiler warnings:

#[tokio::test]
#[traced_test]
async fn test_7_tokio_blocking_or_current_unnamed_guard()
{
    tracing::info!("Test thread");

    let thread_span = tracing::debug_span!("thread").or_current();
    tokio::task::spawn_blocking(|| { 
        let _ = thread_span.entered();   // this doesn't work, but _entered does
        hello() 
    }).await.unwrap();

    assert!(logs_contain("Test thread"));
    assert!(logs_contain("Hello, world!"));
}

Result:

test test_7_tokio_blocking_or_current_unnamed_guard ... FAILED

Conclusions

Since tracing events were shown in test failure log, like the "Hello, world!" here...

---- test_3_multithread_std stdout ----
2023-02-16T09:50:18.446516Z  INFO test_3_multithread_std: r#mod: Test thread
2023-02-16T09:50:18.447020Z  INFO r#mod: Hello, world!
thread 'test_3_multithread_std' panicked at 'assertion failed: logs_contain(\"Hello, world!\")', tests/mod.rs:37:5

---- test_4_tokio_blocking stdout ----
2023-02-16T09:50:18.446222Z  INFO test_4_tokio_blocking: r#mod: Test thread
2023-02-16T09:50:18.447002Z  INFO r#mod: Hello, world!
thread 'test_4_tokio_blocking' panicked at 'assertion failed: logs_contain(\"Hello, world!\")', tests/mod.rs:48:5
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace

...I expeced logs_contain() to have used whatever method cargo test was using to globally capture everything. Then again, #19 and the associated issue seem reasonable, too. How about just adding a short note to docs about threads and the need for .or_current()?

[bgw]

Interesting gotcha: the guard variable has to be named or it gets immediately dropped. Using plain _ instead of _entered fails the test without any compiler warnings

Wow, TIL. https://medium.com/codechain/rust-underscore-does-not-bind-fec6a18115a8

[odyslam]

I am encountering the same issue. Is there a good solution to this?

[landonxjames]

I ran into this issue today as well and it is fairly easy to reproduce. The following small variation on the example from the documentation fails. Since tokio tests default to running in a single threaded runtime the comment in the example is incorrect and the default example does not include any separate threads.

    #[tokio::test(flavor = "multi_thread", worker_threads = 1)]
    #[traced_test]
    async fn test_logs_are_captured() {
        // Local log
        info!("This is being logged on the info level");

        info!("CountMe");
        // Log from a spawned task (which runs in a separate thread)
        tokio::spawn(async {
            warn!("This is being logged on the warn level from a spawned task");
            info!("CountMe");
        })
        .await
        .unwrap();

        // Ensure that `logs_contain` works as intended
        assert!(logs_contain("logged on the info level"));
        assert!(logs_contain("logged on the warn level"));
        assert!(!logs_contain("logged on the error level"));

        // Ensure that `logs_assert` works as intended (with a closure)
        logs_assert(|lines: &[&str]| {
            match lines.iter().filter(|line| line.contains("CountMe")).count() {
                2 => Ok(()),
                n => Err(format!("Count should be 2, but was {}", n)),
            }
        });

        // Ensure that `logs_assert` works as intended (with a function)
        fn assert_fn(lines: &[&str]) -> Result<(), String> {
            match lines.iter().filter(|line| line.contains("CountMe")).count() {
                2 => Ok(()),
                n => Err(format!("Count should be 2, but was {}", n)),
            }
        }
        logs_assert(assert_fn);
    }

fails with:

running 1 test
test meter::tests::test_logs_are_captured ... FAILED

successes:

successes:

failures:

---- meter::tests::test_logs_are_captured stdout ----
2024-11-05T22:09:27.493105Z  INFO test_logs_are_captured: aws_smithy_observability_otel::meter::tests: This is being logged on the info level
2024-11-05T22:09:27.493167Z  INFO test_logs_are_captured: aws_smithy_observability_otel::meter::tests: CountMe
2024-11-05T22:09:27.493352Z  WARN aws_smithy_observability_otel::meter::tests: This is being logged on the warn level from a spawned task
2024-11-05T22:09:27.493368Z  INFO aws_smithy_observability_otel::meter::tests: CountMe
thread 'meter::tests::test_logs_are_captured' panicked at aws-smithy-observability-otel/src/meter.rs:525:9:
assertion failed: logs_contain("logged on the warn level")

[josecelano]

I think I'm also having problems with nested spawned tasks, but I have not been able to reproduce it with a minimal example yet.

I'm trying to refactor this PR since I realized I was building this crate. However, I can only see logs from the first level of spawned tasks.

[josecelano]

I've created a test repo to play with different configurations:

https://github.com/josecelano/tracing-test-bug