fix(desktop): update gate stops waiting on a held checkout at the scripts' 7200 s ceiling
A dead marker whose checkout lock a leftover process still holds (`held` / `busy` from the script helper) parked the Desktop with no deadline (review R6 m7): a lock leaked into a long-lived process held start-up hostage while the scripts themselves give up after RELEASE_WAIT_S = 7200 s. The gate's marker probe now counts a held wait from the marker's line 2 (the last time an owner wrote it), or from the first sighting in this process for an unreadable line 2, and stops blocking after HELD_CEILING_MS = 7200 s: it logs it once, reports it through onHeld, and leaves the marker untouched (A7: the Desktop never mutates it). While held, boot progress names the update process that exited and the time left; past the ceiling a non-blocking dialog tells the user what still holds the install and how to move on. A helper `live <pid>` keeps no ceiling (C1 rule 3). The ceiling is a test seam option, not an env var. (cherry picked from commit ac513e33ce0f5c99338d51607f894cf0dc3b4a8c)
This commit is contained in:
@@ -598,7 +598,7 @@ import {
|
||||
updateHandoffConflict,
|
||||
writeUpdateMarker
|
||||
} from './update-marker'
|
||||
import { liveMarkerProbe } from './update-marker-gate'
|
||||
import { heldCeilingNotice, type HeldState, heldWaitMessage, liveMarkerProbe } from './update-marker-gate'
|
||||
import { updateConnectionsBeforeLocal } from './update-order'
|
||||
import {
|
||||
resolveUpdaterMechanism,
|
||||
@@ -2997,7 +2997,10 @@ const UPDATE_HANDOFF_DWELL_MS = 2500
|
||||
// The hand-off state closes the later Windows `cmd start` wrapper gap: the
|
||||
// wrapper exits 0 before the real PowerShell script claims the marker, and
|
||||
// `finally` clears updateInFlight immediately after the hand-off is accepted.
|
||||
function updateGateDeps(onLiveMarker?: (marker: { startedAt: number | null }) => void) {
|
||||
function updateGateDeps(
|
||||
onLiveMarker?: (marker: { startedAt: number | null }) => void,
|
||||
onHeld?: (state: HeldState) => void
|
||||
) {
|
||||
// One creation-time probe per pid for this wait: on Windows each probe is a
|
||||
// powershell spawn and the gate polls every second.
|
||||
const createTime = cachedCreateTimeProbe()
|
||||
@@ -3013,6 +3016,7 @@ function updateGateDeps(onLiveMarker?: (marker: { startedAt: number | null }) =>
|
||||
hermesHome: HERMES_HOME,
|
||||
createTime,
|
||||
onLiveMarker,
|
||||
onHeld,
|
||||
log: rememberLog,
|
||||
reclaim: async () => {
|
||||
const updateRoot = resolveUpdateRoot()
|
||||
@@ -3091,8 +3095,20 @@ async function waitForUpdateToFinish() {
|
||||
// Marker line 2 of the run this boot parked on: the result we report is that
|
||||
// run's, never an older one (C2 started_at match).
|
||||
let parkedRunStartedAt: number | null = null
|
||||
// A dead marker whose checkout a leftover process still holds (R6): its
|
||||
// state this poll, and whether its ceiling let us through (review R6 m7).
|
||||
let held: HeldState | null = null
|
||||
let heldExpired: HeldState | null = null
|
||||
|
||||
const outcome = await waitForUpdateClearance(updateGateDeps(marker => (parkedRunStartedAt = marker.startedAt)), {
|
||||
const gateDeps = updateGateDeps(
|
||||
marker => (parkedRunStartedAt = marker.startedAt),
|
||||
state => {
|
||||
held = state
|
||||
heldExpired = state.expired ? state : heldExpired
|
||||
}
|
||||
)
|
||||
|
||||
const outcome = await waitForUpdateClearance(gateDeps, {
|
||||
signal: localBackendLifecycle.signal,
|
||||
onWaitTick: async (reason, waitedMs) => {
|
||||
if (!announced) {
|
||||
@@ -3100,6 +3116,15 @@ async function waitForUpdateToFinish() {
|
||||
rememberLog(`[updates] update in progress (${reason}); deferring backend start until it finishes`)
|
||||
}
|
||||
|
||||
const heldNow = held
|
||||
held = null
|
||||
|
||||
if (reason === 'marker' && heldNow) {
|
||||
await advanceBootProgress('backend.update-wait', heldWaitMessage(heldNow), 12)
|
||||
|
||||
return
|
||||
}
|
||||
|
||||
// A live update owner is waited out, never aged out (C1 rule 3): booting
|
||||
// a backend into a half-replaced runtime is the failure this gate exists
|
||||
// for. Past the old ceiling, say so instead of silently counting down.
|
||||
@@ -3199,6 +3224,17 @@ async function waitForUpdateToFinish() {
|
||||
localBackendLifecycle.assertCanStart()
|
||||
}
|
||||
|
||||
if (heldExpired) {
|
||||
// The way forward when the gate stopped waiting on a held checkout: boot
|
||||
// goes on (non-blocking dialog); the marker stays for the scripts/Python.
|
||||
void dialog.showMessageBox({
|
||||
type: 'warning',
|
||||
title: 'Hermes update',
|
||||
message: 'Hermes started while an earlier update still holds the install',
|
||||
detail: heldCeilingNotice(heldExpired)
|
||||
})
|
||||
}
|
||||
|
||||
if (outcome === 'clear') {
|
||||
return false
|
||||
}
|
||||
|
||||
@@ -85,7 +85,9 @@ export interface WaitForUpdateClearanceOptions {
|
||||
* Windows update is exactly the failure the gate exists for. The marker reader
|
||||
* still bounds the wait: an owner whose creation time cannot be read stops
|
||||
* reading live at the 20-minute ceiling (A1), so a reused pid never parks
|
||||
* boot forever.
|
||||
* boot forever, and a dead marker whose checkout a leftover process still
|
||||
* holds (`held`) stops reading live at the scripts' 7200 s ceiling
|
||||
* (update-marker-gate.ts, review R6 m7).
|
||||
*/
|
||||
export async function waitForUpdateClearance(
|
||||
deps: UpdateGateDeps,
|
||||
|
||||
@@ -12,7 +12,7 @@ import path from 'path'
|
||||
import { afterEach, describe, test } from 'vitest'
|
||||
|
||||
import { markerPath } from './update-marker'
|
||||
import { liveMarkerProbe } from './update-marker-gate'
|
||||
import { HELD_CEILING_MS, type HeldState, heldWaitMessage, liveMarkerProbe } from './update-marker-gate'
|
||||
import { cleanupMarkerFixtures, deadPid, liveOwner, minutesAgo, tmpHome } from './update-marker.test-helpers'
|
||||
import { runMarkerHelper } from './updater/marker-helper'
|
||||
import { cleanupFakeCheckouts, fakeHelperCheckout } from './updater/marker-helper.test-helpers'
|
||||
@@ -31,14 +31,78 @@ function helperCalls(home: string): string[] {
|
||||
}
|
||||
|
||||
describe.skipIf(process.platform === 'win32')('gate over a dead marker (R6)', () => {
|
||||
function gate(root: string, home: string, now?: () => number) {
|
||||
function gate(
|
||||
root: string,
|
||||
home: string,
|
||||
now?: () => number,
|
||||
extra: { onHeld?: (state: HeldState) => void; log?: (line: string) => void } = {}
|
||||
) {
|
||||
return liveMarkerProbe({
|
||||
hermesHome: home,
|
||||
reclaim: () => runMarkerHelper('reclaim', { updateRoot: root, hermesHome: home, isWindows: false }),
|
||||
now
|
||||
now,
|
||||
...extra
|
||||
})
|
||||
}
|
||||
|
||||
test('`held` stops blocking at the scripts\' 7200 s ceiling: told to the user, logged once, marker never touched (R6 m7)', async () => {
|
||||
const { root, home } = fakeHelperCheckout()
|
||||
const owner = await deadPid()
|
||||
const body = `${owner}\n${minutesAgo(1)}\nct:1.000\n`
|
||||
fs.writeFileSync(markerPath(home), body)
|
||||
fs.writeFileSync(path.join(home, 'helper-verdict'), 'held')
|
||||
let clock = Date.now()
|
||||
const states: HeldState[] = []
|
||||
const logs: string[] = []
|
||||
const hasLiveMarker = gate(root, home, () => clock, { onHeld: s => states.push(s), log: l => logs.push(l) })
|
||||
|
||||
assert.equal(await hasLiveMarker(), true, 'held: still parked')
|
||||
clock += HELD_CEILING_MS - 2 * 60_000
|
||||
assert.equal(await hasLiveMarker(), true, 'still inside the ceiling (counted from line 2, a minute ago)')
|
||||
|
||||
clock += 2 * 60_000
|
||||
assert.equal(await hasLiveMarker(), false, 'past the ceiling the gate stops blocking')
|
||||
assert.equal(await hasLiveMarker(), false)
|
||||
assert.equal(fs.readFileSync(markerPath(home), 'utf8'), body, 'Desktop never mutates the marker (A7)')
|
||||
|
||||
const [first] = states
|
||||
assert.deepEqual([first.verdict, first.ownerPid, first.expired], ['held', owner, false])
|
||||
assert.ok(first.remainingMs! > HELD_CEILING_MS - 2 * 60_000, 'counted from line 2, not from boot')
|
||||
assert.match(heldWaitMessage(first), new RegExp(`update \\(process ${owner}\\) exited.*still holds`))
|
||||
assert.equal(states.at(-1)!.expired, true)
|
||||
assert.equal(logs.filter(l => l.includes('no longer blocking')).length, 1, 'logged once')
|
||||
|
||||
assert.equal(await gate(root, home, () => clock)(), false, 'a later gate wait does not restart the ceiling')
|
||||
})
|
||||
|
||||
test('a malformed held marker counts its ceiling from the first sighting, across gate waits', async () => {
|
||||
const { root, home } = fakeHelperCheckout()
|
||||
fs.writeFileSync(markerPath(home), `garbage-${process.pid}-${Date.now()}\n`)
|
||||
fs.writeFileSync(path.join(home, 'helper-verdict'), 'busy')
|
||||
let clock = Date.now()
|
||||
|
||||
assert.equal(await gate(root, home, () => clock)(), true)
|
||||
clock += HELD_CEILING_MS - 1_000
|
||||
assert.equal(await gate(root, home, () => clock)(), true, 'a new wait continues the same count')
|
||||
clock += 1_000
|
||||
assert.equal(await gate(root, home, () => clock)(), false)
|
||||
})
|
||||
|
||||
test('a helper `live <pid>` names a live identity: no ceiling', async () => {
|
||||
const { root, home } = fakeHelperCheckout()
|
||||
fs.writeFileSync(markerPath(home), `${await deadPid()}\n${minutesAgo(1)}\nct:1.000\n`)
|
||||
fs.writeFileSync(path.join(home, 'helper-verdict'), 'live 4242')
|
||||
let clock = Date.now()
|
||||
const states: HeldState[] = []
|
||||
const hasLiveMarker = gate(root, home, () => clock, { onHeld: s => states.push(s) })
|
||||
|
||||
assert.equal(await hasLiveMarker(), true)
|
||||
clock += 10 * HELD_CEILING_MS
|
||||
assert.equal(await hasLiveMarker(), true)
|
||||
assert.equal(states.at(-1)!.remainingMs, null)
|
||||
assert.equal(states.at(-1)!.livePid, 4242)
|
||||
})
|
||||
|
||||
test('`held` keeps the gate closed and is re-asked every 5 s; the marker is never touched', async () => {
|
||||
const { root, home } = fakeHelperCheckout()
|
||||
const body = `${await deadPid()}\n${minutesAgo(1)}\nct:1.000\n`
|
||||
|
||||
@@ -16,6 +16,17 @@
|
||||
* The helper is asked once per distinct dead marker body per wait; a `held` /
|
||||
* `busy` / `live` answer is re-asked every `reprobeMs` (5 s) because only the
|
||||
* script can see the lock being released.
|
||||
*
|
||||
* `held` / `busy` have a ceiling (review R6 m7): no owner identity is alive,
|
||||
* only some process still holding the checkout lock, and that can be a
|
||||
* leaked long-lived one. The scripts stop waiting on it after RELEASE_WAIT_S
|
||||
* (7200 s); the gate stops blocking after the same span, counted from the
|
||||
* marker's line 2 (the last time an owner wrote it; the scripts keep it young
|
||||
* while they live) or, when line 2 is unreadable, from the first time this
|
||||
* process saw the body held. Past the ceiling the probe answers "not
|
||||
* running", logs it once and reports it through `onHeld` so the caller can
|
||||
* tell the user; the marker is left exactly as it is. A helper `live <pid>`
|
||||
* names a live identity and is waited out like any live marker (C1 rule 3).
|
||||
*/
|
||||
|
||||
import { type CreateTimeProbe, inspectUpdateMarker } from './update-marker'
|
||||
@@ -23,30 +34,72 @@ import type { MarkerHelperVerdict } from './updater/marker-helper'
|
||||
|
||||
export const HELD_REPROBE_MS = 5_000
|
||||
|
||||
/** The scripts' own wait on the checkout lock (posix.sh RELEASE_WAIT_S, marker.ps1 MarkerReleaseWaitSeconds). */
|
||||
export const HELD_CEILING_MS = 7_200_000
|
||||
|
||||
/** Why a dead marker still keeps the gate closed, as the script helper put it. */
|
||||
export interface HeldState {
|
||||
verdict: 'held' | 'busy' | 'live'
|
||||
/** Line 1 of the marker: the update process that started it (exited), when it parses. */
|
||||
ownerPid: number | null
|
||||
/** The live process the helper named (`live <pid>`), else null. */
|
||||
livePid: number | null
|
||||
/** Epoch ms the ceiling counts from. */
|
||||
since: number
|
||||
/** Ms until the gate stops blocking; null when there is no ceiling (`live`). */
|
||||
remainingMs: number | null
|
||||
/** The ceiling passed: the gate is open and the marker untouched. */
|
||||
expired: boolean
|
||||
}
|
||||
|
||||
export interface LiveMarkerProbeOptions {
|
||||
hermesHome: string
|
||||
/** The script helper `reclaim`, or null when the checkout's script predates protocol 2. */
|
||||
reclaim: (() => Promise<MarkerHelperVerdict>) | null
|
||||
createTime?: CreateTimeProbe
|
||||
onLiveMarker?: (marker: { startedAt: number | null }) => void
|
||||
/** Every answer that comes from a running helper verdict (boot progress, the ceiling notice). */
|
||||
onHeld?: (state: HeldState) => void
|
||||
log?: (line: string) => void
|
||||
now?: () => number
|
||||
reprobeMs?: number
|
||||
/** Test seam; production is HELD_CEILING_MS. */
|
||||
heldCeilingMs?: number
|
||||
}
|
||||
|
||||
const STILL_RUNNING = new Set(['held', 'busy', 'live'])
|
||||
|
||||
// First sighting of each held body, process-wide: a later gate wait (a pool
|
||||
// backend, a reconnect) continues the same ceiling instead of restarting it.
|
||||
const firstHeldAt = new Map<string, number>()
|
||||
|
||||
function heldSince(key: string, startedAt: number | null, at: number): number {
|
||||
if (!firstHeldAt.has(key)) {
|
||||
if (firstHeldAt.size >= 16) {
|
||||
firstHeldAt.clear()
|
||||
}
|
||||
|
||||
firstHeldAt.set(key, at)
|
||||
}
|
||||
|
||||
const written = startedAt !== null && Number.isFinite(startedAt) && startedAt > 0 ? startedAt * 1000 : Infinity
|
||||
|
||||
return Math.min(firstHeldAt.get(key)!, written)
|
||||
}
|
||||
|
||||
/** `hasLiveMarker` for one gate wait (create it per wait, never module-wide). */
|
||||
export function liveMarkerProbe({
|
||||
hermesHome,
|
||||
reclaim,
|
||||
createTime,
|
||||
onLiveMarker,
|
||||
onHeld,
|
||||
log,
|
||||
now = Date.now,
|
||||
reprobeMs = HELD_REPROBE_MS
|
||||
reprobeMs = HELD_REPROBE_MS,
|
||||
heldCeilingMs = HELD_CEILING_MS
|
||||
}: LiveMarkerProbeOptions): () => Promise<boolean> {
|
||||
const asked = new Map<string, { running: boolean; at: number }>()
|
||||
const asked = new Map<string, { verdict: MarkerHelperVerdict; at: number; expiryLogged?: boolean }>()
|
||||
|
||||
return async () => {
|
||||
const inspection = await inspectUpdateMarker(hermesHome, { createTime, now })
|
||||
@@ -63,24 +116,87 @@ export function liveMarkerProbe({
|
||||
|
||||
const key = inspection.raw.toString('hex')
|
||||
const previous = asked.get(key)
|
||||
let entry = previous
|
||||
|
||||
if (previous && (!previous.running || now() - previous.at < reprobeMs)) {
|
||||
return previous.running
|
||||
if (!previous || (STILL_RUNNING.has(previous.verdict.kind) && now() - previous.at >= reprobeMs)) {
|
||||
const verdict = await reclaim()
|
||||
|
||||
if (!previous || STILL_RUNNING.has(previous.verdict.kind) !== STILL_RUNNING.has(verdict.kind)) {
|
||||
log?.(`[updates] dead update marker: script helper says ${verdict.kind}${'pid' in verdict ? ` ${verdict.pid}` : ''}`)
|
||||
}
|
||||
|
||||
entry = { ...previous, verdict, at: now() }
|
||||
asked.set(key, entry)
|
||||
}
|
||||
|
||||
const verdict = await reclaim()
|
||||
const running = STILL_RUNNING.has(verdict.kind)
|
||||
const { verdict } = entry!
|
||||
|
||||
if (!previous || previous.running !== running) {
|
||||
log?.(`[updates] dead update marker: script helper says ${verdict.kind}${'pid' in verdict ? ` ${verdict.pid}` : ''}`)
|
||||
if (!STILL_RUNNING.has(verdict.kind)) {
|
||||
return false
|
||||
}
|
||||
|
||||
asked.set(key, { running, at: now() })
|
||||
const startedAt = inspection.marker?.startedAt ?? null
|
||||
const since = heldSince(key, startedAt, now())
|
||||
const remainingMs = verdict.kind === 'live' ? null : Math.max(0, since + heldCeilingMs - now())
|
||||
|
||||
if (running) {
|
||||
onLiveMarker?.({ startedAt: inspection.marker?.startedAt ?? null })
|
||||
const state: HeldState = {
|
||||
verdict: verdict.kind as HeldState['verdict'],
|
||||
ownerPid: inspection.marker?.pid ?? null,
|
||||
livePid: 'pid' in verdict ? verdict.pid : null,
|
||||
since,
|
||||
remainingMs,
|
||||
expired: remainingMs === 0
|
||||
}
|
||||
|
||||
return running
|
||||
onHeld?.(state)
|
||||
|
||||
if (state.expired) {
|
||||
if (!entry!.expiryLogged) {
|
||||
entry!.expiryLogged = true
|
||||
log?.(
|
||||
`[updates] update marker still ${state.verdict} ${Math.round((now() - since) / 60_000)} min after its owner` +
|
||||
`${state.ownerPid ? ` (pid ${state.ownerPid})` : ''} last wrote it; no longer blocking start-up` +
|
||||
' (the scripts stop waiting at the same ceiling). The marker is left in place.'
|
||||
)
|
||||
}
|
||||
|
||||
return false
|
||||
}
|
||||
|
||||
onLiveMarker?.({ startedAt })
|
||||
|
||||
return true
|
||||
}
|
||||
}
|
||||
|
||||
function duration(ms: number): string {
|
||||
const m = Math.max(1, Math.ceil(ms / 60_000))
|
||||
|
||||
return m >= 120 ? `${Math.round(m / 60)} hours` : m === 1 ? '1 minute' : `${m} minutes`
|
||||
}
|
||||
|
||||
/** Boot-progress text while a dead marker's checkout is still held. */
|
||||
export function heldWaitMessage(state: HeldState): string {
|
||||
if (state.livePid !== null) {
|
||||
return `An update is still finishing (process ${state.livePid}) — Hermes will start automatically when it completes…`
|
||||
}
|
||||
|
||||
const who = state.ownerPid ? `the update (process ${state.ownerPid}) exited, but a process` : 'a process'
|
||||
|
||||
return (
|
||||
`An update is still finishing: ${who} it started still holds the Hermes install. ` +
|
||||
`Hermes will start when that process exits, or in ${duration(state.remainingMs ?? 0)} at the latest.`
|
||||
)
|
||||
}
|
||||
|
||||
/** Dialog detail once the ceiling let Hermes start over a still-held checkout. */
|
||||
export function heldCeilingNotice(state: HeldState): string {
|
||||
const owner = state.ownerPid ? ` (process ${state.ownerPid}, now exited)` : ''
|
||||
|
||||
return (
|
||||
`An earlier update${owner} left a process that still held the Hermes install ${duration(HELD_CEILING_MS)} ` +
|
||||
'later, so Hermes started without waiting for it. The update marker was left in place.\n\n' +
|
||||
'If something looks wrong: quit Hermes, end leftover git or hermes processes (or restart the computer), ' +
|
||||
'then run the update again from Settings or with `hermes update`. Details are in logs/update.log.'
|
||||
)
|
||||
}
|
||||
|
||||
Reference in New Issue
Block a user