How to test for spans?

[najamelan]

I instrument futures with spans and would like to verify the correct spans are on my logs. This is my log without tracing-test:

let _ = tracing_subscriber::fmt::Subscriber::builder()

	   .with_max_level(tracing::Level::TRACE)
	   .try_init()
;

In my integration test gives:

May 23 11:48:24.707 TRACE thespis_impl::addr: CREATE Addr for: Creator (1)
May 23 11:48:24.708 TRACE actor{id=1}: thespis_impl::mailbox: mailbox: started for: Creator (1)
May 23 11:48:24.708 TRACE actor{id=1}: tracing: creating new actor
May 23 11:48:24.708 TRACE actor{id=1}: tracing: i am awaited within the handler on Creator
May 23 11:48:24.708 TRACE actor{id=1}: thespis_impl::addr: CREATE Addr for: Created (2, created)
May 23 11:48:24.708 TRACE actor{id=1}: async_io::driver: block_on()    
... much more lines of logs...

When replacing that with tracing-test macro, the assertion with logs_contain fails and the output shows:

---- tracing_nested_pool stdout ----
May 23 11:48:55.162 TRACE tracing: creating new actor
May 23 11:48:55.162 TRACE tracing: i am awaited within the handler on Creator
May 23 11:48:55.162 TRACE tracing: in created handler
May 23 11:48:55.162 TRACE tracing: a spawned subtask
thread 'tracing_nested_pool' panicked at 'assertion failed: logs_contain(r#\"actor{id=1 name=\"creator\"}: tracing: creating new actor\"#)', tests/tracing.rs:71:5
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace

It looks like it both lost a whole lot of the log lines, as well as the spans.

[dbrgn]

This is how the "mock subscriber" is initialized:

https://github.com/dbrgn/tracing-test/blob/main/tracing-test/src/subscriber.rs#L56-L66

It's been a while since I wrote that code, but we'd have to check how the span information is passed on to the subscriber. I'm currently a bit short on time, so if someone else wants to find out the reason for this behavior, contributions would be welcome!

[dbrgn]

Related to #2.

[najamelan]

Ok, I see. I admit I have been refraining from writing my own tracing subscriber because I find it a very complicated API. Most of the time I just want the kind of output tracing_subscriber::fmt::Subscriber gives, but when I looked into how it's done, it's hard to imagine how to re-use the underlying machinery on another subscriber. There is lots of types that have a ton of generics.

One possibility is to use with_writer API to just capture what fmt::Subscriber outputs. I suppose other subscribers can also provide a with_writer API which would in principle allow tracing_test to be used to test output of any subscribers. It is part of the Layer interface. TestWriter might also be of interest.

[najamelan]

Ah, sorry. I didn't realize that you were already using with_writer. Ok. I'll try to debug a bit why the output is different then.

[najamelan]

Ok, I found the first issue. The env filter restricts the log events to the current crate, but in case of integration tests that's the current file. In my case above that's "tracing". So no log events from my library that I am testing are in the output.

tracing-test/tracing-test-macro/src/lib.rs

Line 67 in 1e0f28f

let env_filter = format!("{}=trace", crate_name);

[najamelan]

I changed the subscriber code to:

        // .with_env_filter(env_filter)
        .with_max_level(tracing_core::Level::TRACE)

After this my test is still failing, but this is the output:

failures:

---- tracing_nested_pool stdout ----
May 24 20:04:05.345 TRACE tracing_nested_pool: thespis_impl::addr: CREATE Addr for: Creator (1, creator)
May 24 20:04:05.346 TRACE actor{id=1 name="creator"}: thespis_impl::mailbox: mailbox started for: Creator (1, creator)
May 24 20:04:05.346 TRACE actor{id=1 name="creator"}: thespis_impl::mailbox: actor Creator (1, creator) will process a message.
May 24 20:04:05.346 TRACE actor{id=1 name="creator"}: tracing: creating new actor
May 24 20:04:05.346 TRACE actor{id=1 name="creator"}: tracing: i am awaited within the handler on Creator
May 24 20:04:05.346 TRACE actor{id=1 name="creator"}: thespis_impl::addr: CREATE Addr for: Created (2, created)
May 24 20:04:05.346 TRACE actor{id=2 name="created"}: thespis_impl::mailbox: mailbox started for: Created (2, created)
May 24 20:04:05.346 TRACE actor{id=2 name="created"}: thespis_impl::mailbox: actor Created (2, created) will process a message.
May 24 20:04:05.346 TRACE actor{id=2 name="created"}: tracing: in created handler
May 24 20:04:05.347 TRACE actor{id=2 name="created"}:handle request: tracing: a spawned subtask
May 24 20:04:05.348 TRACE actor{id=2 name="created"}: thespis_impl::mailbox: actor Created (2, created) finished handling it's message. Waiting for next message
May 24 20:04:05.348 TRACE actor{id=1 name="creator"}: thespis_impl::addr: DROP Addr for: Created (2, created)
thread 'tracing_nested_pool' panicked at 'assertion failed: logs_contain(r#\"tracing: creating new actor\"#)', tests/tracing.rs:82:5
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace
May 24 20:04:05.348 TRACE actor{id=2 name="created"}: thespis_impl::mailbox: Mailbox stopped actor for Created (2, created)
May 24 20:04:05.348 TRACE actor{id=1 name="creator"}: thespis_impl::mailbox: actor Creator (1, creator) finished handling it's message. Waiting for next message
May 24 20:04:05.348 TRACE tracing_nested_pool: thespis_impl::addr: DROP Addr for: Creator (1, creator)

The text I'm looking for is literally in there, so I don't yet know why logs_contains fails. In any case it looks like the env filter was also filtering out the spans (they are created in the lib, not in the test file).

[najamelan]

The reason my test was still failing is that logs_contain tries to match the "scope" as well as the text being searched. This scope is based on a Span being injected in the test function. However, spans are thread-local and I spawn futures on a threadpool (which is common in async code). Thus, the span doesn't get applied to events that occur in other threads.

So in conclusion, I think a more robust method is needed. It might be a solution to just keep track of the index in the buffer when the test starts and and ends, or log a specific string like BEGIN --- scope_name --- BEGIN and END --- scope_name --- END. On top of that, libtest runs tests in parallel by default, so it might be necessary to tell it not to in order for this to work. It would be good to have a proper warning in the readme/api docs about how tracing-test behaves in a multi-threaded environment.

For the env_filter, it might be better to allow an attribute on the macro if people want to filter. Most of the time I would assume that the statements that people want to test on are sufficiently unique that other crates's log output doesn't change the outcome of the assert.

[threema-danilo]

Hi @najamelan, thanks for your investigations! Yeah, the fact that scope matching is a bit wonky is the reason why this library is still marked as experimental... 😕

Disallowing parallel test runs is a bad idea in my view. We should try to find a solution that does not rely on non-interleaved tests.

Thus, the span doesn't get applied to events that occur in other threads.

Ahh, this statement confused me a bit, since here we have a test that spawns an async task on another thread. Being able to capture logs that are logged on other threads are precisely why this library exists.

However, right now this only works for async logs on another thread (within the Tokio runtime), but not if the logs are in sync code on another thread. I'll have to investigate what our possibilities are. Right now, being able to apply a span to the code-under-test is important for the functionality we have (as you noticed).

For the env_filter, it might be better to allow an attribute on the macro if people want to filter. Most of the time I would assume that the statements that people want to test on are sufficiently unique that other crates's log output doesn't change the outcome of the assert.

That might be a valid workaround for now.

[threema-danilo]

For the record, to quote this reply:

Entering a span is per-thread by design, because in many cases each thread in a program is executing a separate logical unit of work, and it wouldn't make sense to propagate them by default.

[threema-danilo]

For the record, in #3 @mooreniemi contributed a reproducer test:

#[traced_test]
#[test]
fn annotate_target_sync_test() {
    assert!(!logs_contain("Logging from a non-async test"));
    info!(target: "target", "Logging from a non-async but targeted test");
    assert!(logs_contain("Logging from a non-async but targeted test"));
    assert!(!logs_contain("This was never logged"));
}