Skip to content

Tests: live tests wait for NMSh's journal, not screen text (CI races seen on #441 and #442) - #442

Merged
raiseCatError merged 3 commits into
devfrom
fix/v022-queue-live-sync
Oct 21, 2026
Merged

raiseCatError merged 3 commits into
devfrom
fix/v022-queue-live-sync

Conversation

@raiseCatError

@raiseCatError raiseCatError commented Oct 18, 2026 •

Copy link
Copy Markdown
Owner

Draft, do not merge before v0.21 ships. Test-only. Part of v0.22 (#431). Found while investigating #441's CI run 39173560112; independent of every other v0.22 PR.

The failure

Ubuntu, tests/commandQueueLive.test.ts, a program waiting for a line gets Enter; Ctrl+Q queues; Ctrl+S sends to a program NMSh cannot see waiting: timed out waiting for /Running cat/, with the screen showing ◆ Waiting for input · cat.

Cause (reproduced on dev a8b383c2 and on #441's head)

The test queues echo QUEUED-AFTER-READ with Ctrl+Q while read waits, answers alice, waits for /got=alice[\s\S]*QUEUED-AFTER-READ/, then types cat.

That wait can match the queue list's row echo QUEUED-AFTER-READ, drawn under got=alice, before the command's output and before its prompt returns. Measured frame by frame on the unchanged test sequence (first read in a fresh session):

regex matches output drawn prompt returned (from queue completion)
dev a8b383c2 53 ms 71 ms 83 ms
#441 48f70e96, busier machine 701 ms 746 ms 901 ms

So cat can be typed while the queued command is still finishing.

  • What NMSh does then: it queues cat by design (Enter while a command runs queues), and runs it from the queue. While the queue timeline shows, the activity row is the queue summary (Queue activity · … · 1 running), not Running cat.
  • On Linux: the kernel's report then makes it ◆ Waiting for input · cat, exactly the CI screen.
  • Reproduction: with the queued command's prompt deliberately delayed by 1 s after its output, the unchanged test fails every time on both dev and Composer history: History n/N on a free composer rule while browsing (#389) #441, showing cat in the queue timeline.

Neither #438 nor #441 touches this path (the test never presses Up).

A second race of the same class (macOS CI on this PR, run 39178446961)

tests/typingAfterRead.test.ts, live zsh: keys typed the moment a read finishes are never lost, nor keys typed ahead during it, failed with the answer reached read, expected got=vahead2.

  • In "ahead" rounds the test answers the read, types echo NEXT-<tag> at once (it is queued), and waits for NEXT-<tag>[\s\S]*Completed. That can match the queue row › echo NEXT-<tag> followed by an older Completed in a later redraw. The CI screen shows the read still running (1 running · 1 waiting) when the assertion ran.
  • Measured on unchanged dev, 6 rounds: the regex matched at 112–443 ms, and NMSh's journal recorded echo NEXT-<tag> completed at 534–1017 ms, every time. On this Mac the answer happened to be drawn first; on the CI runner it was not.
  • Reproduced on dev: with the read's output 1 s late, the unchanged test fails with the CI message (expected /got=vahead1/).

Fix (test only, both races)

  • tests/helpers/liveFrontend.ts: Frontend.completions(command) exposes the journal count run() already used. The frontend writes that record when the shell's prompt returns, so waiting for it to grow is a deterministic end of a command, independent of screen text.
  • commandQueueLive: the queued command is printf "QUEUED-%s\n" AFTER-READ, so its output cannot match its command text. After its output, the test waits for its journal record before typing cat at an idle prompt.
  • typingAfterRead: the test waits for the journal record of echo NEXT-<tag>, then asserts the answer reached the read. It now also asserts that the next command's output (not its text) appeared, which is stricter than before.

No sleep, no longer timeout, no retry; no assertion is weakened.

Verification

Check Old wait (dev) Journal wait (this PR)
commandQueueLive, queued command's prompt 1 s after its output fails (dev and #441) 3/3
typingAfterRead zsh, read output 1 s late fails with the CI message passes
tests/commandQueueLive.test.ts 19/19
tests/typingAfterRead.test.ts (zsh, Bash, Fish) 3/3

Not caused by this PR, not fixed here

Ubuntu, same CI run: live fish: absolute executable paths… timed out waiting for ADB[devices].

Residual (not changed here)

On Linux, Running cat is drawn only before the first input look (400 ms after the command starts), after which the kernel's report shows Waiting for input · cat. A frontend that draws nothing for 400 ms after cat starts would miss it. That has not been observed, and this CI failure is fully explained by the queue race above.

Refs #431

The wait matched the queued command's text in the queue list before
its output or prompt, so cat could be typed while that command was
still finishing. NMSh then queues cat by design and never draws
Running cat (the CI failure on #441). The output now differs from the
command text, and the test waits for the queued command's completion
row, which is drawn only once the shell's prompt has returned.
…ommand ran

typingAfterRead waited for NEXT-<tag> followed by Completed: the queued
command's row and an older redrawn Completed matched before the read
printed its answer (macOS CI on #442; reproduced on dev with a read
whose output comes 1 s late). The live Frontend now exposes the journal
count run() already uses; typingAfterRead and commandQueueLive wait for
the command's completed record, which the frontend writes once the
shell's prompt returns.
@raiseCatError raiseCatError changed the title Tests: type cat only after the queued command's prompt returns (CI race seen on #441) Tests: live tests wait for NMSh's journal, not screen text (CI races seen on #441 and #442) Oct 19, 2026
raiseCatError added a commit that referenced this pull request Oct 19, 2026
…source findings

The candidate (all nine PRs in dependency order) is green in CI on
567cf53 after two #437 follow-ups it surfaced. Records #442 and #443,
the stacked #437, the conflict rule, the scratch combined /view editor
test, what was recovered after the 2026-10-19 kernel panic, and the
findings for the planned test-resource pass.
…un once

With #437's #426 review change, a command typed ahead during a hidden
read's answer can be held at the prompt when a look still saw hidden
input as the command ended (it may be a reply to a second question with
no prompt). It is then never run by itself; the person's Tab shows it
and Enter runs it. The test accepts that outcome only for typing ahead
during a hidden read, presses Tab and Enter, and still requires the
next command to run exactly once (journal count). Without #437 the
held branch is never taken.
@raiseCatError

Copy link
Copy Markdown
Owner Author

Release follow-up, 292583ae (test only): typingAfterRead accepts one more correct outcome, from #437's #426 review. A command typed ahead during a hidden read's answer may be held at the prompt when a look still saw hidden input as the command ended. The test then presses Tab and Enter. It accepts the held outcome only for typing ahead during a hidden read, and still requires the next command to run exactly once (journal count). Without #437, the held branch is never taken. Merged into release/v0.22.0 (#444); there, this version replaces #437's copy of the test.

@raiseCatError
raiseCatError merged commit 3fa2ac6 into dev Oct 21, 2026
12 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.

1 participant