test(server): fix unit tests that sometimes capture no log events

[elyasmnvidian]

What

sse::tests::stream_client_error_warn_redacts_upstream_body fails in about 2% of runs of the server unit tests on main (31 of 1,450 runs at 47bba06). cargo test runs these tests in parallel by default. In a failing run, the test captures no log events, so it panics at the check that the stream iteration failed warning was logged:

thread 'sse::tests::stream_client_error_warn_redacts_upstream_body' panicked at crates/switchyard-server/src/sse.rs:247:9:
[]

The test never reaches the check it exists for: that the warning leaves out the upstream error body. With this PR, the test failed in 0 of 2,100 runs. The method is in the evidence section below.

This PR adds one test helper, with_subscriber, in crates/switchyard-server/src/testing.rs. The first time a test calls it, it sets a global tracing_subscriber::Registry with no layers for the rest of the test binary. Then it runs the test's code with the test's own subscriber through tracing::subscriber::with_default, as before. All three places in this crate's unit tests that capture tracing output now call the helper:

• the SSE test above
• captured_events in lib.rs, which three request-log tests use
• request_span_continues_incoming_w3c_trace_context in observability.rs

Production code does not change.

Why

tracing keeps a cache for each call site, which is one logging macro in the source, such as one warn! line. The cache records whether any subscriber wants that call site's events. tracing fills the cache the first time any thread reaches the call site. When exactly one subscriber is registered, tracing does not ask that subscriber. Instead, it asks the default subscriber of the thread that reached the call site (see Dispatchers::rebuilder in tracing-core 0.1.36, callsite.rs). A subscriber set with with_default counts as registered, even though only one thread uses it. On a thread with no subscriber, the default subscriber does nothing and answers "never".

The SSE test sets its capturing subscriber only on its own thread. Two other tests in the same module, stream_error_terminates_without_done_marker and anthropic_stream_error_uses_api_error_type, reach the same warn!("stream iteration failed") line in frame_stream with no subscriber. Here is one bad ordering (an illustration, not a log):

1. The SSE test sets its subscriber on thread 1. It is the only registered subscriber.
2. stream_error_terminates_without_done_marker reaches warn!("stream iteration failed") on thread 2 for the first time. tracing asks thread 2's default subscriber, which answers "never", and caches that answer for this line.
3. The SSE test reaches the same line. The cache says "never", so tracing skips the event, and the test's list of captured events stays empty.

The global Registry stays registered for the life of the process, and it wants every call site. While it is the only subscriber, a thread without its own subscriber uses it. Once the test's subscriber is also registered, tracing asks both subscribers. In either case, the cache cannot say "never". The Registry has no layers, so it writes no output and keeps no event data.

The request-log tests and the request-span test do not fail today. No other unit test in this crate reaches their call sites without a subscriber. But they capture output the same way, and a test that forces the bad ordering makes each of them fail like the SSE test (see the evidence below). With one helper, the explanation stays in one place, and new capture tests get the same protection.

Two other changes would also prevent the failure, but each costs more. --test-threads=1 would run every test in the binary one at a time. A shared lock would have to go into every test that reaches the same log line, including tests that do not capture logs.

Notes for reviewers

Start with crates/switchyard-server/src/testing.rs. In the other three files, one call changes from tracing::subscriber::with_default to the helper. lib.rs also declares the testing module.

Costs and limits:

• The global Registry exists only in the unit test binary, because the module is #[cfg(test)]. The integration tests in crates/switchyard-server/tests/ build separate binaries and do not change.
• Any span that a unit test creates outside a test subscriber now goes to the empty Registry. The Registry keeps the span's data until the span closes.
• If a future unit test in this crate sets its own global subscriber, for example by calling initialize_observability, that call returns an error when with_subscriber ran first. No unit test does this today. In the opposite order, with_subscriber ignores the error, because any global subscriber keeps the cache from saying "never".

Evidence: failure counts before and after

Method: I built the server unit test binary with cargo test -p switchyard-server --lib --no-run, once on main (47bba06) and once with this change. I copied both binaries and ran them from crates/switchyard-server. Each run executes all 29 unit tests with the default number of parallel test threads. The machine was an Apple M3 Pro with 12 cores, and other builds were running at the same time (load average 11 to 48). "10 busy CPU workers" means 10 yes > /dev/null processes running during the loop.

How the runs were scheduled	Before	After
Alternating one run before the change with one run after it	18/400 failed	0/400 failed
Alternating, with 10 busy CPU workers	2/300 failed	0/300 failed
One run at a time	6/300 failed	0/800 failed
Three copies of the binary running at once	4/150 failed	0/300 failed
One run at a time, with 10 busy CPU workers	0/150 failed	0/150 failed
Three copies at once, with 10 busy CPU workers	1/150 failed	0/150 failed
Total	31/1,450 failed	0/2,100 failed

Every failure before the change was the same panic at sse.rs:247:9 with []. No other test failed in any run. The busy CPU workers made the failure rarer, not more common.

Evidence: tests that force the bad ordering

I wrote three throwaway tests, one per call site; they are not part of this PR. Each test first reaches the call site on a new thread that has no subscriber. Then it reaches the call site again on the test thread, inside the capturing subscriber. I ran each test alone with --exact: 20 times with tracing::subscriber::with_default, and 20 times with with_subscriber.

