Skip to content

fix(kernel-cli): log fatal exits from daemon-entry before terminating - #966

Merged
FUDCo merged 3 commits into
mainfrom
chip/daemon-entry-fatal-logging
Jul 15, 2026
Merged

fix(kernel-cli): log fatal exits from daemon-entry before terminating#966
FUDCo merged 3 commits into
mainfrom
chip/daemon-entry-fatal-logging

Conversation

@FUDCo

@FUDCoFUDCo commented Jul 8, 2026

Copy link
Copy Markdown
Contributor

Summary

  • Add process-level handlers in daemon-entry.ts for uncaughtException, unhandledRejection, SIGHUP, and exit.
  • Each handler synchronously appends a line to daemon.log before the process exits.
  • Handlers install at module load, before main() runs, so early kernel-init failures also leave a fingerprint.

Why

daemon-entry runs with stdio: 'ignore' under the CLI spawner (see daemon-spawn.ts). Node's default behaviour on uncaughtException / unhandledRejection (print stack to stderr, exit 1) therefore writes to nowhere, and the operator sees only that the daemon vanished — no trace in ~/.ocap*/daemon.log.

I've hit two silent daemon deaths in the last few weeks (matcher daemon disappearing mid-rehearsal, services daemon disappearing between registration and the next call), and in both cases the log ended cleanly on the last successful message with no shutdown line, no error, no stack trace. Debugging cost real time each time.

With this change, every terminating path now leaves at least one line:

[timestamp] [error] Uncaught exception (about to exit): <stack>
[timestamp] [error] Process exiting (code=1).

or

[timestamp] [error] SIGHUP received; exiting.
[timestamp] [error] Process exiting (code=0).

Log-write itself is wrapped in try/catch so a broken log file doesn't mask the original exit cause.

Test plan

  • yarn workspace @metamask/kernel-cli test:dev:quiet --run — all package tests pass.
  • yarn workspace @metamask/kernel-cli lint — clean.
  • CI green.
  • Manual (in a downstream branch): induce an uncaught exception in a scratch daemon under a temp $OCAP_HOME, confirm the log line lands and the process exits 1.

🤖 Generated with Claude Code


Note

Low Risk
Observability-only changes to daemon exit paths; SIGHUP now logs and exits 0 explicitly instead of the default silent terminate, with no auth or data-handling impact.

Overview
Daemon fatal-path visibility when the CLI spawns daemon-entry with stdio: 'ignore': uncaught errors and signals no longer vanish with no record in daemon.log.

daemon-entry now builds the file logger at module load (before main()), registers installFatalHandlers() immediately, and logs then exits on uncaughtException, unhandledRejection, and SIGHUP, with an exit handler that always writes a final line. The log transport switches from dynamic require('node:fs') to appendFileSync so fatal handlers flush synchronously. CHANGELOG documents the fix under Unreleased.

Reviewed by Cursor Bugbot for commit 70b96eb. Bugbot is set up for automated code reviews on this repo. Configure here.

daemon-entry runs with `stdio: 'ignore'` under the CLI spawner, so
Node's default behaviour on uncaughtException / unhandledRejection
(print stack to stderr, exit 1) writes to nowhere and the operator
sees only that the daemon vanished. Two recent debugging sessions
were consumed by silent daemon deaths that left no trace.
Install process-level handlers that append a synchronous log line
before the process exits:
- uncaughtException — captures stack, exits(1)
- unhandledRejection — captures reason, exits(1)
- SIGHUP — logs, exits(0) (default was silent terminate)
- exit — last-ditch record; fires on every exit path
Handlers are installed at module load, before main() runs, so
early kernel-init failures also leave a fingerprint. Each handler
uses only synchronous fs and the fs write is wrapped in try/catch
so a log-write failure never masks the original exit cause.
@github-actions

github-actionsBot commented Jul 8, 2026

Copy link
Copy Markdown
Contributor

Coverage Report

