how logs_contain for *_span! works?

[mooreniemi]

Hi, I'm a newbie to Rust and learning the tracing library. I don't have a great mental model yet, so I apologize if this ends up being very obvious once I get that.

I wanted to use this crate to check log output where I am using the info_span! and error_span! but it doesn't work as I'd expect. I'd expect all spans to still be getting intercepted by the global write buffer such that I can check them with logs_contain.

I'm going to try to understand and report back here why this would be, but if you intercept this first maybe it can go into the documentation?

Using the documented setup I can see tracing::info! just fine in a test, but not tracing::info_span!:

// in the method I am testing
    tracing::info!("meow and some other words");
    tracing::info_span!("bark and some other words");

// in my test, annotated
    assert!(logs_contain("meow")); // passes
    assert!(logs_contain("bark")); // fails

What I see in logs:

---- test_name_removed stdout ----
Apr 08 14:57:53.783  INFO test_name_removed: class::etc: meow and some other words
thread 'my_crate::tests::my_test' panicked at 'assertion failed: logs_contain("bark")', src/file_name.rs:297:9
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace

[mooreniemi]

I've worked through my confusion now. Just generating the span doesn't itself log anything. It just creates a context in which the logged events would happen. So if the future I instrumented with an info_span (what I'm actually doing) doesn't itself log anything, I won't see anything via logs_contain. Once I added something inside the future I saw the log as expected.

[dbrgn]

Hehe, yeah. That gotcha also bit me a few times 🙂 Good that you could figure it out!