Skip to content

fix(cache): defer TUI warnings until terminal restore - #1065

Merged
junhoyeo merged 4 commits into
junhoyeo:mainfrom
fzlzjerry:agent/fix-tui-cache-warning
Aug 9, 2026
Merged

fix(cache): defer TUI warnings until terminal restore#1065
junhoyeo merged 4 commits into
junhoyeo:mainfrom
fzlzjerry:agent/fix-tui-cache-warning

Conversation

@fzlzjerry

@fzlzjerry fzlzjerry commented Aug 7, 2026

Copy link
Copy Markdown
Contributor

What changed

  • defer cache persistence warnings while the TUI owns raw mode and the alternate screen
  • flush deferred warnings after terminal restoration while preserving once-per-context behavior
  • coordinate warning routing and TUI state changes to prevent enqueue-after-flush races
  • add regression coverage for warning deferral, formatting, and deduplication

Why

warn_cache_failure_once previously recorded the warning context before checking whether the TUI was active. A cache failure during a TUI session therefore consumed the once-per-process warning while suppressing its only visible output, leaving users with repeated cold reparses and no diagnostic.

This addresses the cache-warning subtask in #941 without closing the umbrella issue.

Validation

  • cargo fmt --all -- --check
  • cargo clippy --locked --workspace --all-features -- -D warnings
  • targeted cache-warning and TUI deferral regression tests
  • cargo test --workspace --all-features: 2,665 tests passed; one unrelated permission test fails under a root container because root can read a chmod 000 fixture. The failure reproduces on clean upstream/main, and the same test passes as a non-root user.

Summary by cubic

Defers cache warnings while the TUI owns the terminal and flushes them after restore, preventing screen corruption and ensuring the once-per-context warning shows. Hardens the warning path against a poisoned once-only set, and fixes the test guard to preserve deferred output in nested active scopes.

  • Bug Fixes
    • Route cache warning fallback via tui_signal::emit_or_defer_stderr; keep once-per-context behavior without consuming it during TUI.
    • Flush deferred stderr on restore by calling set_tui_active(false) last; coordinate state and queue behind a shared lock to avoid enqueue-after-flush races.
    • Recover from a poisoned once-only set using unwrap_or_else(...into_inner()); factor warn_cache_failure_once_in so tests isolate a poisoned set.
    • Add TuiActiveGuard; restore previous state in a single transition so nested active scopes keep their deferred diagnostics; add regression test.

Written for commit 314435d. Summary will update on new commits.

Review in cubic

@vercel

vercel Bot commented Aug 7, 2026

Copy link
Copy Markdown
Contributor

The latest updates on your projects. Learn more about Vercel for GitHub.

1 Skipped Deployment
Project Deployment Actions Updated (UTC)
tokscale Ignored Ignored Preview Aug 9, 2026 5:26am

Request Review

@fzlzjerry
fzlzjerry marked this pull request as ready for review August 7, 2026 16:25
Copilot AI lite review requested due to automatic review settings August 7, 2026 16:25

Copilot AI left a comment

Copy link
Copy Markdown

Choose a reason for hiding this comment

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

Pull request overview

This PR fixes suppressed cache persistence warnings during TUI sessions by deferring stderr diagnostics while the TUI owns raw mode/alternate screen, then flushing them after terminal restoration so the once-per-context warning is still visible.

Changes:

  • Add a deferred-stderr queue in tokscale-core (tui_signal) and a helper to emit immediately or defer based on TUI activity.
  • Route cache persistence warnings through the new deferral mechanism instead of suppressing them (fixing the once-only warning being “consumed” invisibly during TUI).
  • Adjust TUI terminal restoration order to flush deferred diagnostics only after leaving the alternate screen / disabling raw mode; add regression tests for deferral and dedup behavior.

Reviewed changes

Copilot reviewed 3 out of 3 changed files in this pull request and generated 1 comment.

