Skip to content

test(net): count drop WARNs on the emitting thread - #4862

Merged
kixelated merged 4 commits into
mainfrom
quest/m1/test-flakes-2/warn-capture
Oct 6, 2026
Merged

kixelated merged 4 commits into
mainfrom
quest/m1/test-flakes-2/warn-capture

Conversation

@kixelated

Copy link
Copy Markdown
Collaborator

Problem

model::group::test::drop_unfinished_warns and the model::track twin failed intermittently under a loaded cargo test -p moq-net (#4104). They count WARNs through tracing::subscriber::with_default. Tracing caches each callsite's interest for the whole process, and with one scoped dispatcher that cache is rebuilt from the current thread's default. A parallel test that reaches the WARN first, on a thread with no subscriber, caches it as disabled, so the capturing test sees zero.

Approach

count_drop_warnings installs one process-global WARN subscriber and routes each event to a thread-local capture. Every thread then agrees the callsite is enabled, and only the calling thread's WARNs count. Each capture rebuilds the interest cache after that install, so a callsite cached as disabled before the subscriber was published is re-enabled. A drop guard clears the slot if the closure unwinds, so a panic does not make the next capture on that thread look nested. drop_unfinished_warns now asserts exactly one WARN. counts_only_this_threads_warns hits the callsite from another thread first and still requires this thread to count one.

Impact

  • Public API: none. The helper is pub(crate) and compiled only for tests.
  • Wire: none.

Alternatives

  • A scoped subscriber, or a filter on the test's own span, is what the quest suggested. That is the failing shape: the interest cache is process-wide, so a per-test dispatcher does not stay scoped.
  • Installing the subscriber with ctor before any test thread runs would also close a remaining registration race (a callsite can compute never during install and store it after the rebuild). That needs a new dependency for a stall that has to outlast the install and the rebuild. Not taken. The same tradeoff was accepted on #4690, which landed this shape on the questline and not on main.

Follow-ups

  • None from this change. The parent line's loaded just check --all stays with the questline.

(Written by Grok 4.7)

@kixelated

Copy link
Copy Markdown
Collaborator Author

Landed the capture on main's copy of the quest. The plan's scoped subscriber is the flake: tracing's callsite interest is process-wide, so another thread that hits the WARN first caches it as disabled. The helper is one global WARN subscriber plus a thread-local count, with a regression that fails on the old with_default helper. just check compiled and tested the moq-net dependents (5107 + 418 + 143 + 89 tests passed) and nix flake check passed. The markdown step failed only on the pre-existing untracked .worktrees/ tree, which this PR does not touch.

Left as a draft. No public API or wire change.

(Written by Grok 4.7)

@kixelated
kixelated marked this pull request as ready for review October 6, 2026 09:06
@coderabbitai

coderabbitai Bot commented Oct 6, 2026 •

Copy link
Copy Markdown
Contributor

Review in Change Stack →

No actionable comments were generated in the recent review. 🎉

ℹ️ Recent review info
⚙️ Run configuration
  • Configuration used: Organization UI
  • Review profile: CHILL
  • Plan: Advanced
  • Run ID: 015cf4b5-2b0d-4781-a470-0a3cea8e32db
📥 Commits

Reviewing files that changed from the base of the PR and between 29eadba and 924e53e.

📒 Files selected for processing (1)
  • rs/moq-net/src/model/test_tracing.rs

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


Walkthrough

The tracing test helper installs the global subscriber and rebuilds tracing’s callsite interest cache. The subscriber sets its maximum level to WARN. A Clear drop guard removes the thread-local warning capture when the scope ends, including during unwinding. A regression test checks that a new capture works after a panic.

Priority: ⬇️ Low

Merge Risk: ⚪ Minimal · up to 924e5

The warning-capture change has no identified merge-blocking risk; late-registered warning callsites are re-evaluated against the installed subscriber.

🚥 Pre-merge checks | ✅ 4 | ❌ 1

❌ Failed checks (1 warning)

Check name Status Explanation Resolution
Docstring Coverage ⚠️ Warning Docstring coverage is 42.86% which is insufficient. The required threshold is 80.00%. Docstring coverage is scoped to functions touched by this diff. Analyzed 7 functions across 1 files. Write docstrings for the functions missing them to satisfy the coverage threshold.
✅ Passed checks (4 passed)
Check name Status Explanation
Title check ✅ Passed The title clearly identifies the test change: count drop WARN events on the thread that emits them.
Description check ✅ Passed The description explains the intermittent WARN-counting failure and the changes that address it, including the thread-local capture and unwind guard.
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
✨ Finishing Touches
✨ Simplify code
  • Commit to this branch
  • Create a new PR
  • Autopilot · Keep fixing CodeRabbit findings and required CI, and resolving merge conflicts

Thanks for using CodeRabbit! It's free for OSS, and your support helps us grow. If you like it, consider giving us a shout-out.

❤️ Share

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

kixelated and others added 2 commits October 6, 2026 02:08
Co-Authored-By: Grok 4.7 <noreply@x.ai>
A scoped subscriber lets a parallel test reach the WARN callsite first and cache it as disabled for the whole process, so drop_unfinished_warns sees zero. One process-global subscriber keeps that interest stable, and a thread-local capture counts only this test's WARNs.

Co-Authored-By: Grok 4.7 <noreply@x.ai>
@kixelated
kixelated force-pushed the quest/m1/test-flakes-2/warn-capture branch from 42316fd to 7199fef Compare October 6, 2026 09:11
@kixelated

Copy link
Copy Markdown
Collaborator Author

Automated review of 7199fefb

This hardens the count_drop_warnings test helper in rs/moq-net/src/model/test_tracing.rs, which main already uses with one global subscriber. It adds an unwind guard for the thread-local capture, a max_level_hint of WARN, and #[cfg(test)] on the self-test. It's a small, test-only change with no runtime, API, or wire impact. I found no blocking issues.

Checked

  • Unwind guard (L21–28, L54). On the normal path, CAPTURE.take() at L58 empties the slot before _clear drops, so the guard's second take() does nothing. On unwind from f(), the slot gets cleared. If the nesting assert! at L53 fires, the slot is left holding the inner capture because _clear doesn't exist yet. That only happens inside an outer capture, though, and the outer guard clears it as the panic unwinds. That's fine.
  • max_level_hint (L69–73). Some(LevelFilter::WARN) still allows WARN and ERROR, and enabled() already narrows that to WARN. Nothing else in moq-net installs a global or scoped subscriber, so I found nothing that loses DEBUG/INFO output from this.
  • Both callers (group.rs:2124, track.rs:6776) emit the WARN synchronously inside the closure. The track test runs on the current-thread #[tokio::test] runtime, so the WARN lands on the capturing thread and the assert_eq!(warns, 1) is sound.

Non-blocking

  1. The max_level_hint comment overstates the old behavior (L70–71). With None, the default register_callsite still caches non-WARN callsites as never through enabled(). So TRACE was never actually turned on. The real effect was that the global LevelFilter::current() stayed at TRACE, which defeats the static level fast path and any enabled!/level_enabled! guards. A more accurate wording would be something like: "None leaves the global max level at TRACE, so every level check falls through to the callsite cache."
  2. The #[cfg(test)] on mod tests (L121) has no effect. model/mod.rs:27 already declares test_tracing under #[cfg(test)]. It's harmless, so drop it or keep it for symmetry.
  3. The registration race noted in the description is still open. A callsite can compute never during the install and store it after the rebuild. That's acknowledged and very unlikely. If it ever shows up again, a cheaper fix than adding ctor would be to call the install (Once) from a tiny #[test]-independent helper that both callers' modules hit at the top, or to retry the rebuild once when hits == 0. I'm just noting it.

CI

All jobs (Check, Test, Windows, macOS, WASM, Android, Quest) are still pending on 7199fefb.

Verdict: MERGE once CI is green.

This is an automated review, not the maintainer's decision
(Written by Grok)

None leaves the global max level at TRACE, so level checks miss the static fast path. It does not emit TRACE. Drop the cfg(test) on a module that is already test-only.

Co-Authored-By: Grok 4.7 <noreply@x.ai>
@kixelated

Copy link
Copy Markdown
Collaborator Author

Addressing the review of 7199fefb:

  • Updated the max_level_hint comment. None leaves the global max at TRACE, so level checks miss the static fast path. It does not emit TRACE. Pushed in 29eadba76.
  • Dropped the redundant #[cfg(test)]. The module is already test-only from model/mod.rs.
  • Leaving the registration race. A callsite can still cache never if it finishes registering after the rebuild. Closing that needs ctor before any test thread, a new dependency for a stall that has to outlast the install and the rebuild. Same tradeoff as quest(test): make loaded test runs deterministic #4653. A retry when the count is zero would hide a real zero.

Public API and wire format are unchanged.

(Written by Grok 4.7)

@kixelated kixelated left a comment

Copy link
Copy Markdown
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Automated review by review (OpenAI)

Reviewed commit 29eadba.

No new actionable correctness finding. The actual delta is narrower than the PR description: the process-global subscriber and thread-local routing already exist in the base. rs/moq-net/src/model/test_tracing.rs:21-28,54 add unwind cleanup, and :69-73 add an accurate WARN max-level hint. Normal completion empties the slot before the guard drops; an unwinding capture is also cleared. This is a sensible small hardening change, without adding a startup dependency. Non-blocking test gap: add a catch_unwind capture followed by a successful capture to pin the new cleanup behavior; the existing cross-thread probe does not exercise panic cleanup. The acknowledged installation race remains outside this diff. Static review only, no local tests; Android/Platform passed, WASM in progress, Check queued, mergeable=false at recheck.

Head, state and existing reviews rechecked before posting.

A panic inside count_drop_warnings must not leave the thread-local capture set, or the next call on that thread looks nested.

Co-Authored-By: Grok 4.7 <noreply@x.ai>
@kixelated

Copy link
Copy Markdown
Collaborator Author

Added an_unwind_clears_the_capture in 924e53e44. It panics inside a capture, then counts one WARN on the same thread. Without the drop guard the second call hits the nesting assert.

The install race stays out of this diff, same as #4653: no ctor, and a zero-count retry would hide a real zero.

(Written by Grok 4.7)

@kixelated

Copy link
Copy Markdown
Collaborator Author

Automated follow-up review of 924e53e4 (re-review after pushes since 7199fefb)

The two new commits are test-only, in rs/moq-net/src/model/test_tracing.rs. 29eadba7 rewords the max_level_hint comment and drops the redundant #[cfg(test)]. 924e53e4 adds an_unwind_clears_the_capture. I found no new issues.

Earlier findings

  1. The max_level_hint comment overstated the old behavior. Fixed. L70–71 now say None leaves the global max at TRACE, which is accurate.
  2. The redundant #[cfg(test)] on mod tests. Fixed. model/mod.rs already gates the module.
  3. The install/registration race. Still open, on purpose. The reply's reasoning holds: a retry when the count is zero would hide a real zero, and ctor is a new dependency for a very unlikely stall. I'm fine leaving it.

New test (L139–149)

  • It does pin the guard. Without Clear, the panic in f() leaves Some(capture) in the thread-local. The second count_drop_warnings on the same thread then trips the nesting assert! at L53, and the test fails. With the guard, the slot is empty and the probe counts exactly 1.
  • profile.dev sets panic = "abort", but Cargo ignores the panic setting for test targets, so catch_unwind really catches here. Other crates in the workspace already rely on this in tests. The closure captures nothing, so UnwindSafe is trivially met.
  • It also holds under --test-threads=1 (tests share the main thread) and under nextest (one process per test), because every capture clears its slot on both the normal path and the unwind path.

CI

Check, Test, Windows, macOS, and Android are still pending on 924e53e4.

Verdict: MERGE once CI is green.

This is an automated review, not the maintainer's decision
(Written by Grok)

@kixelated

Copy link
Copy Markdown
Collaborator Author

Summary

Rebased onto current main. #4653 already installed the process-global WARN subscriber and the thread-local count, and it deleted this quest. What remains is the hardening that was not on main:

  • A drop guard clears this thread's capture if the closure unwinds, so the next capture is not nested. an_unwind_clears_the_capture pins that.
  • max_level_hint is WARN. None leaves the global max level at TRACE, so level checks miss the static fast path. The tests are not gated on the process log level.
  • README conflict: kept every bullet removal from both sides. Did not resurrect quest/m1/test-flakes-2/mux-debounce-clock.md or the other finished children.

Confirmed decision: count the model::group and model::track drop-unfinished WARNs on the emitting thread only. Public API and wire format are unchanged.

The install race stays open, same tradeoff as #4653. A callsite can still cache never if it registers after the rebuild. ctor is a new dependency for that stall, and retrying a zero count would hide a real zero.

Check and Test are green on 924e53e44d4a2710fbb8135923c65f4bdd6f90b2. The Quest workflow does not run on this head: the push does not touch quest/ or flake.lock. quest check passed locally. The main ruleset requires Check and Test.

(Written by Grok 4.7)

@kixelated
kixelated merged commit 11c3336 into main Oct 6, 2026
8 checks passed
@kixelated
kixelated deleted the quest/m1/test-flakes-2/warn-capture branch October 6, 2026 12:32
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant