fix(desktop): scrape the remote >> log 2>&1 READY sentinel with the merged-buffer regex
The splice hazard the tail seed guards against is live in remote-lifecycle's scrapeReadyPort: the remote spawn log merges stdout and stderr, yet it was matched with the `^`-anchored READY_RE. Export one READY_IN_MERGED_OUTPUT_RE (lookbehind token boundary — the hand-rolled `[^0-9A-Z_]` class admitted lowercase-glued tokens) from backend-ready.ts and use it for both merged buffers. Comments trimmed to the WHY; 6 new tests collapsed to the two invariants (splice recovers, prose does not match) plus one remote-log case.
This commit is contained in:
@@ -320,90 +320,22 @@ test('bufferedOutput without a sentinel still times out (no false positive)', as
|
||||
await assert.rejects(wait, /Timed out waiting/)
|
||||
})
|
||||
|
||||
// ---------------------------------------------------------------------------
|
||||
// merged-tail seed (#103792): the spawn-time tail holds stdout AND stderr in
|
||||
// ONE buffer, so it is not line-accurate. uvicorn logs to stderr in raw
|
||||
// chunks, and a chunk that ends without a newline is concatenated straight
|
||||
// onto the stdout sentinel that follows it. A `^`-anchored scan then recovers
|
||||
// nothing from a backend that announced perfectly, the wait hits its 90s
|
||||
// deadline, and a healthy listening backend is killed — while desktop.log
|
||||
// (which reads both streams) plainly shows the READY line.
|
||||
// ---------------------------------------------------------------------------
|
||||
|
||||
test('resolves when a partial stderr line is spliced onto the sentinel in the merged tail (#103792)', async () => {
|
||||
test('the merged-tail seed recovers a sentinel spliced onto a partial stderr line (#103792)', async () => {
|
||||
const child = makeFakeChild()
|
||||
|
||||
// No trailing newline on the stderr chunk, exactly as uvicorn emits it.
|
||||
const mergedTail = 'INFO Started server process [4711]HERMES_BACKEND_READY port=65238\n'
|
||||
|
||||
// uvicorn's stderr chunk has no trailing newline, so the tail is not line-accurate.
|
||||
const port = await waitForDashboardPortAnnouncement(child, {
|
||||
bufferedOutput: () => mergedTail,
|
||||
bufferedOutput: () => 'INFO Started server process [4711]HERMES_BACKEND_READY port=65238',
|
||||
timeoutMs: 500
|
||||
})
|
||||
|
||||
assert.equal(port, 65238)
|
||||
})
|
||||
|
||||
test('splice recovery also covers the legacy HERMES_DASHBOARD_READY sentinel', async () => {
|
||||
test('the merged-tail seed does not match prose that merely names the sentinel', async () => {
|
||||
const child = makeFakeChild()
|
||||
|
||||
const port = await waitForDashboardPortAnnouncement(child, {
|
||||
bufferedOutput: () => 'INFO Application startup complete.HERMES_DASHBOARD_READY port=65239\n',
|
||||
timeoutMs: 500
|
||||
})
|
||||
|
||||
assert.equal(port, 65239)
|
||||
})
|
||||
|
||||
test('a spliced sentinel with no trailing newline is still recovered from the tail', async () => {
|
||||
const child = makeFakeChild()
|
||||
|
||||
// The tail is a snapshot: the sentinel's own newline may not have been
|
||||
// flushed into it yet. Line-splitting would drop it; the tail scan must not.
|
||||
const port = await waitForDashboardPortAnnouncement(child, {
|
||||
bufferedOutput: () => 'waiting for application startupHERMES_BACKEND_READY port=65240',
|
||||
timeoutMs: 500
|
||||
})
|
||||
|
||||
assert.equal(port, 65240)
|
||||
})
|
||||
|
||||
test('the merged-tail scan does not match prose that merely names the sentinel', async () => {
|
||||
const child = makeFakeChild()
|
||||
|
||||
// `port=<digits>` is what makes the token unambiguous. Without it, a log
|
||||
// line discussing the sentinel must never be mistaken for an announcement.
|
||||
const wait = waitForDashboardPort(
|
||||
child,
|
||||
50,
|
||||
() => '',
|
||||
() => 'still waiting for HERMES_BACKEND_READY from the backend\n'
|
||||
)
|
||||
|
||||
await assert.rejects(wait, /Timed out waiting/)
|
||||
})
|
||||
|
||||
test('the merged-tail scan does not match a longer token ending in the sentinel', async () => {
|
||||
const child = makeFakeChild()
|
||||
|
||||
const wait = waitForDashboardPort(
|
||||
child,
|
||||
50,
|
||||
() => '',
|
||||
() => 'X_HERMES_BACKEND_READY port=1234\n'
|
||||
)
|
||||
|
||||
await assert.rejects(wait, /Timed out waiting/)
|
||||
})
|
||||
|
||||
test('the LIVE per-line scanner stays line-anchored (splice tolerance is tail-only)', async () => {
|
||||
const child = makeFakeChild()
|
||||
|
||||
const wait = waitForDashboardPort(child, 60)
|
||||
// Live stdout chunks ARE line-accurate for this stream, so a sentinel that
|
||||
// is a suffix of some other line is not an announcement. Loosening this
|
||||
// would let unrelated child output settle the boot on a bogus port.
|
||||
child.stdout.emit('data', 'downloading HERMES_BACKEND_READY port=1234\n')
|
||||
const wait = waitForDashboardPort(child, 50, () => '', () => 'still waiting for HERMES_BACKEND_READY from the backend\n')
|
||||
|
||||
await assert.rejects(wait, /Timed out waiting/)
|
||||
})
|
||||
|
||||
@@ -5,19 +5,11 @@ import fs from 'node:fs'
|
||||
// works against both the headless backend and old/dashboard runtimes.
|
||||
const _READY_RE = /^HERMES_(?:BACKEND|DASHBOARD)_READY port=(\d+)/m
|
||||
|
||||
// Same sentinel, matched inside the spawn-time output tail rather than inside
|
||||
// a single line. The tail merges stdout AND stderr into one buffer, so it is
|
||||
// NOT line-accurate: uvicorn's stderr startup logging is appended in raw
|
||||
// chunks, and a chunk that ends without a newline is concatenated directly
|
||||
// onto the stdout sentinel that follows it, producing
|
||||
// `INFO Started server process [4711]HERMES_BACKEND_READY port=65238`.
|
||||
// A `^`-anchored match then fails on a backend that announced perfectly: the
|
||||
// seed below silently recovers nothing, the wait hits its 90s deadline, and a
|
||||
// healthy, listening backend is killed while desktop.log plainly shows the
|
||||
// READY line (#103792). Guard on a token boundary instead of a line start.
|
||||
// `port=<digits>` keeps the token unambiguous, so prose that merely mentions
|
||||
// the sentinel cannot match.
|
||||
const _READY_IN_MERGED_TAIL_RE = /(?:^|[^0-9A-Z_])HERMES_(?:BACKEND|DASHBOARD)_READY port=(\d+)/
|
||||
// Same sentinel inside a MERGED stdout+stderr buffer (the spawn-time output tail, a remote
|
||||
// `>> log 2>&1` file): uvicorn's stderr chunks end without a newline, so the sentinel can be
|
||||
// spliced onto them (`...process [4711]HERMES_BACKEND_READY port=65238`) and `^` never lines up
|
||||
// (#103792). Match on a token boundary instead; `port=<digits>` keeps prose mentions out.
|
||||
export const READY_IN_MERGED_OUTPUT_RE = /(?<!\w)HERMES_(?:BACKEND|DASHBOARD)_READY port=(\d+)/
|
||||
|
||||
// The announcement clock starts the instant the backend process is spawned —
|
||||
// before uvicorn binds its socket. On a cold install the child must first
|
||||
@@ -135,24 +127,12 @@ function waitForDashboardPort(
|
||||
// Listener is live — now recover a sentinel that was already flushed and
|
||||
// consumed before this promise existed. The snapshot is taken AFTER the
|
||||
// listener attaches, so no chunk can fall between snapshot and listener.
|
||||
// Scanned with the merged-tail regex, not the line-anchored one: the tail
|
||||
// interleaves both streams and can splice a partial line onto the sentinel.
|
||||
//
|
||||
// REACHABILITY — do not mistake this for a hot path. Both callers in
|
||||
// main.ts (spawnPoolBackend, startHermes) build this wait in the SAME
|
||||
// synchronous block as `outputTail.attach(child)`, with no `await`
|
||||
// between them, and stream 'data' is delivered asynchronously. So under
|
||||
// the current ordering `bufferedOutput()` is always empty here and this
|
||||
// block recovers nothing — it is a dormant safety net, not a live fix.
|
||||
//
|
||||
// It stops being dormant the moment ANY await is reintroduced between
|
||||
// attach and this call. That was the real ordering before #100442, and it
|
||||
// is one refactor away from returning: the surrounding region is claim /
|
||||
// boot-progress / token-handoff code that repeatedly grows awaits. Keep
|
||||
// the net correct while it is cheap, and keep the tests that pin it.
|
||||
// Merged-buffer regex here (the tail interleaves both streams). Currently dormant: both
|
||||
// main.ts callers attach the tail and build this wait in one synchronous block, so the
|
||||
// snapshot is empty; any await reintroduced between them makes this the live path again.
|
||||
if (!done) {
|
||||
const alreadyBuffered = bufferedOutput()
|
||||
const m = alreadyBuffered ? alreadyBuffered.match(_READY_IN_MERGED_TAIL_RE) : null
|
||||
const m = alreadyBuffered ? alreadyBuffered.match(READY_IN_MERGED_OUTPUT_RE) : null
|
||||
|
||||
if (m) {
|
||||
cleanup()
|
||||
|
||||
@@ -913,6 +913,8 @@ test('spawnRemoteDashboard always spawns serve (legacy dashboard path removed)',
|
||||
test('READY_RE accepts both serve and dashboard sentinels', () => {
|
||||
assert.equal(READY_RE.exec('HERMES_BACKEND_READY port=4321')?.[1], '4321')
|
||||
assert.equal(READY_RE.exec('HERMES_DASHBOARD_READY port=8765')?.[1], '8765')
|
||||
// The remote log is `>> log 2>&1`, so a stderr chunk without a newline can be spliced onto the sentinel.
|
||||
assert.equal(READY_RE.exec('INFO Started server process [4711]HERMES_BACKEND_READY port=65238')?.[1], '65238')
|
||||
})
|
||||
|
||||
test('spawnRemoteDashboard rejects when no pid is returned', async () => {
|
||||
|
||||
@@ -27,6 +27,7 @@
|
||||
|
||||
import crypto from 'node:crypto'
|
||||
|
||||
import { READY_IN_MERGED_OUTPUT_RE } from './backend-ready'
|
||||
import { parseRemoteProfileListing } from './connection-registry'
|
||||
import { assertBootstrapNotSuperseded } from './ssh-connection'
|
||||
|
||||
@@ -35,7 +36,7 @@ const LOCKFILE_SCHEMA_VERSION = 2
|
||||
// an old running dashboard unsafe to reattach to (token handling, readiness/spawn
|
||||
// args, served-token reconciliation). A mismatch forces a clean respawn.
|
||||
const PROTOCOL_VERSION = 1
|
||||
const READY_RE = /^HERMES_(?:BACKEND|DASHBOARD)_READY port=(\d+)/m
|
||||
const READY_RE = READY_IN_MERGED_OUTPUT_RE // the remote log is `>> log 2>&1`: merged, not line-accurate
|
||||
const REMOTE_LOCK_DIR = '~/.hermes/desktop-ssh'
|
||||
const SUPPORTED_REMOTE_OS = new Set(['Linux', 'Darwin'])
|
||||
const DEFAULT_READY_TIMEOUT_MS = 45_000
|
||||
|
||||
Reference in New Issue
Block a user