fix(desktop): log why the MSIX relaunch waiter failed to start

startRelaunchWaiter returned undefined for four different failures
(staging dir, script copy, PowerShell spawn, missed handshake), and the
detached script runs with stdio ignored. The Store updater then showed
only "Could not register automatic relaunch" and desktop.log had no
reason, so a user report could not be told apart.

Each failure path now writes its cause to desktop.log (error text,
paths, exit code or signal, elapsed ms). The script appends its own
steps and exit reason to %TEMP%\hermes-relaunch-waiter.log, which
survives the stage dir it deletes on exit, and a failed handshake
includes that file's tail in desktop.log.

The two waiter call sites shared the same options block; they now go
through one startUpdateRelaunchWaiter so the log hook cannot be
forgotten at one of them.
This commit is contained in:
ethernet committed 2026-10-08 00:22:46 -04:00
1 parent cfb9ae4f86
commit bdb8f92f3b
4 files changed
+154 -22

No files matched your search

+8 -14
View File
@@ -656,7 +656,7 @@ import {
registerUpdateRelaunch,
type RelaunchRegistration
} from './updater/relaunch'
import { relaunchWaiterScript, startRelaunchWaiter } from './updater/relaunch-waiter'
import { startUpdateRelaunchWaiter } from './updater/relaunch-waiter'
import { preflightStateDb } from './updater/state-db-preflight'
import { createStoreStrategy } from './updater/store-client'
import { isExternalVenvHolder, isHermesOwnedVenvDaemon } from './venv-holder-select'
@@ -3856,12 +3856,7 @@ function createNativePackagedStrategy(
// script is staged to a temp dir and resolved absolutely so
// nothing inherited from the package holds the swap open.
relaunch: () =>
startRelaunchWaiter({
processId: process.pid,
processStartTimeMs: Math.round(Date.now() - process.uptime() * 1000),
identityName: PRODUCT_IDENTITY.msixAppIdWithOrg,
scriptPath: relaunchWaiterScript(process.resourcesPath)
})
startUpdateRelaunchWaiter(PRODUCT_IDENTITY.msixAppIdWithOrg, process.resourcesPath, rememberLog)
})
}
@@ -3887,13 +3882,12 @@ function createNativePackagedStrategy(
registerPendingRelaunch: (fromVersion: string): Promise<RelaunchRegistration> =>
registerUpdateRelaunch(app, fromVersion, {
relaunch: () =>
startRelaunchWaiter({
processId: process.pid,
processStartTimeMs: Math.round(Date.now() - process.uptime() * 1000),
identityName: PRODUCT_IDENTITY.storeMsix!.identityName,
scriptPath: relaunchWaiterScript(process.resourcesPath),
timeoutSeconds: 1860
})
startUpdateRelaunchWaiter(
PRODUCT_IDENTITY.storeMsix!.identityName,
process.resourcesPath,
rememberLog,
1860
)
})
})
}
@@ -195,3 +195,56 @@ test('missing scripts refuse startup before spawning a waiter', async (): Promis
)
assert.equal(spawned, false)
})
test('every failed start tells the log why it failed', async (): Promise<void> => {
const logs: string[] = []
const log = (message: string): void => void logs.push(message)
await startRelaunchWaiter(
{
processId: process.pid,
processStartTimeMs: 1_000_000,
identityName: 'disposable-waiter-test',
scriptPath: path.join(scriptPath, 'absent.ps1')
},
{ log }
)
assert.match(logs.join('\n'), /cannot copy .*absent\.ps1/)
logs.length = 0
await startRelaunchWaiter(
{ processId: process.pid, processStartTimeMs: 1_000_000, identityName: 'disposable-waiter-test', scriptPath },
{
log,
spawn: (): never => {
throw new Error('EACCES fixture')
}
}
)
assert.match(logs.join('\n'), /spawning .*powershell\.exe threw: Error: EACCES fixture/)
logs.length = 0
await startRelaunchWaiter(
{ processId: process.pid, processStartTimeMs: 1_000_000, identityName: 'disposable-waiter-test', scriptPath },
{
log,
pollMs: 20,
spawn: (_command, _args, options): ChildProcess =>
spawn(process.execPath, ['-e', 'process.exit(2)'], { ...options, stdio: 'ignore' })
}
)
assert.match(logs.join('\n'), /exited before its handshake after \d+ms \(exit code 2/)
logs.length = 0
await startRelaunchWaiter(
{ processId: process.pid, processStartTimeMs: 1_000_000, identityName: 'disposable-waiter-test', scriptPath },
{
log,
pollMs: 20,
handshakeTimeoutMs: 200,
spawn: (_command, _args, options): ChildProcess =>
spawn(process.execPath, ['-e', 'setInterval(() => {}, 1000)'], { ...options, stdio: 'ignore' })
}
)
assert.match(logs.join('\n'), /no handshake within 200ms \(pid \d+\); stopping it/)
}, 20_000)
@@ -61,6 +61,27 @@ export interface RelaunchWaiterDeps {
/** Poll interval for the ready file (tests shrink this). */
pollMs?: number
cancelTimeoutMs?: number
/** Where the reason for each failed start goes (the caller passes desktop.log). */
log?: (message: string) => void
}
/** Written by the waiter script itself, outside the stage dir that it deletes on exit. */
export const RELAUNCH_WAITER_LOG_FILENAME = 'hermes-relaunch-waiter.log'
function errorText(error: unknown): string {
return error instanceof Error ? `${error.name}: ${error.message}` : String(error)
}
function waiterLogTail(maxChars: number = 1500): string {
const file: string = path.join(os.tmpdir(), RELAUNCH_WAITER_LOG_FILENAME)
try {
const text: string = fs.readFileSync(file, 'utf8').trim()
return `${file}:\n${text.slice(-maxChars)}`
} catch {
return `${file}: not written (the script never ran far enough to log)`
}
}
/** Pure: the exact argv the waiter is spawned with. */
@@ -86,12 +107,17 @@ export function buildRelaunchWaiterArgs(options: RelaunchWaiterOptions, readyFil
}
/** Stage outside the package so its replacement does not invalidate the waiter. */
async function stageRelaunchWaiter(options: RelaunchWaiterOptions): Promise<WaiterStaging | undefined> {
async function stageRelaunchWaiter(
options: RelaunchWaiterOptions,
log: (message: string) => void
): Promise<WaiterStaging | undefined> {
let stageDir: string
try {
stageDir = await fs.promises.mkdtemp(path.join(os.tmpdir(), 'hermes-relaunch-'))
} catch {
} catch (error) {
log(`[updates] relaunch waiter: cannot create a staging dir under ${os.tmpdir()}: ${errorText(error)}`)
return undefined
}
@@ -101,6 +127,8 @@ async function stageRelaunchWaiter(options: RelaunchWaiterOptions): Promise<Wait
try {
await fs.promises.copyFile(options.scriptPath, scriptPath)
} catch (error) {
log(`[updates] relaunch waiter: cannot copy ${options.scriptPath} to ${scriptPath}: ${errorText(error)}`)
try {
await fs.promises.rm(stageDir, { recursive: true, force: true })
} catch (cleanupError) {
@@ -126,7 +154,8 @@ export async function startRelaunchWaiter(
const handshakeTimeoutMs = deps.handshakeTimeoutMs ?? DEFAULT_RELAUNCH_WAITER_HANDSHAKE_MS
const pollMs = deps.pollMs ?? 250
const cancelTimeoutMs = deps.cancelTimeoutMs ?? 10_000
const staging = await stageRelaunchWaiter(options)
const log = deps.log ?? ((): void => {})
const staging = await stageRelaunchWaiter(options, log)
if (!staging) {
return undefined
@@ -142,6 +171,8 @@ export async function startRelaunchWaiter(
{ detached: true, stdio: 'ignore', windowsHide: true, cwd: staging.stageDir }
)
} catch (error) {
log(`[updates] relaunch waiter: spawning ${POWERSHELL_PATH} threw: ${errorText(error)}`)
try {
await cleanup()
} catch (cleanupError) {
@@ -152,6 +183,7 @@ export async function startRelaunchWaiter(
}
let closed = false
const startedAt = Date.now()
const closedPromise = new Promise<void>(resolve => {
child.once('close', () => {
@@ -207,8 +239,21 @@ export async function startRelaunchWaiter(
resolve(ready)
}
child.once('error', () => finish(false))
child.once('close', () => finish(false))
child.once('error', error => {
log(`[updates] relaunch waiter: PowerShell failed to start: ${errorText(error)}`)
finish(false)
})
child.once('close', (code, signal) => {
if (!settled) {
log(
`[updates] relaunch waiter: exited before its handshake after ${Date.now() - startedAt}ms ` +
`(exit code ${code ?? 'none'}, signal ${signal ?? 'none'}; 1 = script error, 2 = identity ` +
`${options.identityName} not found or has no app id)\n${waiterLogTail()}`
)
}
finish(false)
})
const check = () => {
if (settled) {
@@ -228,6 +273,13 @@ export async function startRelaunchWaiter(
})
if (!ready) {
if (!closed) {
log(
`[updates] relaunch waiter: no handshake within ${handshakeTimeoutMs}ms ` +
`(pid ${child.pid ?? 'none'}); stopping it\n${waiterLogTail()}`
)
}
await cancel()
return undefined
@@ -237,3 +289,22 @@ export async function startRelaunchWaiter(
return { cancel }
}
/** The MSIX update paths all hand off to this waiter; `log` is where a failed start explains itself. */
export function startUpdateRelaunchWaiter(
identityName: string,
resourcesPath: string,
log: (message: string) => void,
timeoutSeconds?: number
): Promise<RelaunchWaiterHandle | undefined> {
return startRelaunchWaiter(
{
processId: process.pid,
processStartTimeMs: Math.round(Date.now() - process.uptime() * 1000),
identityName,
scriptPath: relaunchWaiterScript(resourcesPath),
timeoutSeconds
},
{ log }
)
}
@@ -8,16 +8,24 @@ param(
[int]$PollMillis = 500
)
# The parent runs this detached with no stdio, so this file is the only record of why it gave up.
$LogFile = Join-Path $env:TEMP 'hermes-relaunch-waiter.log'
function Write-WaiterLog([string]$Message) {
try { Add-Content -LiteralPath $LogFile -Value ('{0} [{1}] {2}' -f (Get-Date -Format o), $PID, $Message) } catch {}
}
try {
$ErrorActionPreference = 'Stop'
Write-WaiterLog "start: parent=$ProcessId identity=$IdentityName timeout=${TimeoutSeconds}s"
$deadline = (Get-Date).AddSeconds($TimeoutSeconds)
$package = Get-AppxPackage -Name $IdentityName | Select-Object -First 1
if (-not $package) { exit 2 }
if (-not $package) { Write-WaiterLog "no package named $IdentityName"; exit 2 }
$appId = (Get-AppxPackageManifest $package).Package.Applications.Application.Id | Select-Object -First 1
if (-not $appId) { exit 2 }
if (-not $appId) { Write-WaiterLog "package $($package.PackageFullName) has no application id"; exit 2 }
$fromVersion = $package.Version
$familyName = $package.PackageFamilyName
Set-Content -LiteralPath $ReadyFile -Value "$fromVersion|$familyName|$appId"
Write-WaiterLog "ready: from=$fromVersion family=$familyName app=$appId"
while ($true) {
$parent = Get-Process -Id $ProcessId -ErrorAction SilentlyContinue
@@ -25,19 +33,25 @@ try {
# Compare absolute birth times. Process age changes on every poll.
$birthMs = ([DateTimeOffset]$parent.StartTime).ToUnixTimeMilliseconds()
if ([Math]::Abs($birthMs - $ProcessStartTimeMs) -gt 3000) { break }
if ((Get-Date) -gt $deadline) { exit 3 }
if ((Get-Date) -gt $deadline) { Write-WaiterLog 'timed out waiting for the parent to exit'; exit 3 }
Start-Sleep -Milliseconds $PollMillis
}
while ((Get-Date) -le $deadline) {
$current = Get-AppxPackage -Name $IdentityName | Select-Object -First 1
if ($current -and $current.Version -ne $fromVersion -and $current.PackageFamilyName -eq $familyName) {
Write-WaiterLog "package is now $($current.Version); launching"
Start-Process "shell:AppsFolder\$familyName!$appId"
Write-WaiterLog 'launched'
exit 0
}
Start-Sleep -Milliseconds $PollMillis
}
Write-WaiterLog "timed out waiting for the package version to change from $fromVersion"
exit 4
} catch {
Write-WaiterLog ('failed: ' + ($_ | Out-String).Trim())
exit 1
} finally {
Set-Location $env:TEMP
Remove-Item -LiteralPath $ReadyFile -Force -ErrorAction SilentlyContinue