No capture from std::thread::spawn or tokio::task::spawn_blocking
#23
Comments
elonen
changed the title
std::thread::spawn
|
Oh, looks like #[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: |
elonen
changed the title
std::thread::spawnstd::thread::spawn or tokio::task::spawn_blocking
|
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. |
|
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 You can associate the spawned code with the current span using |
|
Thank you. Test 2 ( Passing the span manually into a thread with #[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: Interesting gotcha: the guard variable has to be named or it gets immediately dropped. Using #[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: ConclusionsSince tracing events were shown in test failure log, like the "Hello, world!" here... ...I expeced |
Wow, TIL. https://medium.com/codechain/rust-underscore-does-not-bind-fec6a18115a8 |
With deadpool-sqlite, the database interactions happen in a sync context (due to using rusqlite) on a separate thread. The tracing crate can add conetxt to any logs (events). Due to the database interactions happening on a separate thread, this context gets lost. Enabling the tracing feature allows the information to be preserved. Related: dbrgn/tracing-test#23 Note: I don't know if this is something that should rather be implemented in the `spawn_blocking` method of Tokio.
With deadpool-sqlite, the database interactions happen in a sync context (due to using rusqlite) on a separate thread. The tracing crate can add conetxt to any logs (events). Due to the database interactions happening on a separate thread, this context gets lost. Enabling the tracing feature allows the information to be preserved. Related: dbrgn/tracing-test#23 Note: I don't know if this is something that should rather be implemented in the `spawn_blocking` method of Tokio.
With deadpool-sqlite, the database interactions happen in a sync context (due to using rusqlite) on a separate thread. The tracing crate can add conetxt to any logs (events). Due to the database interactions happening on a separate thread, this context gets lost. Enabling the tracing feature allows the information to be preserved. Related: dbrgn/tracing-test#23 Note: I don't know if this is something that should rather be implemented in the `spawn_blocking` method of Tokio.
|
I am encountering the same issue. Is there a good solution to this? |
|
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: |
|
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. |
|
I've created a test repo to play with different configurations: |
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::spawninstead of multi-threading tokio?The following passes first two tests but fails the third:
Results:
Cargo.toml contains
no-env-filter:The text was updated successfully, but these errors were encountered: