logs_contain does not work if message contains line break

[nthuemmel-scontain]

If a log message contains a line break, logs_contain always returns false for the same message.

Example to reproduce:

fn main() {}

#[test]
#[tracing_test::traced_test]
fn line_break() {
    tracing::info!("foo\nbar");
    assert!(logs_contain("foo\nbar"));
}

Error message when running test:

     Running unittests src/main.rs (target/debug/deps/tracinglinebreak-853b0990bd23df31)
2024-12-16T13:13:09.706270Z  INFO line_break: tracinglinebreak: foo
bar

assertion failed: logs_contain("foo\nbar")
thread 'line_break' panicked at src/main.rs:9:5:
assertion failed: logs_contain("foo\nbar")
stack backtrace:
   0: rust_begin_unwind
             at /rustc/129f3b9964af4d4a709d1383930ade12dfe7c081/library/std/src/panicking.rs:652:5
   1: core::panicking::panic_fmt
             at /rustc/129f3b9964af4d4a709d1383930ade12dfe7c081/library/core/src/panicking.rs:72:14
   2: core::panicking::panic
             at /rustc/129f3b9964af4d4a709d1383930ade12dfe7c081/library/core/src/panicking.rs:146:5
   3: tracinglinebreak::line_break
             at ./src/main.rs:9:5
   4: tracinglinebreak::line_break::{{closure}}
             at ./src/main.rs:7:16
   5: core::ops::function::FnOnce::call_once
             at /rustc/129f3b9964af4d4a709d1383930ade12dfe7c081/library/core/src/ops/function.rs:250:5
   6: core::ops::function::FnOnce::call_once
             at /rustc/129f3b9964af4d4a709d1383930ade12dfe7c081/library/core/src/ops/function.rs:250:5

This is likely due to this filter: https://docs.rs/tracing-test/0.2.5/src/tracing_test/internal.rs.html#47 (.filter(|line| line.contains(&format!(" {}:", scope))))

Tested with v0.2.5

[dbrgn]

Do you have a good idea on how to solve this?

Probably we'll have to implement more elaborate log separator detection.

[nthuemmel-scontain]

Some ideas would be:

1. Store logs in individual buffers for each test, such that we can distinguish between entries of different tests without having to rely on line breaks or know the scope value of all of the tests.

• Either keep the current Vec<u8> already-formatted storage and filter by scope value to differentiate between entries within a single test as is done now (but treat all lines until the next scope value occurrence as one entry),
• Or store structured log events directly, applying formatting on them only when iterating during evaluation,
• Or have a wrapping subscriber that swaps the buffer underneath the FmtSubscriber's writer after each log event, accumulating into a Vec<Vec<u8>> or Vec<String> (one already-formatted entry per event)

2. To route between the buffers for each test, one could

• Use a scope-level dispatcher (https://docs.rs/tracing/0.1.41/tracing/dispatcher/fn.set_default.html)
• Keep using a global dispatcher but add an intermediate subscriber that delegates to the correct per-test subscriber based on the scope value

I don't have experience with implementing custom subscribers though, so please leave a comment if you see that something won't work ;)

[pronebird]

I think that's a good idea to store each entry as individual buffer, matching it should be fairly simple then.