StatusCategoryPercentageCovered / Total
🔵Lines71.31%
⬇️ -0.08%
8869 / 12437
🔵Statements71.13%
⬇️ -0.08%
9019 / 12678
🔵Functions72.46%
⬇️ -0.13%
2140 / 2953
🔵Branches64.81%
⬇️ -0.11%
3584 / 5530
File Coverage
FileStmtsBranchesFunctionsLinesUncovered Lines
Changed Files
packages/kernel-cli/src/commands/daemon-entry.ts0%
🟰 ±0%
0%
🟰 ±0%
0%
🟰 ±0%
0%
🟰 ±0%
14-203
Generated in workflow #4529 for commit 70b96eb by the Vitest Coverage Report Action

@FUDCo
FUDCo marked this pull request as ready for review July 9, 2026 00:43
@FUDCo
FUDCo requested a review from a team as a code ownerJuly 9, 2026 00:43

@grypezgrypez left a comment

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

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

I think it would suffice to create the logger at file root scope instead of in the main header. File-scoped logger for entrypoints is alreadystandardconvention across the monorepo; seems we just missed this one because it is a command.

Comment on lines +155 to +181
/**
* Append a fatal-path entry to `daemon.log` synchronously. Used from
* `process.on('uncaughtException' | 'unhandledRejection' | 'SIGHUP')`
* handlers where the async logger pipeline can't be trusted to
* flush before the process exits. Best-effort: if the log file is
* unwritable we swallow the error rather than throw from a fatal
* handler.
*
* @param logPath - The daemon-log file path.
* @param message - Short label for the entry.
* @param detail - Optional extra data (stack, error, etc.) — coerced
* to string.
*/
function logFatalSync(
logPath: string,
message: string,
detail?: string | number,
): void {
try {
const tail = detail === undefined ? '' : ` ${detail}`;
const line = `[${new Date().toISOString()}] [error] ${message}${tail}\n`;
// eslint-disable-next-line n/no-sync -- fatal handler must flush before exit
appendFileSync(logPath, line);
} catch {
// Best-effort — the daemon is dying either way.
}
}

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

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

Suggested change
/**
*Appendafatal-pathentryto`daemon.log`synchronously.Usedfrom
*`process.on('uncaughtException' | 'unhandledRejection' | 'SIGHUP')`
*handlerswheretheasyncloggerpipelinecan't be trusted to
*flushbeforetheprocessexits.Best-effort: ifthelogfileis
*unwritableweswallowtheerrorratherthanthrowfromafatal
*handler.
*
* @paramlogPath-Thedaemon-logfilepath.
* @parammessage-Shortlabelfortheentry.
* @paramdetail-Optionalextradata(stack,error,etc.)coerced
*tostring.
*/
functionlogFatalSync(
logPath: string,
message: string,
detail?: string|number,
): void{
try{
consttail=detail===undefined ? '' : ` ${detail}`;
constline=`[${newDate().toISOString()}] [error] ${message}${tail}\n`;
// eslint-disable-next-line n/no-sync -- fatal handler must flush before exit
appendFileSync(logPath,line);
}catch{
// Best-effort — the daemon is dying either way.
}
}

The logger dispatch routine is already synchronous; async methods follow 'spray and pray' semantics, i.e. best effort.

I think the process.on handlers are doing the work here, not this function.

Copy link
Copy Markdown
ContributorAuthor

Choose a reason for hiding this comment

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