Call site	With tracing::subscriber::with_default	With with_subscriber
warn!("stream iteration failed") in sse.rs	20/20 failed; capture was []	0/20 failed
"LLM request cancelled" event in lib.rs	20/20 failed; 0 events	0/20 failed
request_span in observability.rs	20/20 failed; trace ID was 00000000000000000000000000000000	0/20 failed

The SSE version, added to the tests module in sse.rs:

#[test]
fn forced_order_loses_the_warn_event() -> TestResult {
    let capture = WarnCapture::default();
    let subscriber = tracing_subscriber::registry().with(capture.clone());
    let body = tracing::subscriber::with_default(subscriber, || -> TestResult<String> {
        // A thread with no subscriber reaches the warn! line first.
        std::thread::spawn(|| {
            tokio::runtime::Builder::new_current_thread()
                .enable_all()
                .build()
                .unwrap()
                .block_on(chat_body(vec![Err(LlmStreamError::Client(
                    LlmClientError::General("other test".to_string()),
                ))]))
                .unwrap();
        })
        .join()
        .unwrap();
        tokio::runtime::Builder::new_current_thread()
            .enable_all()
            .build()?
            .block_on(chat_body(vec![Err(LlmStreamError::Client(
                LlmClientError::General("this test".to_string()),
            ))]))
    })?;
    assert!(body.contains("this test"));
    let events = capture.0.lock().unwrap().clone();
    assert!(
        events
            .iter()
            .any(|event| event.contains("stream iteration failed")),
        "{events:?}"
    );
    Ok(())
}

This test fails on every run. If you replace tracing::subscriber::with_default with crate::testing::with_subscriber, it passes on every run.

Summary by CodeRabbit

• Tests
  • Improved consistency in tests that capture tracing events, verify trace-context continuation, and check warning logs.
  • These test setup changes help ensure tracing output is available for assertions across the relevant test cases.

[coderabbitai]

Navigate logical layers of code changes, visualize relationships, and explore their blast radius.

No actionable comments were generated in the recent review. 🎉

ℹ️ Recent review info

⚙️ Run configuration

Configuration used: Repository: NVIDIA-NeMo/Switchyard/.coderabbit.yaml

Review profile: CHILL

Plan: Enterprise

Run ID: 76a14b04-1985-4eac-82b2-575b3a58969f

📥 Commits

Reviewing files that changed from the base of the PR and between 16cbe59 and 998abd8.

📒 Files selected for processing (4)

• crates/switchyard-server/src/lib.rs
• crates/switchyard-server/src/observability.rs
• crates/switchyard-server/src/sse.rs
• crates/switchyard-server/src/testing.rs

Included review availability: This review used your included allowance. Your plan provides up to 12 included reviews per hour; 9 remain after this review.

---

Walkthrough

The server adds a test-only tracing subscriber helper. Three tests use it instead of tracing::subscriber::with_default.

Changes

Tracing test support

Layer / File(s)	Summary
Add the shared subscriber helper crates/switchyard-server/src/lib.rs, crates/switchyard-server/src/testing.rs	The test-only module adds with_subscriber. On its first call, the helper attempts to install an empty global Registry, then runs the closure with the supplied thread-default subscriber.
Use the helper in tracing tests crates/switchyard-server/src/lib.rs, crates/switchyard-server/src/observability.rs, crates/switchyard-server/src/sse.rs	The captured-events, trace-context continuation, and warning-log tests call with_subscriber instead of tracing::subscriber::with_default. The assertions are unchanged.

Priority: ⬇️ Low

Estimated code review effort: 2 (Simple) | ~10 minutes

Merge Risk: ⚪ Minimal · up to 998ab

No actionable merge-blocking risk is identified; this test-only change is mergeable after normal checks.

🚥 Pre-merge checks | ✅ 4 | ❌ 1

❌ Failed checks (1 warning)

Check name	Status	Explanation	Resolution
Docstring Coverage	⚠️ Warning	Docstring coverage is 75.00% which is insufficient. The required threshold is 80.00%. Docstring coverage is scoped to functions touched by this diff. Analyzed 4 functions across 4 files.	Write docstrings for the functions missing them to satisfy the coverage threshold.

✅ Passed checks (4 passed)

Check name	Status	Explanation
Description Check	✅ Passed	Check skipped - CodeRabbit’s high-level summary is enabled.
Title check	✅ Passed	The title clearly and concisely describes the main change: fixing intermittent server unit tests that fail to capture log events.
Linked Issues check	✅ Passed	Check skipped because no linked issues were found for this pull request.
Out of Scope Changes check	✅ Passed	Check skipped because no linked issues were found for this pull request.

• Fix all pre-merge checks with AI

• Autopilot · Keep fixing CodeRabbit findings and required CI, and resolving merge conflicts

Autopilot is currently an internal CodeRabbit preview.

---

_{I’m a rabbit with a tracing tune,
I hop through tests beneath the moon.
A Registry greets the call,
Thread-default subscribers catch them all.
Three tests now share the way,
And I nibble clover to celebrate today.}

_{Comment @coderabbitai help to get the list of available commands.}