File Description
crates/tokscale-core/src/tui_signal.rs Introduces deferred stderr routing + flush on set_tui_active(false) with race-safe coordination via a shared mutex.
crates/tokscale-core/src/message_cache.rs Switches cache warning fallback to emit_or_defer_stderr and adds regression test for deferral + once-only behavior.
crates/tokscale-cli/src/tui/mod.rs Ensures deferred diagnostics flush only after terminal restore steps so they don’t corrupt the alternate screen.

💡 Add Copilot custom instructions for smarter, more guided reviews. Learn how to get started.

Comment on lines +115 to +121
static WARNED_CONTEXTS: OnceLock<Mutex<HashSet<&'static str>>> = OnceLock::new();
let warned = WARNED_CONTEXTS.get_or_init(|| Mutex::new(HashSet::new()));
if warned.lock().is_ok_and(|mut warned| warned.insert(context))
&& !crate::tui_signal::is_tui_active()
{
eprintln!("tokscale: warning: {context} ({}): {error}", path.display());
if warned.lock().is_ok_and(|mut warned| warned.insert(context)) {
crate::tui_signal::emit_or_defer_stderr(format!(
"tokscale: warning: {context} ({}): {error}",
path.display()
));

@cubic-dev-ai cubic-dev-ai Bot left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

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

All reported issues were addressed across 3 files

Reply with feedback, questions, or to request a fix.

Re-trigger cubic

Comment thread crates/tokscale-core/src/message_cache.rs Outdated
@fzlzjerry

Copy link
Copy Markdown
Contributor Author

@junhoyeo pls review, thank you💗

@junhoyeo

junhoyeo commented Aug 8, 2026

Copy link
Copy Markdown
Owner

Reviewed as part of a sweep across the open PRs. The diagnosis is exactly right — recording the warning context before checking whether the TUI owns the terminal consumed the once-per-process budget while suppressing the only visible output — and deferring to terminal-restore is the right shape. I walked the lock order in tui_signal.rs and message_cache.rs after the change looking for the classic A-then-B / B-then-A inversion that "coordinate with a shared lock" usually introduces, and did not find one.

Both bot threads are pointing at the same real thing and I would fix it:

warn_cache_failure_once drops the warning on a poisoned mutex. warned.lock().is_ok_and(...) evaluates to false when the mutex is poisoned by an unrelated panic, so the warning is silently discarded — which is precisely the silent-failure this PR exists to remove. tui_signal.rs already handles poisoning correctly at its lock sites in this same changeset, so the two files disagree with each other:

let mut warned = WARNED_CONTEXTS
    .lock()
    .unwrap_or_else(|poisoned| poisoned.into_inner());

Two smaller notes:

  • is_tui_active has no production callers left after this PR — it survives as internal glue for route_stderr plus test scaffolding, while remaining public API that invites re-adding the suppression pattern this change removes. Worth demoting to pub(crate) or removing.
  • The new test asserts exact-vector equality on a process-global queue while TUI_ACTIVE is set. That is fine under #[serial], but if it is not serialized a concurrent non-serial test appending a second entry would make it flaky. Worth confirming it carries the attribute.

One pre-existing gap this PR does not cause but sits right next to: degrade_source in pricing/mod.rs writes a raw eprintln! that does not go through emit_or_defer_stderr, so a pricing-fetch failure still corrupts the alternate screen — the same class of corruption #906 and this PR address. Probably a follow-up rather than scope creep here, but worth capturing before it is forgotten.

Note no build or test leg ran on this branch — the first-time-contributor gate meant only cubic executed — so worth approving a CI run before merge.

@junhoyeo

junhoyeo commented Aug 8, 2026

Copy link
Copy Markdown
Owner

Approved the workflow runs so this branch finally got a build. Results, and one thing you will want to know before rebasing:

Lint and Ubuntu tests pass. Windows failed — but not because of your change.

test headless_capture_fast_success_does_not_wait_for_timeout ... FAILED
test headless_capture_fast_nonzero_preserves_exit_code ... FAILED
test headless_capture_slow_command_times_out ... FAILED
  fast failure waited too long: 11.0576809s

All three assert elapsed < Duration::from_secs(8) in wall-clock around a spawned fake codex binary. The runner took 11s. It is a timing flake in tests that have nothing to do with tui_signal or message_cache — your deferral path is not on that code path at all.

The part worth acting on: the run's top-level conclusion still says success even though that job failed, because this branch's base predates #1068, when the Windows leg was still continue-on-error. On current main that leg is a hard gate. So the moment you rebase — which you need anyway, the branch is 6 commits behind — this pre-existing flake stops being advisory and starts blocking the merge.

That is not a reason to avoid rebasing; it just means a red Windows leg after the rebase is most likely this flake rather than anything you introduced, and re-running the job is the first thing to try. For reference, cargo test --workspace --all-features is green on current main locally, and the recent PRs based at main HEAD all pass their Windows legs, so this is intermittent rather than persistent.

Probably worth a separate issue about the 8-second budget: a wall-clock assertion that tight is fragile on a contended Windows runner, and it matters more now that the leg is a hard gate than it did when it was advisory.

The poisoned-mutex fix in my earlier comment still stands as the one thing I would change before merge.

@junhoyeo

junhoyeo commented Aug 9, 2026

Copy link
Copy Markdown
Owner

Checked the two unresolved review threads from @copilot-pull-request-reviewer and cubic — they are both right, and I want to add the verification plus one sequencing note that matters for landing this.

The poisoned-mutex drop is real, and it defeats the PR's own stated purpose

At the current head, warn_cache_failure_once gates the warning on:

if warned.lock().is_ok_and(|mut warned| warned.insert(context)) {

If WARNED_CONTEXTS is poisoned by an unrelated panic, lock() returns Err, is_ok_and short-circuits to false, and the warning is dropped silently. That is the exact failure mode the comment three lines above promises is impossible: "Surface persistence failures directly once per process so a permanently cold cache can never fail silently again."

The fix the reviewers suggest is already the established idiom in the module this PR routes through — tui_signal.rs recovers from poisoning at all three of its lock sites:

24:        .unwrap_or_else(|poisoned| poisoned.into_inner());
47:        .unwrap_or_else(|poisoned| poisoned.into_inner());
66:        .unwrap_or_else(|poisoned| poisoned.into_inner());

So message_cache.rs is the odd one out against the very file it defers to. Matching that idiom keeps the once-only semantics while making the warning survive an unrelated panic.

Sequencing: do not rebase yet

This branch's base predates #1068, so its Windows leg is still advisory. That is why its last run reported success at the top level while Tests (windows-latest) (job 93170461116) actually failed — visible only per-job.

The failure is not caused by anything in this PR. All three headless_capture_* tests failed on wall-clock assertions while the behaviour under test was correct:

fast failure waited too long: 11.0576809s
fast success waited too long: 11.16815s
slow command timeout duration was unexpected: 21.173129s

That is a pre-existing timing flake, now tracked as #1078. The consequence for this PR is concrete: the moment you rebase onto a base containing #1068, that flake becomes a hard red gate on your branch, through no fault of your change. A fix for #1078 is in progress, so it is worth rebasing after it lands rather than before — otherwise a red Windows leg here will look like your bug.

So: the poison-recovery fix is the one substantive item, and the rebase is worth holding briefly.

…face

warn_cache_failure_once gated the once-per-process fallback on
`lock().is_ok_and(...)`, so a poisoned WARNED_CONTEXTS mutex silently
dropped the diagnostic instead of emitting it. That is the exact silent
failure the fallback exists to prevent.

Recover from poisoning with `unwrap_or_else(|poisoned| poisoned.into_inner())`,
matching how tui_signal already handles all of its lock sites, and hoist
the static so the poisoned path is testable. Once-per-context semantics
and the TUI deferral are unchanged.
@junhoyeo

junhoyeo commented Aug 9, 2026

Copy link
Copy Markdown
Owner

Pushed df1b6de to this branch, fixing the poisoned-mutex hole that @copilot-pull-request-reviewer and cubic both flagged independently on this PR. They were right, and it was the one thing in here that undercut the fix's own premise.

What was wrong

warn_cache_failure_once gated the once-per-process fallback on:

if warned.lock().is_ok_and(|mut warned| warned.insert(context)) {

If WARNED_CONTEXTS is poisoned by an unrelated panic elsewhere in the process, lock() returns Err, is_ok_and short-circuits to false, and the warning is dropped with no diagnostic at all — not deferred, just gone. That is exactly the failure mode the comment three lines above promises is impossible: "Surface persistence failures directly once per process so a permanently cold cache can never fail silently again."

tui_signal.rs, the module this PR routes the fallback through, already recovers from poisoning at all three of its lock sites with .unwrap_or_else(|poisoned| poisoned.into_inner()). So message_cache.rs was the outlier against the very file it defers to.

The fix

Same idiom as tui_signal.rs:

if warned_contexts()
    .lock()
    .unwrap_or_else(|poisoned| poisoned.into_inner())
    .insert(context)
{

The set only records which contexts were already reported, so its contents stay meaningful across an unwind — recovering is correct here, not just convenient. Once-per-context semantics and the TUI deferral behavior are unchanged; the fallback still defers rather than writing raw stdio mid-render, which is the whole point of #941 and this PR.

The static moved from function-local to module-level behind a warned_contexts() helper. That is the minimum restructuring needed to make the poisoned path observable from a test.

Red-green proof

New test cache_warning_survives_a_poisoned_once_only_set poisons the set by panicking inside catch_unwind while holding the lock, asserts is_poisoned() so the test cannot silently degrade into a no-op, then calls warn_cache_failure_once twice with the TUI active and asserts exactly one complete warning was deferred.

Against the previous is_ok_and implementation:

test message_cache::tests::cache_warning_survives_a_poisoned_once_only_set ... FAILED

assertion `left == right` failed: a poisoned once-only set must still defer exactly one warning
  left: []
 right: ["tokscale: warning: test source cache warning after poisoning (cache-warning-poison-test): simulated cache failure"]

After the fix:

test message_cache::tests::cache_warning_is_deferred_once_while_the_tui_is_active ... ok
test message_cache::tests::cache_warning_survives_a_poisoned_once_only_set ... ok

test result: ok. 2 passed; 0 failed

Gates

  • cargo fmt --all -- --check — clean
  • cargo clippy -p tokscale-core --all-targets — clean
  • cargo test -p tokscale-core1492 passed; 0 failed; 1 ignored (lib), all integration suites green

Not rebased on main deliberately: this branch's base predates #1068, and rebasing would pull in the pre-existing timing flake tracked in #1078 (fix in #1081) as a hard red gate unrelated to this change.

@cubic-dev-ai cubic-dev-ai Bot left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

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

All reported issues were addressed across 1 file (changes from recent commits).

Reply with feedback, questions, or to request a fix.

Re-trigger cubic

Comment thread crates/tokscale-core/src/message_cache.rs Outdated
Comment thread crates/tokscale-core/src/message_cache.rs Outdated
…poisoned set

The poisoned-set regression test reached for process-global state in two ways that can disturb tests running beside it.

It swapped the process-global panic hook for a no-op to keep its deliberate panic out of the test output. That suppresses panic diagnostics for whatever else runs in parallel, and races with any other hook user. The unwind happens on the test's own thread, which libtest already captures, so the hook swap is dropped entirely and the expected message now prints only when the test fails.

It also set TUI_ACTIVE and restored it by hand just before its final assertion, so a panic anywhere in between leaked the mutation into every later test in the binary. Add TuiActiveGuard next to the state it guards, mirroring paths::test_env::EnvGuard: it restores the previous value on Drop, drains what the test deferred rather than printing it on the real stderr, and carries its own proof that it restores while unwinding. Both message_cache tests and the tui_signal test now use it.

Finally, the test poisoned the process-global once-only set, which is irreversible and left every later test depending on the recovery under test. warn_cache_failure_once now delegates to warn_cache_failure_once_in, which takes the set as a parameter, so the test can poison one scoped to itself. Production has a single caller that always passes warned_contexts(), and the deferral test still exercises the real global set, so the once-per-process, once-per-context semantics are unchanged.
@junhoyeo

junhoyeo commented Aug 9, 2026

Copy link
Copy Markdown
Owner

Both of these were findings against the regression test we added in df1b6de (cache_warning_survives_a_poisoned_once_only_set), not against your work in this PR. Cleaning them up here in 56dc13d rather than merging over them. The production fix and the once-per-context semantics are unchanged.

The test replaced the process-global panic hook

It swapped std::panic::set_hook for a no-op just to keep its deliberate panic out of the test output. The hook is process-global, so under a parallel run that suppresses panic diagnostics for whatever else happens to be running, and it races with any other hook user.

Resolved by not touching the hook at all. The unwind happens on the test's own thread, which libtest already captures, so the expected panic message is simply captured and printed only if the test fails — confirmed: the message appears under --nocapture and is silent without it.

Non-panic-safe restore of the process-global TUI state

The old let previous = is_tui_active(); ... set_tui_active(previous); pair restored just before the final assert_eq!, so a panic anywhere in between leaked TUI-active into every later test in the binary.

Resolved with TuiActiveGuard, added in tui_signal.rs next to the state it guards and following the existing paths::test_env::EnvGuard convention (same capture() / set(&mut self, ..) shape and the same rationale). Drop restores the previous value, so unwinding restores it too, and it also drains whatever the test deferred — restoring through set_tui_active would otherwise eprintln! the test's synthetic diagnostics onto the real stderr, and leaving them queued would surface in the next test's take_deferred_stderr_for_test.

The guard carries its own proof (tui_active_guard_restores_even_when_the_probe_panics), mirroring the existing env_guard_restores_even_when_the_test_body_panics. Verified it is meaningful: stubbing Drop to a no-op makes it fail with TuiActiveGuard must restore the previous value while unwinding.

I also moved the adjacent cache_warning_is_deferred_once_while_the_tui_is_active (from 8c5895b) onto the same guard. It had the identical hand-rolled restore, and leaving one copy of the pattern next to the fixed one would just invite the same comment again.

Permanent poisoning of the process-global once-only set

We flagged this ourselves: the test poisoned the real WARNED_CONTEXTS for the rest of the test binary. Mutex poisoning is irreversible, so every later test in the process was silently depending on the very recovery this test exists to check.

Scoped it. warn_cache_failure_once now delegates to warn_cache_failure_once_in, which takes the set as a parameter, so the test poisons a Mutex<HashSet<..>> local to itself. Production has exactly one caller and it always passes warned_contexts(), so once-per-process/once-per-context behaviour is untouched, and cache_warning_is_deferred_once_while_the_tui_is_active deliberately still goes through the real global set so the production entry point stays covered.

Red-green re-verified

The test still genuinely proves the poisoned-mutex behaviour. Reverting the production line to warned.lock().is_ok_and(..):

test message_cache::tests::cache_warning_survives_a_poisoned_once_only_set ... FAILED

assertion `left == right` failed: a poisoned once-only set must still defer exactly one warning
  left: []
 right: ["tokscale: warning: test source cache warning after poisoning (cache-warning-poison-test): simulated cache failure"]

test result: FAILED. 2 passed; 1 failed; 0 ignored; 0 measured; 1490 filtered out

With the fix restored:

test message_cache::tests::cache_warning_is_deferred_once_while_the_tui_is_active ... ok
test message_cache::tests::cache_warning_survives_a_poisoned_once_only_set ... ok
test tui_signal::tests::defers_stderr_until_the_tui_is_inactive ... ok
test tui_signal::tests::tui_active_guard_restores_even_when_the_probe_panics ... ok

test result: ok. 4 passed; 0 failed; 0 ignored; 0 measured; 1490 filtered out

Gates

cargo fmt --all -- --check clean, cargo clippy -p tokscale-core --all-targets clean, and cargo test -p tokscale-core green in the default parallel mode (no --test-threads=1), so cross-test interference would show:

test result: ok. 1493 passed; 0 failed; 1 ignored; 0 measured; 0 filtered out
test result: ok. 10 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out
test result: ok. 4 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out
test result: ok. 14 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out
test result: ok. 3 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out
test result: ok. 4 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out

The lib suite was also repeated 5x in parallel with no flakes.

@cubic-dev-ai cubic-dev-ai Bot left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

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

All reported issues were addressed across 2 files (changes from recent commits).

Tip: Review your code locally with the cubic CLI to iterate faster.

Re-trigger cubic

Comment thread crates/tokscale-core/src/tui_signal.rs Outdated
…g queued diagnostics

TuiActiveGuard::drop transitioned to inactive before restoring self.previous. The inactive transition drains and permanently discards the process-global deferred-stderr queue, so a guard whose captured previous value was active tore the state down, threw away diagnostics an enclosing scope still owed its eventual terminal restore, and only then set the flag back to active.

Restore in a single transition instead. transition_tui_active already ties the queue to the state it moves to: restoring to inactive still drains, which is what keeps a test's synthetic diagnostics off the real stderr, and restoring to active now leaves the queue for whoever owns the terminal. Drop stays panic-safe, so an unwind still restores.

Covered by a nested-capture test asserting the deferred message survives the inner guard's drop.
@junhoyeo

junhoyeo commented Aug 9, 2026

Copy link
Copy Markdown
Owner

Follow-up on a finding against code we added in this branch (the test-only TuiActiveGuard), not against the original contribution.

TuiActiveGuard::drop did two transitions: transition_tui_active(false) and then transition_tui_active(self.previous). The first one drains and permanently discards the process-global deferred-stderr queue. That matches the "restore the previous value" contract only when previous == false — the case that happens to be reachable today, since is_tui_active() starts out false. With an active previous value (a nested capture, or state left active by something earlier) the guard tore the state down to inactive, threw away diagnostics the enclosing scope still owed its eventual terminal restore, and only then set the flag back to active. Those messages were gone, silently.

The second-order risk was the one worth fixing for: a test that defers a message and then panics before asserting it has its diagnostics swallowed by the drop — which would mask exactly the deferral regression this PR exists to prevent.

Resolved by restoring in a single transition. transition_tui_active already ties the queue to the state it moves to, so transition_tui_active(self.previous) gives the right behaviour in both directions: restoring to inactive still drains (that is what keeps a test's synthetic diagnostics off the real stderr and out of the next test's take_deferred_stderr_for_test), and restoring to active now leaves the queue alone for whoever actually owns the terminal. Drop is unchanged in its panic-safety, so an unwind still restores.

Red-green, all three guarantees re-checked:

Change under test Test Result
Drop reverted to the unconditional drain tui_active_guard_restoring_an_active_scope_keeps_the_deferred_queue RED — left: [], right: ["deferred inside a nested capture"]
Fix in place same test GREEN
warned.lock().is_ok_and(...) restored cache_warning_survives_a_poisoned_once_only_set RED — left: []
Poison recovery restored same test GREEN
fn drop(&mut self) {} tui_active_guard_restores_even_when_the_probe_panics RED — "must restore the previous value while unwinding"

The new test nests its guards so the outermost one still restores to inactive and drains, and its own assertion consumes the queue, so no TUI-active state or queued diagnostic leaks into a later test.

Gates, in default parallel mode (no --test-threads=1):

cargo fmt --all -- --check      clean
cargo clippy -p tokscale-core --all-targets    clean, no warnings
cargo test -p tokscale-core     1494 passed; 0 failed; 1 ignored (lib)
                                + 4, 4, 3, 14, 10 passed across the integration suites; 0 failed anywhere

The lib suite was run 5 more times in parallel mode to check for flakes: 1494 passed; 0 failed every time.

@junhoyeo
junhoyeo merged commit 965c59e into junhoyeo:main Aug 9, 2026
20 checks passed
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.

3 participants