Good call — done in 70b96eb. Logger dispatch is indeed synchronous (Logger.#dispatch iterates transports via .forEach) and our file transport is appendFileSync, so logger.error(...) from a fatal handler flushes to disk before exit. Dropped the parallel sync helper.

process.on('uncaughtException', (error: unknown) => {
const detail =
error instanceof Error ? (error.stack ?? error.message) : String(error);
logFatalSync(logPath, 'Uncaught exception (about to exit):', detail);

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

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

Suggested change
logFatalSync(logPath,'Uncaught exception (about to exit):',detail);
logger.error('Uncaught exception',detail);

Copy link
Copy Markdown
ContributorAuthor

Choose a reason for hiding this comment

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

Done — the handler now calls logger.error(...) directly, and the file-scoped logger it references is hoisted to module top level in the same commit.

Applying @grypez review feedback on PR #966:
- Move the logger and its path from inside main() to file scope,
matching the entrypoint convention already used by app.ts,
background.ts, and vat-worker.ts.
- Delete logFatalSync — the logger's dispatch routine is synchronous
(Logger.#dispatch iterates transports via .forEach) and the file
transport itself is appendFileSync, so logger.error(...) from
inside a fatal handler flushes to disk before the process exits.
- Fatal handlers now call logger.error directly instead of the
parallel sync helper.
Behaviour is unchanged: every terminating path still writes a
line to daemon.log before the process goes away.
@FUDCo
FUDCo requested a review from grypezJuly 14, 2026 18:05
FUDCo added a commit that referenced this pull request Jul 14, 2026
Applying @grypez review feedback on PR #966:
- Move the logger and its path from inside main() to file scope,
matching the entrypoint convention already used by app.ts,
background.ts, and vat-worker.ts.
- Delete logFatalSync — the logger's dispatch routine is synchronous
(Logger.#dispatch iterates transports via .forEach) and the file
transport itself is appendFileSync, so logger.error(...) from
inside a fatal handler flushes to disk before the process exits.
- Fatal handlers now call logger.error directly instead of the
parallel sync helper.
Behaviour is unchanged: every terminating path still writes a
line to daemon.log before the process goes away.
FUDCo added a commit that referenced this pull request Jul 14, 2026
The demo branch's file-scope logger construction hit a temporal-
dead-zone reference because `makeFileTransport(logPath,
resolveMinLogLevel())` runs at module top and `resolveMinLogLevel`
uses `LOG_LEVELS`, which was declared as a `const` further down
the file. Function declarations hoist but `const` bindings stay
in TDZ until execution reaches them, so the daemon child crashed
at module init with:
ReferenceError: Cannot access 'LOG_LEVELS' before initialization
The crash happened before the fatal-handler install ran, and the
child was spawned with stdio: 'ignore', so the failure surfaced
only as a 30-second polling timeout ("Daemon did not start").
Move `LOG_LEVELS`, `LogLevelName`, and `resolveMinLogLevel()`
above the module-scope logger construction. Fixes the demo
branch; PR #966 (main-based) is unaffected because its transport
factory doesn't reference `LOG_LEVELS`.
grypez added a commit that referenced this pull request Jul 15, 2026
VatManager.initializeAllVats now restores each persisted vat in isolation.
A vat whose bundle is missing or unresolvable (fetch rejects with e.g.
ENOENT) is quarantined — skipped with a structured warning naming the vat,
its subcluster, and its bundle — and the rest of the kernel boots. The
persisted record is retained, so the vat is restored automatically on a
later boot if its bundle returns. Previously one orphaned bundle reference
made the whole kernel unbootable.
Daemon-side observability of fatal exits (rendering the real error to
daemon.log under `stdio: 'ignore'`) is handled separately by #966.
Co-Authored-By: Claude Opus 4.8 <noreply@anthropic.com>
@FUDCo
FUDCo added this pull request to the merge queueJul 15, 2026
Merged via the queue into main with commit bb23dd2Jul 15, 2026
37 checks passed
@FUDCo
FUDCo deleted the chip/daemon-entry-fatal-logging branch July 15, 2026 18:12
grypez added a commit that referenced this pull request Jul 15, 2026
VatManager.initializeAllVats now restores each persisted vat in isolation.
A vat whose bundle is missing or unresolvable (fetch rejects with e.g.
ENOENT) is quarantined — skipped with a structured warning naming the vat,
its subcluster, and its bundle — and the rest of the kernel boots. The
persisted record is retained, so the vat is restored automatically on a
later boot if its bundle returns. Previously one orphaned bundle reference
made the whole kernel unbootable.
Daemon-side observability of fatal exits (rendering the real error to
daemon.log under `stdio: 'ignore'`) is handled separately by #966.
Co-Authored-By: Claude Opus 4.8 <noreply@anthropic.com>
grypez added a commit that referenced this pull request Jul 16, 2026
VatManager.initializeAllVats now restores each persisted vat in isolation.
A vat whose bundle is missing or unresolvable (fetch rejects with e.g.
ENOENT) is quarantined — skipped with a structured warning naming the vat,
its subcluster, and its bundle — and the rest of the kernel boots. The
persisted record is retained, so the vat is restored automatically on a
later boot if its bundle returns. Previously one orphaned bundle reference
made the whole kernel unbootable.
Daemon-side observability of fatal exits (rendering the real error to
daemon.log under `stdio: 'ignore'`) is handled separately by #966.
Co-Authored-By: Claude Opus 4.8 <noreply@anthropic.com>
github-merge-queueBot pushed a commit that referenced this pull request Aug 5, 2026
…1008)
Small, self-contained quality-of-life change to the daemon's log
transport, extracted from `chip/orchestration-demo`. Independent of the
kernel work in #1007 — this branches off `main` directly rather than
stacking.
## Problem
`daemon.log` recorded every level. In practice `debug` output — refcount
churn especially — dominated the file badly enough to make it hard to
read while debugging anything else. On a busy daemon the signal you
actually want is buried.
## Change
The file transport drops entries below a minimum severity, defaulting to
`info`. Set `$OCAP_DAEMON_LOG_LEVEL=debug` to record everything again.
Two details worth a reviewer's eye:
- `LOG_LEVELS` mirrors `@metamask/logger`'s level ordering locally
because `logLevels` isn't part of that package's public surface. If it's
ever exported, this should switch to importing it rather than keeping a
copy in sync.
- It's declared *above* the file-scope logger construction deliberately.
The transport factory is invoked during module init, so a later
declaration would put `LOG_LEVELS` in its temporal dead zone at exactly
the moment it's read.
## Not included
The fatal-path handler work that lives in the same file is already on
`main` (#966), so this PR touches only the level-filtering lines.
## Validation
`@metamask/kernel-cli` builds, lints, and its tests pass. Changelog
entry follows in a second commit once this PR has a number to link to.
🤖 Generated with [Claude Code](https://claude.com/claude-code)
<!-- CURSOR_SUMMARY -->
---
> [!NOTE]
> **Low Risk**
> Observability-only change to log file filtering; no auth, RPC, or
persistence behavior is affected.
> > **Overview**
> **`daemon.log` now skips entries below a minimum severity** (default
**`info`**) in the daemon file transport, so noisy **`debug`** lines no
longer bury useful output.
> > The threshold comes from **`OCAP_DAEMON_LOG_LEVEL`**; set it to
**`debug`** to record all levels again. **`makeFileTransport`** compares
each entry against a local **`LOG_LEVELS`** map (mirroring
`@metamask/logger` ordering, since levels aren’t exported). Changelog
documents the behavior change.
> > <sup>Reviewed by [Cursor Bugbot](https://cursor.com/bugbot) for commit
66dc26d. Bugbot is set up for automated
code reviews on this repo. Configure
[here](https://www.cursor.com/dashboard/bugbot).</sup>
<!-- /CURSOR_SUMMARY -->
---------
Co-authored-by: Claude Opus 4.7 <noreply@anthropic.com>
sirtimid added a commit that referenced this pull request Aug 5, 2026
`main().catch` logged unguarded before the `process.exit(1)` the previous commit
added, and the daemon's transport is `appendFileSync`, so a full disk threw and
that exit was never reached. The process still died, but only by accident: the
throw escaped to `unhandledRejection`, whose handler logs too and so threw again,
and Node aborts when its own exception handler fails. Exit code 7 rather than 1,
and the `exit` fingerprint — the last-ditch record #966 added — lost with it.
Verified both the old path and the fix against a worker thread standing in for a
vat.
The four fatal handlers had the same shape for the same reason, each logging in
front of its own exit. `report` already existed for exactly this and was already
used on every run-loop failure path; export it as `logBestEffort` rather than
write a second one, and put it in front of all five exits.
Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Sign up for freeto 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.

2 participants

@FUDCo@grypez