test: keep tracing callsites enabled so log-capture tests stop flaking - #909
Conversation
`auth::tests::a_missing_credential_denial_names_the_caller_and_the_route` fails intermittently on main: the capture returns an empty buffer even though the subscriber is installed and the denial is emitted. A callsite's `Interest` is cached process-wide the first time that callsite is hit, computed from whatever dispatcher the *hitting* thread has. `capture_logs` installs its subscriber with `set_default`, which is thread-local, so when a sibling test reaches the same unauthenticated path on another thread the callsite resolves against `NoSubscriber`, caches `Interest::never()`, and the event is skipped everywhere from then on -- including inside the capture. Dozens of router tests hit that path, so under the parallel harness the race is routine. Install a bare `Registry` as the global default before capturing. It formats nothing, but it means no thread ever falls back to `NoSubscriber`, so no callsite is cached as disabled; registering it also re-evaluates the callsites seen so far, so the lazy install repairs a cache poisoned earlier in the run. The same helper shape in aisix-guardrails has the same defect and gets the same guard. `aisix-obs`'s `with_default` sites are not exposed: the access-log callsite is only ever emitted from inside those captures.
|
No actionable comments were generated in the recent review. 🎉 ℹ️ Recent review info⚙️ Run configurationConfiguration used: Organization UI Review profile: CHILL Plan: Pro Run ID: 📒 Files selected for processing (4)
📝 WalkthroughWalkthroughThe changes add test-only tracing initialization that keeps callsites enabled and repairs cached interests. Guardrails and proxy log-capture helpers invoke this initialization before installing capture subscribers. ChangesTracing callsite retention
Estimated code review effort: 2 (Simple) | ~10 minutes Possibly related PRs
Suggested reviewers: 🚥 Pre-merge checks | ✅ 5 | ❌ 1❌ Failed checks (1 warning)
✅ Passed checks (5 passed)
✨ Finishing Touches📝 Generate docstrings
🧪 Generate unit tests (beta)
Comment |
There was a problem hiding this comment.
Pull request overview
Stabilizes tracing log-capture tests by preventing process-wide callsite disabling.
Changes:
- Registers a silent global tracing registry in test binaries.
- Applies the guard to proxy authentication and guardrail log-capture helpers.
Reviewed changes
Copilot reviewed 4 out of 4 changed files in this pull request and generated no comments.
| File | Description |
|---|---|
crates/aisix-proxy/src/auth.rs |
Enables tracing callsites before authentication log capture. |
crates/aisix-guardrails/src/lib.rs |
Adds the shared test-only tracing initializer. |
crates/aisix-guardrails/src/aliyun.rs |
Initializes tracing before Aliyun log capture. |
crates/aisix-guardrails/src/aliyun_ai_guardrail.rs |
Initializes tracing before AI Guardrail log capture. |
💡 Add Copilot custom instructions for smarter, more guided reviews. Learn how to get started.
Problem
auth::tests::a_missing_credential_denial_names_the_caller_and_the_routefails intermittently onmain— it took down therust unit + coveragejob on the push run for #904 (run 31137791884):The captured buffer is empty even though the subscriber is installed and the denial is emitted. Adding a marker event inside the same capture scope shows the marker but not the denial, so the subscriber and the thread are fine — the specific callsite is disabled.
Root cause
A callsite's
Interestis cached process-wide the first time that callsite is hit, and it is computed from whatever dispatcher the hitting thread has (tracing_core::callsite::rebuild_callsite_interest, which falls through todispatcher::get_defaulton that thread while only one dispatcher is registered).capture_logsinstalls its subscriber withset_default, which is thread-local. When a sibling test reaches the same unauthenticated request path on another thread, that thread resolves toNoSubscriber, the callsite is cached asInterest::never(), and the event is skipped everywhere from then on — including inside the capture. Dozens of router tests hit the unauthenticated path, so under the parallel harness this is routine rather than exotic.Fix
Install a bare
Registryas the global default before capturing. It formats and writes nothing, but it means no thread ever falls back toNoSubscriber, so no callsite is ever cached as disabled. Registering a dispatcher also re-evaluates the callsites seen so far, so the lazy install repairs a cache already poisoned earlier in the run.The same helper shape in
aisix-guardrails(aliyun.rs,aliyun_ai_guardrail.rs) has the same defect and gets the same guard — its existingTRACING_CAPTURE_LOCKonly orders capture tests against each other and does nothing about callsites registered by unrelated tests. A permanently registered dispatcher also pins the global max-level hint, which is the symptom that lock was originally added for.aisix-obs's threewith_defaultsites are audited and not exposed: the access-log callsite is only ever emitted from inside those captures, so every thread that can register it already has a subscriber. Left unchanged.Verification
Same command, same machine,
--test-threads=64to raise the interleaving pressure:aisix-proxy --libaisix-guardrails --libSuite wall-clock is unchanged (
aisix-proxy12.69s → 12.66s at default threads), which is why the fix uses a bare registry rather than a discardingfmtsubscriber — the latter formats every event and cost ~1s on the guardrails suite.Workspace
cargo clippy --all-targets -- -D warningsandcargo fmt --checkare clean.No new test
The trigger is a process-global, order-dependent race in tracing's callsite cache: a callsite is registered at most once per process and cannot be un-registered, so the poisoning window cannot be forced deterministically from inside the same test binary. Verified statistically instead, as above.
Summary by CodeRabbit