Compare commits

...
1 Commits
Author SHA1 Message Date
Garry TanandClaude Fable 5 8bf23abf71 v0.46.6.0 fix(minions): verify-before-evict lock renewal + per-job leases (#4145) (#4170)
* minions: classify lock-renewal failure causes + starvation telemetry (#4145)

The incident's forensics cost ~8h because the eviction log lines could not
say WHY renewal failed. This commit makes every renewal fault self-explaining
without changing abort semantics:

- Named RenewalCallTimeoutError so cause classification (call-timeout vs
  refused vs fenced-lost) is name-based, never message-sniffing.
- Tick lateness (now - lastTickFiredAt - intervalMs) as the primary
  local-starvation signal — interval callbacks coalesce under a blocked
  loop, so a missed-tick counter cannot measure starvation; lateness can.
  overlap_skips counts tickInFlight re-entrancy skips only.
- Elapsed-time arithmetic now binds deps.now to performance.now()
  (monotonic): wall-clock jumps can no longer distort the deadline math.
  Date.now remains only in log/audit timestamps.
- loadSnapshot dep (raw loadavg[0] + cached core count), try/caught at
  every call site — telemetry must never re-open the unhandledRejection
  class this module exists to close.
- Worker-level event-loop-delay histogram (perf_hooks.monitorEventLoopDelay,
  fail-open when the runtime lacks it), RESET on every successful renewal
  so an eviction-time sample attributes to the exact window in which
  renewal was failing; sampled into the abort + grace-evict log lines.
- Per-launch abortMeta stash so the grace-evict line (which fires 30s
  after the abort) reports cause/lateness/load instead of just the Error
  string that made healthy evictions read like orphan leaks.
- Audit events gain additive optional fields (cause, lateness_ms,
  overlap_skips, load1, cores, via, deadline_deferred) behind a
  back-compatible optional trailing ctx param; the 4-outcome contract and
  pre-upgrade JSONL readback are unchanged (pinned by new tests).

Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>

* minions: inFlight generation-safety — lockToken-conditional deletes (#4145)

Force-evict and the handler's finally both deleted the inFlight entry by
bare job.id. When a force-evicted job is requeued and re-claimed by the
SAME worker while the old handler is still alive, the old execution's
late delete removed the NEW execution's entry — concurrency undercount
and lost tracking for the replacement run. Every claim mints a unique
lockToken and the entry already stores it, so the token is the
generation: both deletes now only remove the entry when it is still
their own.

Pre-existing bug surfaced by the #4145 outside-voice review (R2-1);
fixed in its own commit because the eviction path is exactly what this
wave modifies. Pinned by a deterministic same-worker reclaim test
(stale execution A's finally leaves execution B's entry intact).

Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>

* minions: stall-sweep reclaim grace (#4145)

handleStalled reclaimed on a bare lock_until < now(). When a CPU-starved
worker's event loop unblocks, its coalesced renewal tick and the stall
sweep fire in the same burst — if the sweep's UPDATE lands first it
steals the OWNER'S live job and discards its in-flight work. All three
sweep predicates now carry a reclaim grace (default 15s, env
GBRAIN_MINION_STALL_RECLAIM_GRACE_MS, 0 = exact legacy behavior).

The grace is a head-start for the owner's recovery renewal, not a
guarantee: it covers starvation bursts shorter than the grace; a healthy
second worker's sweep still wins beyond it. Cost: dead-worker recovery
becomes lock_until + grace + up to stalledInterval. This is the minion
analog of the cycle-lock steal grace, adapted because minion_jobs has no
last_refreshed_at column.

Existing stall tests move their synthetic lock_until offsets from 1s to
30s past (they pin stall mechanics on the production default path); new
tests pin within-grace hold, beyond-grace reclaim, grace=0 legacy, and
env resolution incl. warn-once fallback.

Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>

* minions: verify-before-evict + hard eviction deadline (#4145)

The root-cause fix. The only abort path was the throw branch's local
arithmetic: one timed-out renewal on a starvation-delayed tick past
lockDuration - safetyMargin evicted a healthy job — under load the
renewal UPDATE may even have LANDED server-side while the local race
timeout won. 2,571 subagent jobs submitted / 24 done in 24h.

New contract (ports the cycle-lock fencing doctrine to Minion job locks):

- Fenced-false is the only CERTAIN eviction signal; a throw is not
  evidence of loss. When the NEXT tick would land past the soft deadline
  (cadence-aware: sinceLastSuccess + intervalMs >= deadline — the bare
  >= gate is unreachable under cadence quantization for long leases),
  the tick runs ONE bounded VERIFY renewal. renewLock fences on
  lock_token and deliberately ignores lock_until, so an
  expired-but-unstolen lease revives: fenced-true → starved-but-ours,
  keep working (the incident-saving path); fenced-false → certain loss,
  abort (stall detector requeues, no attempt burned); verify unreachable
  → defer + reconnect-once, aborting only past the hardEvictMs backstop
  (default 2×lease, env GBRAIN_LOCK_RENEWAL_HARD_EVICT_MS, floored to
  the soft deadline) — a LOCAL decision under uncertainty that bounds
  blind external side effects during a total outage.
- The verify is a synchronous, cancelled()-guarded, callTimeoutMs-bounded
  call inside the tick's own flow — reconciled in-code with queue.ts's
  no-background-retry rationale (both UPDATEs are same-token idempotent
  lease extensions; a fenced row cannot gain two holders).
- Best-effort cancellation: the race timeout now aborts the in-flight
  renewLock via AbortSignal threaded to executeRawDirect; both engines'
  entry points gained an already-aborted preflight BEFORE dispatch/pool
  acquisition. The fence stays the correctness authority.
- Relational knob validation: margin < lease/2, callTimeout <= cadence,
  hardEvict >= soft deadline — clamped with warn-once; positive-integer
  parsing alone could silently re-break the deadline math.
- Doctrine comments rewritten (tick header + worker grace-evict) — the
  old abort-at-deadline prose actively misled.

Tests: incident replay (starved renewal times out, verify succeeds, job
survives — the exact #4145 shape), fenced-false via verify, deferral +
hard-backstop timelines, CDX-4 quantization pin (300s/60s verifies at
240s with lease left), first-tick verify at the 30s default,
mid-verify cancellation, reconnect-on-deferral, relational clamps, and
a DATABASE_URL-gated e2e pinning the DB-level foundations (expired-
but-unstolen revival, grace hold, post-reclaim fenced-false, and a
blocked-event-loop worker completing with zero stall bounces).

Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>

* minions: per-job lock_duration_ms end-to-end (#4145)

A single worker-global 30s lockDuration cannot serve both 2s shell jobs
and 173s-average LLM subagent jobs — the structural half of the #4145
incident. The lease is now a per-job column resolved through the same
three-layer model as timeout_ms (explicit submit → handler-type map →
worker default), claim-stamped so it survives worker restarts.

- Migration v129 + the 3 schema copies: nullable lock_duration_ms with
  the positive CHECK added via the idempotent drop-then-add pattern (v7
  precedent) — no fresh-vs-migrated asymmetry, no backfill (NULL = worker
  default = pre-#4145 behavior; claim COALESCE owns all defaulting).
- HANDLER_DEFAULT_LOCK_DURATION_MS beside the timeout map (long LLM
  handlers 300s, single-call LLM handlers 120s, shell deliberately absent
  for fast dead-worker reclaim) under one rewritten header explaining why
  lease and wall-clock budget are different quantities.
- Claim derives lock_until from COALESCE(row, map, worker default) and
  stamps the resolved lease; the map binds as a RAW object (jsonb
  double-encode rule). Wall-clock null-fallback becomes
  COALESCE(lock_duration_ms, worker default) so an explicit lease on an
  unmapped handler isn't killed at the old bound (NULL rows pinned to
  exact legacy behavior).
- Worker consumes the effective per-job lease at all three launch sites;
  renewal cadence clamps to min(lease/2, 60s) — a 300s lease renews 5x
  per window instead of every 150s; ≤120s leases keep legacy /2 exactly.
  Derived knob defaults cap at 15s call-timeout / 30s margin so long
  leases don't inherit wedge-inducing values.
- Shared clampLockDurationMs [5s, 1h] used by queue.add, the new
  gbrain jobs submit --lock-duration-ms flag, and the MCP submit_job
  param (handler-side clamp; ParamDef has no min/max — wrong types are
  rejected by the existing number validation). INSERT-only on idempotent
  re-submit, matching the max_stalled footgun rule.
- jobs get shows the lease line alongside the timeout line.

Tests: migration v129 structure/idempotency/CHECK/pre-shape re-run;
claim-stamps-from-map + lock_until horizon; explicit-wins + clamp bounds;
idempotent-resubmit immutability; wall-clock NULL-row regression pin +
leased-row survival; lifetime max_stalled accumulation pin (the known
coverage gap); per-lease knob derivation caps.

Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>

* docs(minions): lock-renewal knobs, eviction-forensics guide, verify-before-evict current-state (#4145)

- queue-operations-runbook.md gains the incident-reading section the
  #4145 forensics lacked: how to read a gave_up/eviction line (cause,
  lateness_ms, load1/cores, overlap_skips, deadline_deferred,
  event-loop-delay), the was-the-DB-down-or-the-worker-starved decision
  table, the full env-knob table (CALL_TIMEOUT / SAFETY_MARGIN /
  HARD_EVICT / MAX_FAILURES / STALL_RECLAIM_GRACE) with relational-clamp
  semantics and legacy escape hatches, and the honest zombie caveat
  (eviction is cooperative until the kill/reap follow-up lands).
- minions-deployment.md's 'what can still bite' section rewritten for
  verify-before-evict + per-type leases + reclaim grace; documents the
  mixed-version-fleet degradation (old workers = legacy behavior, no
  drain needed) and adds --lock-duration-ms to the per-job tuning list.
- KEY_FILES.md entries (lock-renewal-tick.ts ×2 duplicated entries,
  worker.ts, queue.ts, handler-timeouts.ts) updated to current state.
- TODOS.md: filed the kill/reap-evicted-handler follow-up (P2), the
  worker-level --lock-duration flag (P3), and the TODO-LR-2 note that
  its doctor-check inputs now exist in the audit events.
- llms bundles regenerated (unchanged — these guides aren't inlined).

Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>

* test: scrub leaked GBRAIN_HOME from doctor-minions-check subprocess env

The test seeds $HOME/.gbrain/migrations fixtures and spawns gbrain doctor
with HOME overridden — but doctor resolves its home via resolveGbrainHome,
which prefers GBRAIN_HOME over HOME. Sibling test files in the same bun
process (preferences, friction, bootstrap-*, and several .serial files'
beforeEach hooks) set process.env.GBRAIN_HOME; a value captured by the
{...process.env} spread makes the fixture invisible, doctor finds nothing,
and the expected FAIL exit code never happens. Scrub GBRAIN_HOME exactly
like the DATABASE_URL variables already scrubbed two lines up.

Surfaced while triaging a non-blessed whole-suite invocation during the
#4145 wave (reproduced identically on master); the blessed sharded runner
can also co-schedule a GBRAIN_HOME-mutating file into this shard, so the
scrub closes a real flake vector, not just a synthetic one.

Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>

* fix(bootstrap): verify probe cleanup hard-deletes instead of leaving soft-delete tombstones

verify's end-of-run probe cleanup invoked the delete_page OP, which since
v0.26.5 is a SOFT delete — every verify run left two probe tombstone rows
in the user's brain (visible to include_deleted readers) until the 72h
purge. Cleanup now hard-deletes via engine.deletePage(slug, {sourceId}),
the same primitive sweepProbeLeftovers already uses on both engines, with
the warning-capture semantics preserved. Pinned by the (previously
failing) probe-residue assertion in the Postgres bootstrap-verify e2e.

Surfaced by the e2e fix wave: CI runs only 6 of 185 test/e2e files
(.github/workflows/e2e.yml), so the developer-lane files rot silently.

Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>

* fix(search): deterministic relationalFanout path pick on equal-depth multi-seed ties

The fanout's representative-path pick ordered only by (depth, path
length); a node reachable at the same depth from multiple seeds had NO
tie-break, so the winner was plan/heap-order dependent — a fresh PGLite
and a lived-in Postgres heap could disagree, violating both engine parity
and the documented deterministic relational-retrieval contract. Appended
a lexicographic final tie-break to the array_agg ORDER BY in BOTH engines
(lockstep). The engine-parity e2e's multi-seed fanout case now passes on
real Postgres; its stale-page arm also moves off client wall-clock stamps
onto per-row updated_at_iso (the #1768 production semantics) so VM clock
drift can't skew the count.

Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>

* test(e2e): per-file outer-timeout override for LLM-bound Tier-2 files

run-e2e.sh's hard 180s-per-file gtimeout SIGKILLed skills.test.ts mid-run
(the ingest skill alone has been observed at ~131s of real provider
round-trips), producing a mystery failure with no assertion output. CI
runs the Tier-2 keyed files in their own job WITHOUT this wrapper, so the
cap only ever bit local runs. The cap is now GBRAIN_E2E_FILE_TIMEOUT
(default 180) with 4x for skills.test.ts + zeroentropy-live.test.ts.

Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>

* test(e2e): un-rot the developer-lane files — 27 failures across 10 files, all green on both lanes

CI runs only 6 of the 185 test/e2e files; the rest run solely through the
developer-machine lane (bun run test:e2e / ci:local) and had rotted as src
moved deliberately underneath them. Every fix pins CURRENT intended
behavior with the causing commit cited in-file; no assertion was weakened
and several were strengthened. Root causes:

- sync.test.ts (13): the #2114 global-anchor ownership guard (636628fdb)
  refuses anchor writes when the default source's local_path names another
  repo; setupDB truncates config but not sources, so residue from earlier
  files vetoed every bookmark write. The test now resets the default
  source identity in beforeAll.
- v0_29-mcp-dispatch (2): the #4096 WP1/D7 locality backstop dispatches
  localOnly ops only on transport 'stdio'; tests now dispatch with the
  real stdio shape, plus a NEW fail-closed unknown_tool pin for unset
  transport markers across both trust values.
- extract-atoms-discovery-sql (4): PR #2615 widened discovery to the
  schema pack's extractable:true types ('note' included); tests re-pin
  with 'person' as the non-extractable control + wider seed cleanup.
- pglite-cli-exit (1) + bootstrap-harness-lifecycle (1): the wrapper's
  ambient DATABASE_URL leaked into subprocess/in-process env, silently
  retargeting PGLite tests onto shared Postgres (#801 env-override
  precedence); both files now scrub it at their boundaries.
- embedding-column-pglite (1): #3554 changed resetGateway() to restore
  the test-preload baseline; the #3461 fallback test now uses
  __unconfigureGatewayForTests() so the unconfigured path really fires.
- openclaw-plugin-load-real (1): the Retrieval Reflex import chain pulls
  PGLite WASM assets into the bundle — bun build --outfile cannot emit
  multi-output builds; switched to --outdir with entry naming + a
  version-robust runtime inspection helper.
- phantom-redirect (1): halfvec migration (v40) + the #2932 idempotent
  reconcile; the string-shape guard now accepts both legitimate vector
  types.
- serve-http-oauth (1): sql.array() on a fresh connection races the
  async typeArrayMap fetch and binds text instead of text[]; seed uses a
  plain-array bind (the same untyped approach production pgArray() uses).
- type-unification-full-flow (1): checkPackUpgradeAvailable reads the
  operator's real ~/.gbrain config; the test now isolates GBRAIN_HOME and
  pins both the warn and ok arms hermetically.

Verified: full e2e lane 186/186 files, 1279/1279 tests on a pristine
pgvector container; the 14 previously-failing files re-verified green on
the residue-carrying locally-configured database as well.

Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>

* fix(minions): ship-review hardening — histogram lifecycle, cadence single-home, consumption re-clamp, DRY telemetry (#4145)

Fix-First batch from /ship's specialist + coverage reviews (21 findings,
all informational; the mechanical ones applied, the rest pinned by tests):

- The event-loop-delay histogram now disables in stop() and (re-)enables
  in start() — each cycled worker instance previously leaked a ~50Hz
  native sampling timer for process lifetime (embedding hosts and the
  test suite cycle workers constantly).
- renewalIntervalFor()/RENEWAL_INTERVAL_CAP_MS: ONE home for the
  min(lease/2, 60s) cadence formula, used by the worker's timer AND as
  resolveLockRenewalKnobs' default intervalMs — previously the knob
  default (lease/2 uncapped) diverged from production cadence for leases
  over 120s, silently weakening the CDX-10 relational validation for
  callers that omit intervalMs.
- Defense-in-depth re-clamp at consumption: launchJob clamps a row
  lease through clampLockDurationMs — the exposed submit surfaces clamp,
  but a writer bypassing add() could stamp a 1ms lease (renewal-storm
  interval) or a ~25-day one (weeks-long dead-worker pin).
- formatAbortMeta(): one formatter for the classified abort telemetry;
  the three log sites had already drifted (load1: vs load1_at_abort:).
- Knob docstrings updated to the capped defaults (min(lease/3, 15s) /
  min(lease/6, 30s)); KEY_FILES dedup + stale-count scrub; dead test
  binding removed; run-e2e.sh validates GBRAIN_E2E_FILE_TIMEOUT
  digits-only before arithmetic/interpolation.

New pins: worker renews with the per-job lease (launchJob wiring, GAP-1);
claim precedence row-beats-map at the claim UPDATE; MCP submit_job
clamp round-trip incl. the 0→default boundary; jobs get lease lines
(all three states); bootstrap-verify tombstone-proof pages count on
PGLite; relationalFanout lexicographic WINNER (not just parity);
grace-env warn-once dedupe.

Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>

* fix(minions): adversarial-review hardening — claim-time clamp, grace cap, range CHECK, honest dry-run echo (#4145)

Two independent adversarial passes (Codex + Claude) converged on the same
lease-bounds gaps; this batch closes them:

- Claim SQL clamps the resolved row/map lease to [5s,1h] before deriving
  lock_until, so a bypass-written out-of-range value can't produce a
  pathological lease at claim time. The worker-default path ($2) passes
  through untouched (tests pin a 1ms worker lease).
- Migration v130 + all 3 schema copies upgrade the CHECK to a full range
  constraint (>= 5000 AND <= 3600000) — the DB bound now matches the
  app-side clamp instead of only enforcing positivity.
- GBRAIN_MINION_STALL_RECLAIM_GRACE_MS is capped at 600s with a warn-once
  (an absurd env value silently disabled stall reclaim fleet-wide).
- Hard-evict comparison recomputes elapsed AFTER the bounded verify, so
  the backstop can't defer one extra cadence past its advertised bound;
  the should_abort payload carries the recomputed value.
- Verify-failure telemetry re-samples loadavg at its own failure instead
  of reusing a snapshot stale by the verify's duration; audit note that
  the attempt counter advances by 2 per at-deadline tick.
- racedRenewLock/attemptReconnectOnce clear the losing race timer on the
  win path (no stray late abort against a settled query).
- jobs submit --dry-run echoes the CLAMPED lease (annotated when it
  differs from the raw input) instead of echoing a value add() won't store.

Tests: migrations-v130 range-CHECK rejection loop + bypass-clamp claim
test; grace-cap pin; dry-run echo cases. 301 pass / 0 fail targeted;
typecheck clean.

Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>

* chore: bump version and changelog (v0.46.6.0)

Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>

* docs: document-release sweep for v0.46.6.0 — lease-bound enforcement, grace cap, e2e file timeout

Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>

* fix(test): stop run-child-entry SIGTERM test from broadcasting to leaked process listeners

The SIGTERM-semantics test fired a bare process.emit('SIGTERM') in the
shared bun test process. When an earlier file in the same shard had
installed process-cleanup.ts's signal handlers (module-global, never
uninstalled), the broadcast reached its handler, whose cleanup pass ends
in process.exit(143) — killing the entire shard mid-suite. The runner
then misclassified rc=143 as an external kill ("sibling workspace pkill /
memory jetsam") and queued a rescue pass that died the same way when it
reached the same test. Whether it fired depended on file interleaving;
under heavy host load the schedule made it deterministic (three
consecutive suite runs died at the ~3-minute mark with zero test
failures).

The test now snapshots the SIGTERM listener set before invoking
runChildJobEntry and fires ONLY the listener(s) the entry registered —
same wiring under test, no global broadcast.

Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>

* docs: changelog entry for the unit-suite shard self-kill fix

Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>

* fix(test): best-effort tmpdir cleanup in run-child-entry afterAll — EFAULT rmSync flake reds the CI shard

CI shard 3 failed with an "(unnamed)" test: bun treats a throwing afterAll
as a failed test, and the hook's recursive rmSync EFAULT'd (bun 1.3.13,
ubuntu-24.04) immediately after the PGLite WASM engine teardown. All 8
real tests passed. Cleanup is now try/retry/warn — a tmpdir the OS reaps
anyway must never red the suite.

Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>

---------

Co-authored-by: Claude Fable 5 <noreply@anthropic.com>
2026-08-15 22:06:05 -07:00
56 changed files with 2499 additions and 297 deletions
+1 -1
View File
@@ -1,4 +1,4 @@
<!-- gbrain-runbook-stamp: 0.46.5.0 -->
<!-- gbrain-runbook-stamp: 0.46.6.0 -->
<!-- This stamp must equal the VERSION file at every release; CI enforces it
(scripts/check-bootstrap-tag.sh). `gbrain bootstrap status` compares it to
the installed binary and warns on skew. -->
+78
View File
@@ -2,6 +2,84 @@
All notable changes to GBrain will be documented in this file.
## [0.46.6.0] - 2026-08-15
**A busy machine can no longer make the job queue evict its own healthy
work.** ([#4145](https://github.com/garrytan/gbrain/issues/4145)) Under
sustained CPU load, a long-running background job (a subagent averaging
~3 minutes) could miss one lock-renewal window and get force-evicted
mid-inference — the queue would churn for hours while completions stayed
near zero, and the logs read like an orphan leak. Lock renewal is now
**verify-before-evict**: a slow or failed renewal is never treated as
loss; the worker asks the database the one authoritative question (a
fenced re-check) and keeps the job whenever the lease is still its own.
### Added
- **Per-job lock leases.** Long LLM handlers (subagent, autopilot-cycle,
embed-backfill, …) now hold a 300s lease by default instead of the
global 30s; single-call LLM handlers get 120s; short jobs keep 30s for
fast dead-worker recovery. Override per submission with
`gbrain jobs submit --lock-duration-ms N` (clamped to 5s1h; also an
MCP `submit_job` param). Stored on the job row (migration v130), so it
survives worker restarts, and renewed at a `min(lease/2, 60s)` cadence.
The bound is enforced end-to-end — at submit, again on the resolved
lease at claim, and by a database range constraint — and
`--dry-run` echoes the clamped value that will actually be stored.
- **Self-explaining eviction forensics.** Every renewal fault now logs and
audits WHY it failed (call-timeout vs refused vs fenced-lost), how late
the renewal timer fired vs its own cadence (the "was the worker starved
or was the database down?" discriminator), host load, and an
event-loop-delay sample scoped to the failing window. The ops runbook
gained a table for reading these plus the full env-knob reference
(`GBRAIN_LOCK_RENEWAL_*`, `GBRAIN_MINION_STALL_RECLAIM_GRACE_MS`).
- **Stall-sweep reclaim grace.** A lease that lapsed within the last 15s
is not reclaimed — a just-recovered worker's own renewal wins the race
against the sweep instead of having its live job stolen (env-tunable,
capped at 10 minutes with a warn-once clamp; `0` restores the previous
behavior).
### Changed
- **Eviction requires evidence.** The renewal state machine aborts a job
only on a fenced miss (the row was genuinely reclaimed — requeued with
no attempt burned) or after a hard backstop (default 2× the lease)
during a total database outage. Wall-clock jumps can no longer distort
the decision (elapsed-time math runs on a monotonic clock), and a
renewal timeout now also cancels the in-flight query so it stops
holding a pool slot.
- **`gbrain jobs get`** shows the job's lock lease alongside its
wall-clock budget, including the default that will stamp at claim.
### Fixed
- **The unit-suite's SIGTERM-semantics test no longer kills its own
shard.** A bare in-process signal broadcast could reach a leaked
cleanup handler from an earlier test file and exit the whole test
process mid-suite, misreading as an external kill; the test now fires
only the listeners it registered.
- **`gbrain verify` no longer leaves probe tombstones in your brain.**
The end-of-run probe cleanup previously soft-deleted its two probe
pages; every verify run left residue visible to `include_deleted`
readers until the 72h purge. Cleanup now hard-deletes.
- **Relational retrieval is deterministic on ties.** When a graph node is
reachable at the same depth from multiple seeds, the reported path was
plan/heap-order dependent (and could differ between engines); a
lexicographic tie-break restores the documented determinism.
- **A worker slot can no longer lose track of a re-claimed job.** After a
force-evict, the stale execution's cleanup could delete the tracking
entry of the SAME job re-claimed by the same worker; both cleanup sites
now verify generation (lock token) before deleting.
- **Developer e2e lane un-rotted.** 29 test failures across 13 files in
the developer-machine e2e lane (which CI does not run) were fixed:
ten rotted test files re-pinned to current intended behavior, plus the
wrapper's per-file timeout now accommodates the LLM-bound Tier-2 files
(`GBRAIN_E2E_FILE_TIMEOUT`).
To take advantage of v0.46.6.0: upgrade and restart your worker
(`gbrain jobs supervisor stop && gbrain jobs supervisor start --detach`).
Existing queues need no migration steps — the new lease column defaults
every existing row to its handler's lease at next claim. If you tuned
around the old eviction behavior (e.g. very high `--max-stalled`), you can
likely lower it now. Mixed fleets are safe: an old worker simply keeps the
old 30s behavior until restarted.
## [0.46.5.0] - 2026-08-15
**CI in half, evals actually gating.** The Test workflow ran 89.5 minutes on
+32
View File
@@ -1,5 +1,37 @@
# TODOS
## #4145 lock-renewal wave follow-ups (filed 2026-08-15)
- [ ] **P2 — Kill or reap the force-evicted handler process.** **What:** when the
grace-evict fires for a handler that ignores its AbortSignal, actually
terminate the handler's work (LLM loop cancellation vs shell child-tree
kill differ per handler class) or track it as a zombie instead of only
freeing the inFlight slot. **Why:** today the evicted handler keeps
burning CPU/spend on an already-saturated host while the worker claims
new work — the #4145 amplification loop — and the duplicate-external-
side-effect window during an asymmetric outage is bounded only by
handler cooperation, not by `hardEvictMs`. **Context:** deliberately
scoped out of the #4145 wave (grace-evict at
`src/core/minions/worker.ts` frees the slot; the alternative — retaining
the slot until handler exit — re-opens the wedged-slot class D8b closed).
Eviction frequency collapsed with verify-before-evict, so this is
hygiene, not the incident driver. Kill semantics need their own review.
**Effort:** M (human) / S (CC). **Priority:** P2.
- [ ] **P3 — Worker-level `--lock-duration` flag on `jobs work` + supervisor
passthrough.** **What:** a CLI flag for the worker-global default lease,
threaded through `buildWorkerArgs` (`src/core/minions/supervisor.ts`).
**Why:** convenience only — per-job/per-type leases
(`HANDLER_DEFAULT_LOCK_DURATION_MS`, `--lock-duration-ms`) plus the
`GBRAIN_LOCK_RENEWAL_*` env knobs already cover every incident-tuning
case shipped in the #4145 wave. **Context:** requested shape existed in
the issue; deferred because no production caller overrides
`lockDuration` and env wins for incident response. **Effort:** S.
**Priority:** P3.
- [ ] **Note for TODO-LR-2 (doctor `lock_renewal_health`, already filed
below):** the #4145 wave shipped exactly its inputs — audit events now
carry `cause`, `lateness_ms`, `overlap_skips`, `load1`/`cores`, `via`,
`deadline_deferred` — so the doctor check can classify starved-worker
vs DB-outage windows without new plumbing.
## v0.47 SEPTEMBER REMOVAL — ZeroEntropy (filed v0.46.3.0; TARGET: ship 2026-09-04..2026-09-08)
ZeroEntropy's hosted API dies 2026-09-04. v0.46.3.0 deprecated it (split-default:
+1 -1
View File
@@ -1 +1 @@
0.46.5.0
0.46.6.0
+1 -1
View File
@@ -138,7 +138,7 @@ Triage rule: a `warn-pass` EXIT-HANG line in `.context/test-summary.txt` is NOT
- `*.test.ts` → fast loop (parallel up-to-4-shard fan-out, memory-adaptive).
- `*.slow.test.ts` → run via `bun run test:slow` only (intentional cold-path tests; would dominate the fast loop's wallclock).
- `*.serial.test.ts` → run via `bun run test:serial` after the parallel pass completes; one bun process per file (`--max-concurrency=1` within a shared process is not enough — the module registry still leaks `mock.module`), with those per-file processes POOLED (per-process isolation never required one-at-a-time execution). Files touching machine-global state (launchd/cron) live on the sequential `EXCLUSIVE_FILES` lane inside `scripts/run-serial-tests.sh` — growth-guarded to ≤3 entries with justification comments. Quarantine for tests that share file-wide state and race when run alongside other files in the same `bun test` process. Several dozen files, discovered by the `*.serial.test.ts` glob — no list to maintain. Typical residents: `mock.module(...)` users (top-level mocks leak across files in a shard process, e.g. `test/embed.serial.test.ts`), env-coupled files (e.g. `test/brain-registry.serial.test.ts`), and process-lifecycle suites that assert on `process.exitCode` (e.g. `test/pglite-engine-disconnect.serial.test.ts`). **Do not put the parallelism back on a serial file unless you've fixed the contention root cause** (it just re-introduces the flake).
- `test/e2e/*.test.ts` → real-Postgres E2E. Skipped when `DATABASE_URL` is unset. One out-of-directory file rides this lane: `test/phantom-redirect-engine-parity.test.ts` (lives in `test/` for its PGLite arm, but its Postgres arm is only reachable through a DATABASE_URL-bearing lane — the unit wrappers strip the URL per #3485, so `run-e2e.sh`'s no-args list and CI's parity job carry it).
- `test/e2e/*.test.ts` → real-Postgres E2E. Skipped when `DATABASE_URL` is unset. One out-of-directory file rides this lane: `test/phantom-redirect-engine-parity.test.ts` (lives in `test/` for its PGLite arm, but its Postgres arm is only reachable through a DATABASE_URL-bearing lane — the unit wrappers strip the URL per #3485, so `run-e2e.sh`'s no-args list and CI's parity job carry it). `run-e2e.sh` wraps each file in a hard outer timeout (default 180s; `GBRAIN_E2E_FILE_TIMEOUT=<seconds>` overrides) because a synchronously-blocking PGLite WASM call can outlive bun's timer-based `--timeout`; LLM-bound Tier-2 files (`skills.test.ts`, `zeroentropy-live.test.ts`) automatically get 4× the cap since real provider round-trips legitimately run past 180s.
- `tests/heavy/*.sh` → ops-shape shell scripts. Cost minutes per run; NOT in default `bun test`. Run via `bun run test:heavy` or scheduled nightly via `.github/workflows/heavy-tests.yml`. Examples: pg_upgrade matrix (boot legacy brain → walk to head), RSS budget gate (measure peak worker RSS vs committed baseline), read-latency-under-sync (p50/p95/p99 under concurrent writer load), sync lock regression (N concurrent syncs assert 1 winner + N-1 lock-busy + zero leaked `gbrain_cycle_locks` rows). See `tests/heavy/README.md` for when to add a script here vs `*.slow.test.ts`. Files prefixed with `_` (e.g. `tests/heavy/_build_legacy_fixtures.sh`) are helpers/libs invoked by sibling tests — the runner skips them.
- `test/fuzz/*.test.ts` → property-based fuzz harness. Pure-validator targets in `pure-validators.test.ts` are guarded by `scripts/check-fuzz-purity.sh` (in `bun run verify`), which `bun build --target=bun` bundles each target and greps the resulting bundle for banned transitive imports (`node:fs`, `node:child_process`, engine modules). Anything that fails the guard moves to `mixed-validators.test.ts` (still property-tested, but no purity guarantee) or `filesystem-validators.test.ts` (fs-backed, uses temp dirs). Fuzz tests run in the default `bun test` loop because they're fast (~3s for ~12 properties × 1000 runs each).
File diff suppressed because one or more lines are too long
+24 -6
View File
@@ -361,16 +361,34 @@ claimable work waits. The escalation commands and thresholds live in the
[queue operations runbook](queue-operations-runbook.md) — that's the
canonical home for wedge recovery.
What can still bite: a *brief* blip during a long-running job can make
lock renewal miss, and the stall detector dead-letters the job after
`max_stalled` misses (schema column default 5; lock duration and stall
check interval are both 30 s).
What can still bite is now narrow. Lock renewal is verify-before-evict:
a thrown or timed-out renewal is never treated as loss — at the deadline
the worker asks the database the authoritative question (one fenced
re-check), so a starved-but-healthy job recovers its lease and keeps
working. Eviction happens only on a fenced miss (the row was genuinely
reclaimed — requeued with no attempt burned) or after a hard backstop
(default 2× the lease) during a total outage. Long LLM handlers also get
a 300 s lock lease by default (`HANDLER_DEFAULT_LOCK_DURATION_MS`)
instead of the worker-global 30 s, and the stall sweep grants a 15 s
reclaim grace so a just-recovered worker's renewal beats the sweep.
The remaining exposure: a genuinely dead worker's long-lease job waits
up to lease + grace + one sweep interval before requeue, and the stall
detector still dead-letters after `max_stalled` genuine misses (schema
column default 5).
Mixed-version fleets degrade gracefully: an old worker ignores the
`lock_duration_ms` column and runs the legacy 30 s behavior; new workers
honor old rows via the claim-time default. No drain or ordered restart
is required.
**Tune per-job.** `gbrain jobs submit` accepts `--max-stalled N`,
`--backoff-type fixed|exponential`, `--backoff-delay <ms>`,
`--backoff-jitter 0..1`, and `--timeout-ms N` as first-class flags.
`--timeout-ms N`, `--lock-duration-ms N` (lock lease, clamped to
[5 s, 1 h]), and `--backoff-jitter 0..1` as first-class flags.
These write onto the job row at submit time — which is what
`handleStalled()` reads — so per-job tuning is the real knob.
`handleStalled()` and the renewal timer read — so per-job tuning is the
real knob. The lock-renewal env knobs (incident escape hatches) are
documented in the [queue operations runbook](queue-operations-runbook.md).
### DO NOT pass `maxStalledCount` to `MinionWorker`
+51
View File
@@ -107,6 +107,57 @@ gbrain jobs smoke --wedge-rescue
`queue.add()` call. If you want a taller pile, raise the threshold via
`GBRAIN_QUEUE_WAITING_THRESHOLD=50 gbrain doctor`.
## Lock-renewal: reading an eviction, and the knobs
Since v0.46 lock renewal is **verify-before-evict**: a thrown or timed-out
renewal is never treated as loss. At the deadline the worker runs one fenced
re-check against the database — the only CERTAIN loss signal is that fenced
miss. Every renewal fault also writes a JSONL audit event
(`~/.gbrain/audit/lock-renewal-*.jsonl`) carrying the fields that answer the
first incident question — *was the database down, or was the worker starved?*
How to read a `gave_up` / eviction line:
| Field | Reading |
|---|---|
| `cause` | `call-timeout` = our own timer fired (starved loop, slow pool, or slow DB); `refused` = the driver threw (SQLSTATE in `error_code`); `fenced-lost` = certain reclaim, not an infrastructure fault. |
| `lateness_ms` | How late the renewal tick fired vs its own cadence. Tens of seconds = the WORKER was starved (the #4145 shape); ~0 with `refused` = the database was actually unreachable. |
| `load1` / `cores` | Raw loadavg at event time, with core count for normalization. |
| `overlap_skips` | Ticks skipped because a prior renewal call was still in flight. |
| `deadline_deferred` | The soft deadline passed but the fenced verify was unreachable — the job was KEPT and retried (the fence is the backstop). |
| `event_loop_delay …` (log line) | p99/max event-loop delay since the last successful renewal — the direct starvation measurement. |
A `Job N did not exit within 30s of abort` line after an infrastructure
abort is NOT an orphan leak: the handler is cooperatively cancelling. The
line carries the same cause/lateness/load fields. Caveat: eviction is
cooperative — an abort-IGNORING handler keeps running past every bound and
can duplicate external side effects until it exits; the worker only frees
the slot.
Env knobs (incident escape hatches; all validated, warn-once on bad values;
defaults derive from the per-job lease):
| Env var | Default | What it does |
|---|---|---|
| `GBRAIN_LOCK_RENEWAL_CALL_TIMEOUT_MS` | `min(lease/3, 15s)` | Per-call budget for each renewal attempt (raced + best-effort cancelled). |
| `GBRAIN_LOCK_RENEWAL_SAFETY_MARGIN_MS` | `min(lease/6, 30s)` | Headroom before lease expiry; the fenced verify fires when the NEXT tick would land past `lease - margin`. |
| `GBRAIN_LOCK_RENEWAL_HARD_EVICT_MS` | `2 × lease` | Hard local backstop when even the verify is unreachable (total outage). Floored to the soft deadline. Setting it TO the soft deadline approximates the legacy abort-at-deadline behavior. |
| `GBRAIN_LOCK_RENEWAL_MAX_FAILURES` | 3 | Audit-event labeling only — never gates eviction. |
| `GBRAIN_MINION_STALL_RECLAIM_GRACE_MS` | 15000 | Stall-sweep reclaim grace: a lease that lapsed within this window is not reclaimed (starved-owner head start). `0` restores the legacy `lock_until < now()` predicate. Capped at 600000 (10 min, warn-once + clamp) — an oversized value would otherwise disable stalled-job recovery fleet-wide. |
Cross-knob invariants are enforced with warn-once clamps (margin < lease/2,
call timeout ≤ renewal cadence, hard evict ≥ soft deadline) — a
misconfigured knob can degrade cadence but cannot silently re-break the
deadline math.
Per-job lease: `gbrain jobs submit --lock-duration-ms N` (clamped
[5 s, 1 h] — enforced at submit, re-applied to the resolved lease at
claim, and backed by a database range constraint; `--dry-run` echoes the
clamped value that will actually be stored); long LLM handlers default to 300 s via
`HANDLER_DEFAULT_LOCK_DURATION_MS` in `src/core/minions/handler-timeouts.ts`.
Renewal cadence is `min(lease/2, 60 s)`. Trade-off: a genuinely dead
worker's long-lease job requeues after lease + grace + one sweep interval.
## Self-check: is a worker even running?
```bash
+1 -1
View File
@@ -1,7 +1,7 @@
{
"id": "gbrain-context-engine",
"name": "gbrain",
"version": "0.46.5.0",
"version": "0.46.6.0",
"description": "Personal knowledge brain with Postgres + pgvector hybrid search",
"family": "bundle-plugin",
"configSchema": {
+1 -1
View File
@@ -164,7 +164,7 @@
"bun": ">=1.3.10"
},
"license": "MIT",
"version": "0.46.5.0",
"version": "0.46.6.0",
"overrides": {
"@hono/node-server": "^2.0.5",
"fast-uri": "^3.1.5",
+2 -2
View File
@@ -67,13 +67,13 @@ if grep -Eq 'lockTimer[[:space:]]*=[[:space:]]*setInterval\([[:space:]]*async' "
echo " routes through src/core/minions/lock-renewal-tick.ts:"
echo
echo " setInterval(() => {"
echo " if (tickInFlight) return;"
echo " if (tickInFlight) { state.overlapSkips += 1; return; }"
echo " tickInFlight = true;"
echo " void runLockRenewalTick(deps, state)"
echo " .then(handleResult)"
echo " .catch(handlePostError)"
echo " .finally(() => { tickInFlight = false; });"
echo " }, lockDurationMs / 2);"
echo " }, renewalIntervalMs); // min(lease/2, 60s)"
exit 1
fi
+24 -8
View File
@@ -186,16 +186,32 @@ for f in "${files[@]}"; do
if [ -n "${DATABASE_URL:-}" ]; then
psql "$DATABASE_URL" -At -c "SELECT pg_terminate_backend(pid) FROM pg_stat_activity WHERE pid != pg_backend_pid() AND datname = current_database()" >/dev/null 2>&1 || true
fi
# Hard outer timeout (180s per file). bun's --timeout covers tests AND
# hooks (measured on 1.3.14), but it's timer-based: a PGLite WASM call
# that blocks the event loop synchronously never lets the timer fire and
# the file wedges indefinitely. gtimeout/timeout SIGKILLs the file so the
# suite advances. gtimeout (macOS via coreutils) preferred; timeout (Linux)
# fallback; bare bun (no outer cap) if neither is installed.
# Hard outer timeout (default 180s per file; GBRAIN_E2E_FILE_TIMEOUT
# overrides). bun's --timeout covers tests AND hooks (measured on 1.3.14),
# but it's timer-based: a PGLite WASM call that blocks the event loop
# synchronously never lets the timer fire and the file wedges indefinitely.
# gtimeout/timeout SIGKILLs the file so the suite advances. gtimeout (macOS
# via coreutils) preferred; timeout (Linux) fallback; bare bun (no outer
# cap) if neither is installed.
#
# LLM-bound Tier-2 files (real provider round-trips when .env.testing
# carries keys) legitimately run past 180s — the ingest skill alone has
# been observed at ~131s — and were being SIGKILLed mid-run with no
# assertion output, which reads like a mystery failure. CI runs those
# files in their own job WITHOUT this wrapper (see .github/workflows/
# e2e.yml tier2), so the cap only ever bit local runs: give them 4x.
file_timeout="${GBRAIN_E2E_FILE_TIMEOUT:-180}"
# Digits-only validation (same strict positive-int posture as the TS env
# knobs): a malformed value falls back to the default instead of
# word-splitting into extra gtimeout arguments or breaking the 4x math.
case "$file_timeout" in ''|*[!0-9]*) file_timeout=180 ;; esac
case "$f" in
*/skills.test.ts|*/zeroentropy-live.test.ts) file_timeout=$((file_timeout * 4)) ;;
esac
if command -v gtimeout >/dev/null 2>&1; then
TIMEOUT_CMD="gtimeout 180"
TIMEOUT_CMD="gtimeout $file_timeout"
elif command -v timeout >/dev/null 2>&1; then
TIMEOUT_CMD="timeout 180"
TIMEOUT_CMD="timeout $file_timeout"
else
TIMEOUT_CMD=""
fi
+34 -2
View File
@@ -17,7 +17,7 @@ import type { PaceKeyOverrides } from '../core/pace-mode.ts';
import { loadConfig, isThinClient } from '../core/config.ts';
import { callRemoteTool, unpackToolResult } from '../core/mcp-client.ts';
import { parseNiceValue, applyNiceness, getEffectiveNiceness, formatNice } from '../core/minions/niceness.ts';
import { defaultTimeoutMsFor } from '../core/minions/handler-timeouts.ts';
import { defaultTimeoutMsFor, defaultLockDurationMsFor, clampLockDurationMs } from '../core/minions/handler-timeouts.ts';
function parseFlag(args: string[], flag: string): string | undefined {
const idx = args.indexOf(flag);
@@ -242,7 +242,17 @@ function formatTimeoutLines(job: MinionJob): string[] {
if (d != null) {
lines.push(` Timeout: (unset) — handler default ${d}ms stamps at claim`);
} else {
lines.push(` Timeout: (unset) — null-default wall-clock sweep applies (2 x lock-duration x max_stalled, ~5m at defaults)`);
lines.push(` Timeout: (unset) — null-default wall-clock sweep applies (2 x lock lease x max_stalled, ~5m at 30s-lease defaults)`);
}
}
// #4145: the lock lease line mirrors the timeout line — row value when
// stamped, otherwise the handler-map default that WILL stamp at claim.
if (job.lock_duration_ms != null) {
lines.push(` Lock lease: ${job.lock_duration_ms}ms (renewed at min(lease/2, 60s) cadence)`);
} else {
const lease = defaultLockDurationMsFor(job.name);
if (lease != null) {
lines.push(` Lock lease: (unset) — handler default ${lease}ms stamps at claim`);
}
}
return lines;
@@ -286,6 +296,7 @@ USAGE
[--max-waiting N]
[--backoff-type fixed|exponential] [--backoff-delay Nms]
[--backoff-jitter 0..1] [--timeout-ms Nms]
[--lock-duration-ms Nms]
[--idempotency-key K] [--queue Q] [--dry-run]
[--redact-secrets] (shell only; scrubs inherit
values from stdout/stderr)
@@ -455,6 +466,7 @@ USAGE
[--max-waiting N]
[--backoff-type fixed|exponential] [--backoff-delay Nms]
[--backoff-jitter 0..1] [--timeout-ms Nms]
[--lock-duration-ms Nms]
[--idempotency-key K] [--queue Q] [--dry-run]
[--redact-secrets]
@@ -471,6 +483,10 @@ OPTIONS
source before coalescing new submissions ([1,100])
--timeout-ms Nms Per-job wall-clock budget. Long-lane handlers get a
default from HANDLER_DEFAULT_TIMEOUT_MS when omitted.
--lock-duration-ms N Per-job lock lease (#4145). Clamped to [5s, 1h].
Long-lane handlers default to 300s via
HANDLER_DEFAULT_LOCK_DURATION_MS; others use the
worker default (30s).
--idempotency-key K At-most-one row per key (dead/cancelled free the key)
--queue Q Target queue (default: default)
--dry-run Print what would be submitted, submit nothing
@@ -580,6 +596,15 @@ export async function runJobs(engineOrNull: BrainEngine | null, args: string[]):
console.error('Error: --timeout-ms must be a positive integer (milliseconds)');
process.exit(1);
}
// #4145: per-job lock lease. Clamped to [5s,1h] in queue.add via
// clampLockDurationMs (shared with the MCP op); NULL falls to the
// handler map, then the worker default.
const lockDurationMsRaw = parseFlag(args, '--lock-duration-ms');
const lockDurationMs = lockDurationMsRaw !== undefined ? parseInt(lockDurationMsRaw, 10) : undefined;
if (lockDurationMsRaw !== undefined && (isNaN(lockDurationMs!) || lockDurationMs! <= 0)) {
console.error('Error: --lock-duration-ms must be a positive integer (milliseconds)');
process.exit(1);
}
const idempotencyKey = parseFlag(args, '--idempotency-key');
const queueName = parseFlag(args, '--queue') ?? 'default';
const dryRun = hasFlag(args, '--dry-run');
@@ -603,6 +628,12 @@ export async function runJobs(engineOrNull: BrainEngine | null, args: string[]):
if (backoffDelay !== undefined) console.log(` Backoff delay: ${backoffDelay}ms`);
if (backoffJitter !== undefined) console.log(` Backoff jitter: ${backoffJitter}`);
if (timeoutMs !== undefined) console.log(` Timeout: ${timeoutMs}ms`);
if (lockDurationMs !== undefined) {
// Echo what will actually be STORED (queue.add clamps to [5s,1h]);
// a dry-run that prints the raw out-of-range input lies.
const stored = clampLockDurationMs(lockDurationMs);
console.log(` Lock lease: ${stored}ms${stored !== lockDurationMs ? ` (clamped from ${lockDurationMs}ms)` : ''}`);
}
if (idempotencyKey) console.log(` Idempotency key: ${idempotencyKey}`);
if (delay > 0) console.log(` Delay: ${delay}ms`);
console.log(` Data: ${JSON.stringify(data)}`);
@@ -648,6 +679,7 @@ export async function runJobs(engineOrNull: BrainEngine | null, args: string[]):
backoff_delay: backoffDelay,
backoff_jitter: backoffJitter,
timeout_ms: timeoutMs,
lock_duration_ms: lockDurationMs,
idempotency_key: idempotencyKey,
queue: queueName,
}, trusted);
+46 -6
View File
@@ -47,6 +47,7 @@ import * as fs from 'fs';
import * as path from 'path';
import { createAuditWriter, resolveAuditDir, computeIsoWeekFilename } from './audit-writer.ts';
import { redactConnectionInfo } from './redact-connection-info.ts';
import type { LockRenewalTelemetryCtx } from '../minions/lock-renewal-tick.ts';
export type LockRenewalOutcome =
| 'failure'
@@ -77,6 +78,23 @@ export interface LockRenewalAuditEvent {
error_message_summary?: string;
/** Postgres SQLSTATE if present (e.g. '08006' for connection failure). */
error_code?: string;
// -- v0.46 additive telemetry (issue #4145 request 3). All optional: --
// -- pre-upgrade JSONL lines parse unchanged; the 4-outcome contract --
// -- is untouched. --
/** Failure-cause classification: call-timeout | refused | fenced-lost. */
cause?: string;
/** How late the renewal tick fired vs its own cadence (ms) — the local-starvation signal. */
lateness_ms?: number;
/** Interval callbacks skipped by the tickInFlight re-entrancy guard (overlap, NOT missed intervals). */
overlap_skips?: number;
/** os.loadavg()[0] at event time (raw, not normalized; 0 on Windows). */
load1?: number;
/** Core count paired with load1 so operators can normalize. */
cores?: number;
/** For success_after_failure: which path recovered — plain renewal or the at-deadline verify. */
via?: string;
/** True when the deadline was reached but eviction was deferred (verify threw pre-hard-deadline). */
deadline_deferred?: boolean;
}
const FEATURE_NAME = 'lock-renewal';
@@ -93,14 +111,33 @@ const writer = createAuditWriter<LockRenewalAuditEvent>({
* without writing to disk.
*/
export interface LockRenewalAuditSink {
logFailure(jobId: number, jobName: string, attempt: number, err: unknown): void;
logSuccessAfterFailure(jobId: number, jobName: string, recoveredAfterAttempts: number): void;
logGaveUp(jobId: number, jobName: string, totalFailures: number, err: unknown): void;
// Trailing ctx params are optional + additive (ENG-E2): the tick's
// structural SinkLike and pre-existing test fakes stay assignable.
logFailure(jobId: number, jobName: string, attempt: number, err: unknown, ctx?: LockRenewalTelemetryCtx): void;
logSuccessAfterFailure(jobId: number, jobName: string, recoveredAfterAttempts: number, ctx?: LockRenewalTelemetryCtx): void;
logGaveUp(jobId: number, jobName: string, totalFailures: number, err: unknown, ctx?: LockRenewalTelemetryCtx): void;
logExecuteJobRejected(jobId: number, jobName: string, err: unknown): void;
}
/**
* Copy only DEFINED ctx fields onto the event so absent telemetry stays
* absent from the JSONL (no `"load1":undefined` noise, stable byte size).
*/
function compactCtx(ctx?: LockRenewalTelemetryCtx): Partial<LockRenewalAuditEvent> {
if (!ctx) return {};
const out: Partial<LockRenewalAuditEvent> = {};
if (ctx.cause !== undefined) out.cause = ctx.cause;
if (ctx.lateness_ms !== undefined) out.lateness_ms = ctx.lateness_ms;
if (ctx.overlap_skips !== undefined) out.overlap_skips = ctx.overlap_skips;
if (ctx.load1 !== undefined) out.load1 = ctx.load1;
if (ctx.cores !== undefined) out.cores = ctx.cores;
if (ctx.via !== undefined) out.via = ctx.via;
if (ctx.deadline_deferred !== undefined) out.deadline_deferred = ctx.deadline_deferred;
return out;
}
export const lockRenewalAudit: LockRenewalAuditSink = {
logFailure(jobId, jobName, attempt, err) {
logFailure(jobId, jobName, attempt, err, ctx) {
writer.log({
job_id: jobId,
job_name: jobName,
@@ -108,18 +145,20 @@ export const lockRenewalAudit: LockRenewalAuditSink = {
outcome: 'failure',
error_message_summary: summarizeError(err),
error_code: extractErrorCode(err),
...compactCtx(ctx),
});
},
logSuccessAfterFailure(jobId, jobName, recoveredAfterAttempts) {
logSuccessAfterFailure(jobId, jobName, recoveredAfterAttempts, ctx) {
writer.log({
job_id: jobId,
job_name: jobName,
attempt: recoveredAfterAttempts,
outcome: 'success_after_failure',
// No error_message_summary or error_code: recovery has no error.
...compactCtx(ctx),
});
},
logGaveUp(jobId, jobName, totalFailures, err) {
logGaveUp(jobId, jobName, totalFailures, err, ctx) {
writer.log({
job_id: jobId,
job_name: jobName,
@@ -127,6 +166,7 @@ export const lockRenewalAudit: LockRenewalAuditSink = {
outcome: 'gave_up',
error_message_summary: summarizeError(err),
error_code: extractErrorCode(err),
...compactCtx(ctx),
});
},
logExecuteJobRejected(jobId, jobName, err) {
+7 -2
View File
@@ -570,7 +570,6 @@ async function runRoundtrip(
const putPage = findOp('put_page');
const getPage = findOp('get_page');
const queryOp = findOp('query');
const deletePage = findOp('delete_page');
await sweepProbeLeftovers(engine, ws, sourceId);
@@ -675,10 +674,16 @@ async function runRoundtrip(
}
// 6. Delete the probes [G13] — failure is a WARNING, never a verify fail.
// HARD delete via the engine primitive (same as sweepProbeLeftovers): the
// probe is not user content and verify is a trusted local caller. The
// delete_page OP is a v0.26.5 SOFT delete (sets deleted_at, row stays in
// pages until the 72h purge) — using it here left two probe tombstones in
// the user's brain after every verify run, visible to include_deleted
// readers and pinned as residue by the Postgres e2e cleanup assertion.
const deleteWarnings: string[] = [];
for (const slug of [VERIFY_PROBE_SLUG, VERIFY_PROBE_ENTITY_SLUG]) {
try {
await deletePage.handler(ctx, { slug });
await engine.deletePage(slug, { sourceId });
} catch (e) {
deleteWarnings.push(`${slug}: ${(e as Error).message}`);
}
+1 -1
View File
@@ -61,7 +61,7 @@ export const CLI_FLAG_REGISTRY: Record<string, readonly string[]> = {
'init': ['--all', '--brain', '--chat-model', '--check', '--ctx-size', '--embedding-dimensions', '--embedding-model', '--embeddings', '--entity', '--expansion-model', '--fast', '--flag', '--force', '--from-pages', '--grant-types', '--help', '--http', '--issuer-url', '--json', '--judge-model', '--key', '--mcp-only', '--mcp-url', '--migrate-only', '--model', '--multimodal', '--no', '--no-embed', '--no-embedding', '--non-interactive', '--oauth-client-id', '--oauth-client-secret', '--path', '--pglite', '--provenance', '--reranking', '--schema-pack', '--scopes', '--skip-embed-check', '--source', '--stale', '--supabase', '--surface', '--to', '--token-ttl', '--touchpoint', '--url', '--version'],
'integrations': ['--auto', '--brain', '--dry-run', '--embeddings', '--fast', '--force', '--from-pages', '--help', '--http', '--json', '--no-embedding', '--overwrite', '--refresh', '--reranking', '--source', '--surface', '--target', '--token-ttl'],
'integrity': ['--aliases', '--all', '--auto', '--backend', '--background', '--brain', '--brain-wide-max-cost-usd', '--check', '--confidence', '--cost', '--dry-run', '--explain', '--fast', '--follow', '--force', '--fresh', '--from-pages', '--help', '--http', '--include-null-signature', '--json', '--limit', '--no-embedding', '--no-extract', '--pattern', '--pending', '--progress-interval', '--progress-json', '--quiet', '--remediate', '--reset', '--resolve', '--review-lower', '--skip-bare-tweet', '--skip-urls', '--source', '--stale', '--supabase', '--supersessions', '--surface', '--thin', '--timeout', '--token-ttl', '--type', '--url'],
'jobs': ['--abbrev-ref', '--aliases', '--all', '--allow-empty', '--allow-protected', '--allow-shell-jobs', '--apply', '--asof', '--auto', '--auto-fix', '--auto-with-prompt', '--background', '--backoff-delay', '--backoff-jitter', '--backoff-type', '--batch', '--batch-size', '--bound-max-concurrent', '--bound-slug-prefixes', '--bound-source', '--bound-tools', '--brain', '--break-lock', '--budget-usd', '--budget-usd-per-day', '--by-mention', '--by-type', '--cached', '--catch-up', '--check', '--cli-path', '--cluster', '--cluster-errors', '--code', '--concurrency', '--confidence', '--confirm-destructive', '--content', '--date', '--days', '--delay', '--detach', '--diff-filter', '--dim', '--dimensions', '--dir', '--drain', '--dry-run', '--embedding-dimensions', '--embedding-model', '--empty', '--entities', '--exclude', '--exclude-standard', '--explain', '--fast', '--federated', '--federated-read', '--ff-only', '--file', '--fix', '--follow', '--force', '--force-break-lock', '--force-retry', '--format', '--fresh', '--from-meetings', '--from-pages', '--full', '--hard-deadline', '--health-interval', '--held-out', '--help', '--http', '--idempotency-key', '--image', '--include-frontmatter', '--include-gitignored', '--include-null-signature', '--infer-dates', '--inject-bootstrap', '--inline', '--input', '--install', '--interval', '--is-ancestor', '--job-id', '--job-isolation', '--json', '--kind', '--lang', '--limit', '--lock', '--markdown', '--max-age', '--max-attempts', '--max-cost-usd', '--max-crashes', '--max-rss', '--max-runtime-min', '--max-sources', '--max-stalled', '--max-usd', '--max-waiting', '--mcp-only', '--migrate-only', '--min-context', '--missing-path', '--mode', '--model', '--multimodal', '--name-only', '--name-status', '--near-symbol', '--ner', '--nice', '--no', '--no-auto-embed', '--no-embed', '--no-embedding', '--no-extract', '--no-federate', '--no-federated', '--no-gpg-sign', '--no-hard-deadline', '--no-inject', '--no-mutate', '--no-pull', '--no-renames', '--no-schema-pack', '--no-verify', '--no-worker', '--non-interactive', '--now', '--offset', '--older-than', '--once', '--order', '--orphan', '--others', '--output', '--override-disabled', '--pace', '--pace-max-concurrency', '--pack', '--parallel', '--params', '--path', '--pattern', '--pending', '--phase', '--pid-file', '--priority', '--progress-interval', '--progress-json', '--queue', '--quiet', '--redact-secrets', '--reenrich-after', '--refresh-cache', '--refresh-ms', '--remediate', '--remediation-plan', '--repo', '--reset', '--resolve', '--respect-gitignore', '--restore-only', '--resume', '--retry-failed', '--review-lower', '--run-id', '--save', '--segment-limit', '--serial', '--session', '--session-id', '--short', '--show-toplevel', '--sigkill-rescue', '--since', '--skip-bare-tweet', '--skip-failed', '--skip-urls', '--sleep', '--slug', '--slugs', '--source', '--source-id', '--src-subpath', '--stale', '--stats', '--status', '--strategy', '--supersessions', '--surface', '--swap-only', '--symbol-kind', '--target', '--target-score', '--thin', '--thin-threshold', '--timeout', '--timeout-ms', '--to', '--token-ttl', '--trusted-extraction', '--type', '--types', '--uninstall', '--unsafe-bypass-dream-guard', '--url', '--user', '--verbose', '--verify', '--version', '--watch', '--wedge-rescue', '--with-db', '--workers', '--yes'],
'jobs': ['--abbrev-ref', '--aliases', '--all', '--allow-empty', '--allow-protected', '--allow-shell-jobs', '--apply', '--asof', '--auto', '--auto-fix', '--auto-with-prompt', '--background', '--backoff-delay', '--backoff-jitter', '--backoff-type', '--batch', '--batch-size', '--bound-max-concurrent', '--bound-slug-prefixes', '--bound-source', '--bound-tools', '--brain', '--break-lock', '--budget-usd', '--budget-usd-per-day', '--by-mention', '--by-type', '--cached', '--catch-up', '--check', '--cli-path', '--cluster', '--cluster-errors', '--code', '--concurrency', '--confidence', '--confirm-destructive', '--content', '--date', '--days', '--delay', '--detach', '--diff-filter', '--dim', '--dimensions', '--dir', '--drain', '--dry-run', '--embedding-dimensions', '--embedding-model', '--empty', '--entities', '--exclude', '--exclude-standard', '--explain', '--fast', '--federated', '--federated-read', '--ff-only', '--file', '--fix', '--follow', '--force', '--force-break-lock', '--force-retry', '--format', '--fresh', '--from-meetings', '--from-pages', '--full', '--hard-deadline', '--health-interval', '--held-out', '--help', '--http', '--idempotency-key', '--image', '--include-frontmatter', '--include-gitignored', '--include-null-signature', '--infer-dates', '--inject-bootstrap', '--inline', '--input', '--install', '--interval', '--is-ancestor', '--job-id', '--job-isolation', '--json', '--kind', '--lang', '--limit', '--lock', '--lock-duration-ms', '--markdown', '--max-age', '--max-attempts', '--max-cost-usd', '--max-crashes', '--max-rss', '--max-runtime-min', '--max-sources', '--max-stalled', '--max-usd', '--max-waiting', '--mcp-only', '--migrate-only', '--min-context', '--missing-path', '--mode', '--model', '--multimodal', '--name-only', '--name-status', '--near-symbol', '--ner', '--nice', '--no', '--no-auto-embed', '--no-embed', '--no-embedding', '--no-extract', '--no-federate', '--no-federated', '--no-gpg-sign', '--no-hard-deadline', '--no-inject', '--no-mutate', '--no-pull', '--no-renames', '--no-schema-pack', '--no-verify', '--no-worker', '--non-interactive', '--now', '--offset', '--older-than', '--once', '--order', '--orphan', '--others', '--output', '--override-disabled', '--pace', '--pace-max-concurrency', '--pack', '--parallel', '--params', '--path', '--pattern', '--pending', '--phase', '--pid-file', '--priority', '--progress-interval', '--progress-json', '--queue', '--quiet', '--redact-secrets', '--reenrich-after', '--refresh-cache', '--refresh-ms', '--remediate', '--remediation-plan', '--repo', '--reset', '--resolve', '--respect-gitignore', '--restore-only', '--resume', '--retry-failed', '--review-lower', '--run-id', '--save', '--segment-limit', '--serial', '--session', '--session-id', '--short', '--show-toplevel', '--sigkill-rescue', '--since', '--skip-bare-tweet', '--skip-failed', '--skip-urls', '--sleep', '--slug', '--slugs', '--source', '--source-id', '--src-subpath', '--stale', '--stats', '--status', '--strategy', '--supersessions', '--surface', '--swap-only', '--symbol-kind', '--target', '--target-score', '--thin', '--thin-threshold', '--timeout', '--timeout-ms', '--to', '--token-ttl', '--trusted-extraction', '--type', '--types', '--uninstall', '--unsafe-bypass-dream-guard', '--url', '--user', '--verbose', '--verify', '--version', '--watch', '--wedge-rescue', '--with-db', '--workers', '--yes'],
'lint': ['--aliases', '--all', '--background', '--brain', '--brain-wide-max-cost-usd', '--dry-run', '--exclude', '--explain', '--fast', '--fix', '--follow', '--force', '--from-pages', '--help', '--http', '--include-null-signature', '--json', '--no-embedding', '--no-extract', '--pattern', '--pending', '--progress-interval', '--progress-json', '--quiet', '--remediate', '--reset', '--resolve', '--source', '--stale', '--supersessions', '--surface', '--thin', '--timeout', '--token-ttl'],
'lsd': ['--brain', '--force-resume', '--help', '--json', '--judge-model', '--limit', '--list-runs', '--max-cost', '--max-far-set', '--max-ideas-per-judge-call', '--no-save', '--resume', '--retry-judge', '--save', '--source', '--strict-budget', '--yes'],
'maintain': ['--aliases', '--all', '--background', '--brain', '--break-lock', '--by-mention', '--catch-up', '--column', '--concurrency', '--content-audit', '--count', '--detach', '--dim', '--dir', '--drain', '--dry-run', '--embedding-dimensions', '--embedding-model', '--explain', '--fast', '--fix', '--force', '--force-retry', '--force-schema', '--from-meetings', '--full', '--help', '--include-flagged', '--include-frontmatter', '--include-null-signature', '--index-audit', '--infer-dates', '--input', '--json', '--kind', '--lang', '--locks', '--markdown', '--max-cost', '--max-cost-usd', '--max-jobs', '--max-rss', '--max-usd', '--migrate-only', '--multimodal', '--near-symbol', '--ner', '--nice', '--no-extract', '--no-mutate', '--older-than', '--once', '--pack', '--parallel', '--params', '--path', '--pattern', '--pending', '--pglite', '--phase', '--pid-file', '--porcelain', '--probe-pglite', '--progress-json', '--query', '--queue', '--quiet', '--rebuild-rollup', '--regenerate', '--remediate', '--remediation-plan', '--reset', '--resolve', '--restore-only', '--resume', '--run-id', '--safe', '--scope', '--since', '--skills-dir', '--skip-failed', '--slugs', '--source', '--source-id', '--stale', '--status', '--supabase', '--supersessions', '--symbol-kind', '--target', '--target-score', '--thin', '--to', '--top-k', '--type', '--unsafe-bypass-dream-guard', '--url', '--verbose', '--window', '--workers', '--yes'],
+24
View File
@@ -5829,6 +5829,30 @@ export const MIGRATIONS: Migration[] = [
ALTER TABLE dream_verdicts ADD COLUMN IF NOT EXISTS triage_version INT;
`,
},
{
version: 130,
name: 'minion_jobs_lock_duration_ms',
// #4145: per-job lock lease. A single worker-global 30s lockDuration
// cannot serve both 2s shell jobs and 173s-average LLM subagent jobs —
// under host CPU saturation the renewal window was missed and healthy
// long-running handlers were force-evicted. The column carries an
// optional per-job lease; NULL means "worker default" (the pre-#4145
// behavior), so NO backfill is needed — the claim-time COALESCE against
// HANDLER_DEFAULT_LOCK_DURATION_MS (handler-timeouts.ts) owns all
// defaulting from here on. CHECK added via the idempotent drop-then-add
// pattern (v7 precedent) so migrated brains carry the same DB bound as
// fresh installs; the operative [5s,1h] range clamp lives app-side in
// clampLockDurationMs. No index: only per-row reads on already-indexed
// access paths (bootstrap-coverage: column-only, no probe needed).
// (Authored as v129; renumbered to v130 when #4152's
// dream_verdicts_triage_v1_columns landed the number first.)
idempotent: true,
sql: `
ALTER TABLE minion_jobs ADD COLUMN IF NOT EXISTS lock_duration_ms INTEGER;
ALTER TABLE minion_jobs DROP CONSTRAINT IF EXISTS chk_lock_duration_positive;
ALTER TABLE minion_jobs ADD CONSTRAINT chk_lock_duration_positive CHECK (lock_duration_ms IS NULL OR (lock_duration_ms >= 5000 AND lock_duration_ms <= 3600000));
`,
},
];
export const LATEST_VERSION = MIGRATIONS.length > 0
+75 -20
View File
@@ -1,28 +1,44 @@
/**
* handler-timeouts.ts — per-handler default wall-clock budgets (#1737).
* handler-timeouts.ts — per-handler-type defaults for the TWO time knobs a
* Minion job carries: the wall-clock budget (`timeout_ms`, #1737) and the
* lock lease (`lock_duration_ms`, #4145). They are DIFFERENT quantities —
* the budget bounds total runtime (subagent: 30min), the lease bounds how
* long a dead worker's claim survives before the stall sweep reclaims it
* (subagent: 300s) — and deriving one from the other would couple two
* unrelated tunables behind an implicit ratio policy. Both maps live here,
* under one header, precisely so they can't drift apart unseen.
*
* Short jobs (shell, lint, backlinks) want the tight default wall-clock
* (`2 * lockDuration * max_stalled`, computed in `handleWallClockTimeouts`
* when `timeout_ms IS NULL`). Long jobs do not: a 30-min LLM loop or a
* 10-15 min embed backfill submitted WITHOUT an explicit `timeout_ms` would
* inherit that short null-default and get wall-clock-killed mid-progress
* one half of #1737's thrash.
* WALL-CLOCK BUDGETS: short jobs (shell, lint, backlinks) want the tight
* default wall-clock (`2 * lock * max_stalled`, computed in
* `handleWallClockTimeouts` when `timeout_ms IS NULL`). Long jobs do not: a
* 30-min LLM loop submitted WITHOUT an explicit `timeout_ms` would inherit
* that short null-default and get wall-clock-killed mid-progress.
*
* Three layers apply the default (an explicit `opts.timeout_ms` always wins):
* LOCK LEASES: the worker-global default lease is 30s — right for 2s shell
* jobs (fast dead-worker reclaim), structurally wrong for 173s-average LLM
* jobs, which had to renew ~12 consecutive times per run; under host CPU
* saturation a missed window force-evicted healthy handlers (the #4145
* incident). Long handlers get a 300s lease (5 renewal chances at the
* clamped 60s cadence); `shell` deliberately stays NULL → worker default
* (child processes don't starve the loop, and verify-before-evict protects
* them anyway). Trade: dead-worker reclaim for mapped types slows to
* ≤ lease + reclaim grace + sweep cadence.
*
* Both defaults apply through the same layers (an explicit opts value
* always wins):
*
* 1. SUBMIT — `MinionQueue.add` stamps the default onto the row. The value
* lives in `minion_jobs.timeout_ms`, not worker memory, so wall-clock
* behavior is stable across worker restart.
* 2. CLAIM — `MinionQueue.claim` COALESCEs a NULL `timeout_ms` from this
* map (and derives `timeout_at` from the coalesced value). This is the
* durable invariant: it covers rows inserted before layer 1 existed and
* any writer that bypasses add(). Persisted by the claim UPDATE, so the
* restart-stability property holds here too.
* 3. ONE-SHOT — migration v128 backfilled `timeout_ms` for non-terminal
* rows that predate both layers (they would otherwise never re-claim
* or die at the short null-default first). v128's values are a
* deliberate authoring-time SNAPSHOT of this map — do NOT sync v128
* when editing the map below; layer 2 owns all future drift.
* lives on minion_jobs, not worker memory, so behavior is stable
* across worker restart.
* 2. CLAIM — `MinionQueue.claim` COALESCEs a NULL column from the map
* (and derives `timeout_at` / `lock_until` from the coalesced value).
* This is the durable invariant: it covers rows inserted before
* layer 1 existed and any writer that bypasses add().
* 3. ONE-SHOT — migration v128 backfilled `timeout_ms` for pre-#1737
* rows. v128's values are a deliberate authoring-time SNAPSHOT — do
* NOT sync v128 when editing the maps; layer 2 owns all future drift.
* (`lock_duration_ms` needs no backfill: NULL simply means "worker
* default", which is the pre-#4145 behavior.)
*
* The 30-min anchor matches the explicit value cycle/patterns.ts already
* passes for subagent jobs, so this generalizes an existing convention
@@ -67,3 +83,42 @@ export const HANDLER_DEFAULT_TIMEOUT_MS: Readonly<Record<string, number>> = {
export function defaultTimeoutMsFor(jobName: string): number | null {
return HANDLER_DEFAULT_TIMEOUT_MS[jobName] ?? null;
}
const FIVE_MIN_MS = 5 * 60 * 1000;
const TWO_MIN_MS = 2 * 60 * 1000;
/**
* Default lock lease (ms) for long-running handler types (#4145). A handler
* not in this map returns `null` → the worker-global `lockDuration` default
* (30s) applies — see the header for why `shell` is deliberately absent.
* 300s = the issue's proposed lease for 173s-average LLM jobs (5 renewal
* chances at the 60s clamped cadence); 120s covers the single-LLM-call
* handlers whose p99 comfortably exceeds a 30s lease.
*/
export const HANDLER_DEFAULT_LOCK_DURATION_MS: Readonly<Record<string, number>> = {
subagent: FIVE_MIN_MS,
subagent_aggregator: FIVE_MIN_MS,
'embed-backfill': FIVE_MIN_MS,
'autopilot-cycle': FIVE_MIN_MS,
'autopilot-global-maintenance': FIVE_MIN_MS,
contextual_reindex_per_chunk: FIVE_MIN_MS,
chronicle_extract: TWO_MIN_MS,
'facts-absorb': TWO_MIN_MS,
};
export function defaultLockDurationMsFor(jobName: string): number | null {
return HANDLER_DEFAULT_LOCK_DURATION_MS[jobName] ?? null;
}
/** Clamp bounds for explicit per-job lease input — [5s, 1h]. The floor
* kills the 1ms-lock foot-gun (instant stall-reclaim thrash); the ceiling
* kills the immortal-lock foot-gun (a crashed worker's claim surviving an
* hour). Shared by queue.add, the CLI flag, and the MCP op (ENG-E4) so
* three hand-copied bounds can't drift. The DB CHECK only enforces > 0;
* this clamp is the operative bound (precedent: max_stalled [1,100]). */
export const LOCK_DURATION_MS_MIN = 5_000;
export const LOCK_DURATION_MS_MAX = 3_600_000;
export function clampLockDurationMs(raw: number): number {
return Math.max(LOCK_DURATION_MS_MIN, Math.min(LOCK_DURATION_MS_MAX, Math.floor(raw)));
}
+429 -76
View File
@@ -18,14 +18,25 @@
* `Promise.race(call, timeoutPromise)` with `callTimeoutMs` so the
* call cannot pend longer than the configured budget.
*
* - **Threshold math**: with `lockDuration=30s` and `interval=15s`,
* a 3-strike count-based abort fires at t=45s but the lock has
* been reclaimable since t=30s — a 15s window where another
* worker can claim the same job. `runLockRenewalTick` aborts based
* on `Date.now() - lastSuccessfulRenewalAt >= lockDuration -
* safetyMargin` (time-based), so the worker voluntarily releases
* BEFORE the stall detector can reclaim. The failure counter is
* kept for audit-event labeling only.
* - **Verify-before-evict (#4145, replaces the v0.41.22.2 abort-at-
* deadline doctrine)**: a thrown/timed-out renewal is NOT evidence of
* loss — under event-loop starvation the UPDATE may even have landed
* server-side while the local race timeout won. When the NEXT tick
* would land past the soft deadline (`lockDuration - safetyMargin`,
* cadence-aware per CDX-4), the tick runs ONE bounded VERIFY renewal:
* fenced-true → starved-but-ours, lease re-extended, keep working;
* fenced-false → CERTAIN loss, abort (stall detector requeues, no
* attempt burned); verify unreachable → defer and retry next tick,
* aborting only past the `hardEvictMs` backstop (a LOCAL decision
* under uncertainty that bounds blind external side effects during a
* total outage). The local clock only schedules WHEN to verify —
* the DB fence decides WHETHER to evict; production binds `deps.now`
* to a monotonic source so wall-clock jumps can't distort the math.
* Accepted timing behavior (ENG-E1): at the 30s default a failed
* renewal (≤10s) + verify (≤10s) can span 20s > the 15s cadence, so
* tickInFlight skips one tick — benign (a verify-success re-extends
* the lease and resets the baseline); do not "fix" it into an
* overlap. The failure counter is kept for audit-event labeling only.
*
* - **Cancelled-tick race**: if the job ends while a renewLock call
* is mid-flight, the IIFE in worker.ts must bail without writing
@@ -47,6 +58,43 @@
* below; tests + workers both consume it.
*/
/**
* Named error for the per-call timeout race so cause classification is
* name-based (`call-timeout` vs `refused`), never message-sniffing
* (issue #4145 request 3).
*/
export class RenewalCallTimeoutError extends Error {
constructor(what: string, ms: number) {
super(`${what} timed out after ${ms}ms`);
this.name = 'RenewalCallTimeoutError';
}
}
/**
* Why a renewal attempt failed, as far as the tick can tell:
* - `call-timeout` — our own race timer fired (starved loop, slow pool,
* or slow DB — the tick can't distinguish; lateness
* + load telemetry does).
* - `refused` — the driver threw (SQLSTATE rides in the audit event).
* - `fenced-lost` — the fenced UPDATE matched 0 rows: CERTAIN loss.
*/
export type RenewalFailureCause = 'call-timeout' | 'refused' | 'fenced-lost';
/**
* Optional telemetry threaded to the audit sink alongside each event.
* All fields additive — the 4-outcome audit contract is unchanged and
* pre-upgrade JSONL lines parse fine without them.
*/
export interface LockRenewalTelemetryCtx {
cause?: RenewalFailureCause;
lateness_ms?: number;
overlap_skips?: number;
load1?: number;
cores?: number;
via?: 'renewal' | 'verify';
deadline_deferred?: boolean;
}
export interface LockRenewalKnobs {
/**
* Failure counter cap used ONLY for audit-event labeling.
@@ -56,17 +104,36 @@ export interface LockRenewalKnobs {
maxFailuresForAudit: number;
/**
* Per-renewLock-call timeout enforced via `Promise.race`.
* Env: `GBRAIN_LOCK_RENEWAL_CALL_TIMEOUT_MS`. Default: `lockDuration / 3`.
* Env: `GBRAIN_LOCK_RENEWAL_CALL_TIMEOUT_MS`. Default: `min(lockDuration / 3, 15s)`
* (the cap keeps a long per-job lease from inheriting a call budget that
* wedges tickInFlight across cadence windows).
* Bounds the "hung renewLock wedges the re-entrancy guard forever" vector.
*/
callTimeoutMs: number;
/**
* Time-based abort fires when `now - lastSuccessfulRenewalAt >=
* lockDuration - safetyMarginMs`. Default safety margin gives ~5s
* of headroom before another worker could reclaim the lock.
* Env: `GBRAIN_LOCK_RENEWAL_SAFETY_MARGIN_MS`. Default: `lockDuration / 6`.
* The soft deadline is `lockDuration - safetyMarginMs`: once the NEXT
* tick would land past it, the tick runs the at-deadline VERIFY renewal
* (fenced re-check) instead of retrying blindly. The margin is the
* headroom the verify has to complete before the lease actually lapses.
* Env: `GBRAIN_LOCK_RENEWAL_SAFETY_MARGIN_MS`. Default: `min(lockDuration / 6, 30s)`.
*/
safetyMarginMs: number;
/**
* The hard local backstop (#4145): when even the VERIFY renewal is
* unreachable (throws/times out) for this long since the last success,
* abort anyway. This is an uncertainty BOUND, not a certainty claim —
* fenced-false is the only CERTAIN loss signal; the hard evict merely
* caps how long a handler with non-fenced EXTERNAL side effects may run
* blind during a total DB outage. APPROXIMATE by design: checked after
* a primary call + verify (overshoot up to ~2×callTimeoutMs + timer
* lateness), and eviction stays cooperative (an abort-ignoring handler
* outlives it — the kill/reap follow-up TODO is the true bound).
* Setting this to the soft deadline approximates the legacy
* abort-at-deadline behavior (the verify still runs once).
* Env: `GBRAIN_LOCK_RENEWAL_HARD_EVICT_MS`. Default: `2 × lockDuration`,
* floored to the soft deadline (warn-once on floor).
*/
hardEvictMs: number;
}
/**
@@ -90,15 +157,36 @@ export function _resetKnobWarningsForTests(): void {
* operator who sets `GBRAIN_LOCK_RENEWAL_CALL_TIMEOUT_MS=abc` gets a
* loud-but-not-fatal nudge AND a working worker.
*/
/**
* The renewal cadence cap: a long lease renews every 60s (multiple chances
* per window, matching the cycle refresher's philosophy) instead of the
* bare lease/2. Leases ≤120s keep the legacy /2 exactly. ONE home for the
* formula — the worker's timer and resolveLockRenewalKnobs' default both
* derive from it, so the relational validation always runs against the
* cadence production actually uses.
*/
export const RENEWAL_INTERVAL_CAP_MS = 60_000;
export function renewalIntervalFor(lockDurationMs: number): number {
return Math.max(1, Math.min(Math.floor(lockDurationMs / 2), RENEWAL_INTERVAL_CAP_MS));
}
export function resolveLockRenewalKnobs(
env: Record<string, string | undefined>,
lockDurationMs: number,
intervalMs: number = renewalIntervalFor(lockDurationMs),
): LockRenewalKnobs {
const defaultMaxFailures = 3;
const defaultCallTimeout = Math.max(1, Math.floor(lockDurationMs / 3));
const defaultSafetyMargin = Math.max(1, Math.floor(lockDurationMs / 6));
// #4145: the derived defaults CAP at 15s/30s so a long per-job lease
// (300s) doesn't inherit a 100s call timeout (which would wedge
// tickInFlight across cadence windows) or a 50s margin. The 30s worker
// default keeps today's 10s/5s exactly. Env overrides are still applied
// first and then pass the relational validation below.
const defaultCallTimeout = Math.min(Math.max(1, Math.floor(lockDurationMs / 3)), 15_000);
const defaultSafetyMargin = Math.min(Math.max(1, Math.floor(lockDurationMs / 6)), 30_000);
const defaultHardEvict = lockDurationMs * 2;
return {
const knobs: LockRenewalKnobs = {
maxFailuresForAudit: parsePositiveInt(
env.GBRAIN_LOCK_RENEWAL_MAX_FAILURES,
defaultMaxFailures,
@@ -114,7 +202,54 @@ export function resolveLockRenewalKnobs(
defaultSafetyMargin,
'GBRAIN_LOCK_RENEWAL_SAFETY_MARGIN_MS',
),
hardEvictMs: parsePositiveInt(
env.GBRAIN_LOCK_RENEWAL_HARD_EVICT_MS,
defaultHardEvict,
'GBRAIN_LOCK_RENEWAL_HARD_EVICT_MS',
),
};
// [CDX-10] Relational validation: positive-integer parsing alone lets a
// margin exceed the lease or a call timeout exceed the cadence, which
// silently re-breaks the deadline math. Clamp the offending knob (to a
// relationally-valid derivation) and warn once per process per knob.
// Runs per job launch against the EFFECTIVE per-job lease.
if (knobs.safetyMarginMs >= lockDurationMs / 2) {
warnRelationalClamp(
'GBRAIN_LOCK_RENEWAL_SAFETY_MARGIN_MS',
`safetyMarginMs (${knobs.safetyMarginMs}) must be < lockDuration/2 (${lockDurationMs / 2})`,
defaultSafetyMargin,
);
knobs.safetyMarginMs = defaultSafetyMargin;
}
if (knobs.callTimeoutMs > intervalMs) {
warnRelationalClamp(
'GBRAIN_LOCK_RENEWAL_CALL_TIMEOUT_MS',
`callTimeoutMs (${knobs.callTimeoutMs}) must be <= the renewal cadence (${intervalMs}) or a slow call wedges tickInFlight across intervals`,
intervalMs,
);
knobs.callTimeoutMs = intervalMs;
}
const softDeadline = lockDurationMs - knobs.safetyMarginMs;
if (knobs.hardEvictMs < softDeadline) {
warnRelationalClamp(
'GBRAIN_LOCK_RENEWAL_HARD_EVICT_MS',
`hardEvictMs (${knobs.hardEvictMs}) must be >= the soft deadline (${softDeadline})`,
softDeadline,
);
knobs.hardEvictMs = softDeadline;
}
return knobs;
}
function warnRelationalClamp(name: string, violation: string, clampedTo: number): void {
const key = `relational:${name}`;
if (!_warnedKnobs.has(key)) {
_warnedKnobs.add(key);
process.stderr.write(
`[lock-renewal] ${violation}; clamping to ${clampedTo}\n`,
);
}
}
function parsePositiveInt(raw: string | undefined, fallback: number, name: string): number {
@@ -148,11 +283,15 @@ function warnAndFallback(name: string, raw: string, fallback: number): number {
*/
export interface LockRenewalDeps {
/**
* The optional `opts.signal` is aborted when this call loses the tick's
* timeout race, so the underlying UPDATE is CANCELLED (postgres.js
* `.cancel()` via executeRawDirect) instead of orphaned on a checked-out
* pool slot for its full server-side duration — the #6 starvation class.
* Optional-param widening keeps the legacy 3-arg test mocks compiling.
* The fenced renewal UPDATE. The optional `opts.signal` is aborted when
* this call loses the tick's timeout race (both attempts: primary AND the
* #4145 at-deadline verify), so the underlying UPDATE is CANCELLED
* (postgres.js `.cancel()` via executeRawDirect) instead of orphaned on a
* checked-out pool slot for its full server-side duration — the #6
* starvation class. Cancellation is BEST-EFFORT (pool acquisition and PG
* protocol cancel are async; PGLite ignores the signal); the token FENCE
* is the correctness authority. Optional-param widening keeps the legacy
* 3-arg test mocks compiling.
*/
renewLock: (
jobId: number,
@@ -166,8 +305,9 @@ export interface LockRenewalDeps {
/**
* Injectable for hermetic Promise.race tests. Production:
* `globalThis.setTimeout`. The function must return a value that
* `clearTimeout` accepts, but this seam doesn't expose clearTimeout
* because the timeout race fires-and-forgets. The losing renewLock is no
* `clearTimeout` accepts: on the win path the race clears the losing
* timer (via global clearTimeout) so it doesn't later fire a stray
* no-op abort against a settled query. The losing renewLock is no
* longer merely abandoned: the timeout callback also aborts the per-call
* signal so the query releases its pool slot.
*/
@@ -190,6 +330,21 @@ export interface LockRenewalDeps {
* (optional-param) signature stays back-compatible with no-arg test mocks.
*/
reconnect?: (ctx?: { error?: unknown }) => Promise<void>;
/**
* OPTIONAL host-load probe for eviction telemetry (issue #4145 req 3).
* The worker binds `os.loadavg()[0]` + a cached core count. Every call
* is wrapped in try/catch here (CEO-F2) — a throwing telemetry hook
* must never re-open the unhandledRejection class this module exists
* to close; on throw the event simply logs without load fields.
*/
loadSnapshot?: () => { load1: number; cores: number };
/**
* OPTIONAL success hook. The worker resets its event-loop-delay
* histogram here (R2-9) so an eviction-time sample attributes to the
* window since the LAST SUCCESSFUL renewal, not process lifetime.
* Best-effort: called inside try/catch.
*/
onRenewalSuccess?: () => void;
}
/**
@@ -198,9 +353,11 @@ export interface LockRenewalDeps {
* import the full audit module and inflate the test surface.
*/
export interface LockRenewalAuditSinkLike {
logFailure(jobId: number, jobName: string, attempt: number, err: unknown): void;
logSuccessAfterFailure(jobId: number, jobName: string, recoveredAfterAttempts: number): void;
logGaveUp(jobId: number, jobName: string, totalFailures: number, err: unknown): void;
// The trailing `ctx` is optional and additive (ENG-E2): pre-existing
// test fakes with the old arity stay structurally assignable.
logFailure(jobId: number, jobName: string, attempt: number, err: unknown, ctx?: LockRenewalTelemetryCtx): void;
logSuccessAfterFailure(jobId: number, jobName: string, recoveredAfterAttempts: number, ctx?: LockRenewalTelemetryCtx): void;
logGaveUp(jobId: number, jobName: string, totalFailures: number, err: unknown, ctx?: LockRenewalTelemetryCtx): void;
}
export interface LockRenewalState {
@@ -221,13 +378,45 @@ export interface LockRenewalState {
* cancellation event AND the post-await branch decisions.
*/
cancelled: () => boolean;
/**
* The renewal timer's cadence (ms) — the SAME value the worker gave
* setInterval. Used for tick-lateness telemetry (below) and the
* cadence-aware verify trigger.
*/
intervalMs: number;
/**
* Timestamp of the previous tick's entry, on the SAME clock as
* `deps.now` (production binds a monotonic source; R2-4). Seeded to
* launch time. Lateness = max(0, now - lastTickFiredAt - intervalMs)
* is the PRIMARY local-starvation signal: interval callbacks COALESCE
* under a blocked event loop (one late callback, not N), so a
* missed-tick counter cannot measure starvation — lateness can.
*/
lastTickFiredAt: number;
/**
* Count of interval callbacks skipped by the worker's tickInFlight
* re-entrancy guard. These are OVERLAP skips (a prior tick still in
* flight), NOT missed intervals — see lastTickFiredAt. Incremented by
* the worker's interval closure; read here for telemetry.
*/
overlapSkips: number;
}
export type TickResult =
| { kind: 'ok' }
| { kind: 'cancelled' }
| { kind: 'lock_lost' }
| { kind: 'should_abort'; reason: 'lock-renewal-failed' };
| { kind: 'lock_lost'; cause: 'fenced-lost'; via: 'renewal' | 'verify' }
| {
kind: 'should_abort';
reason: 'lock-renewal-failed';
/** What the FINAL failed attempt looked like (R2-7 telemetry). */
cause: RenewalFailureCause;
latenessMs: number;
sinceLastSuccessMs: number;
overlapSkips: number;
load1?: number;
cores?: number;
};
/**
* Execute one renewal tick. Returns a tagged result the worker switches
@@ -238,69 +427,145 @@ export async function runLockRenewalTick(
deps: LockRenewalDeps,
state: LockRenewalState,
): Promise<TickResult> {
// Tick-lateness telemetry (CDX-13): how late did this callback fire vs
// its own cadence? Computed FIRST — even a cancelled tick advances the
// baseline so the next measurement stays honest.
const tickEnteredAt = deps.now();
const latenessMs = Math.max(0, tickEnteredAt - state.lastTickFiredAt - state.intervalMs);
state.lastTickFiredAt = tickEnteredAt;
if (state.cancelled()) return { kind: 'cancelled' };
let renewed: boolean;
// Per-call cancellation: when the timeout wins the race, abort the signal
// so the losing UPDATE releases its pool slot instead of holding it until
// the server finishes (issue #6 — an abandoned racer under a saturated
// pooler pinned a checked-out connection for minutes). On the win path the
// late-firing timer aborts an already-settled query, which runUnsafe
// ignores (abort listener removed in its .finally).
const callAbort = new AbortController();
try {
renewed = await Promise.race([
deps.renewLock(state.jobId, state.lockToken, state.lockDurationMs, { signal: callAbort.signal }),
new Promise<never>((_, reject) => {
deps.setTimeout(() => {
callAbort.abort();
reject(new Error(`renewLock timed out after ${state.knobs.callTimeoutMs}ms`));
}, state.knobs.callTimeoutMs);
}),
]);
renewed = await racedRenewLock(deps, state);
} catch (err) {
if (state.cancelled()) return { kind: 'cancelled' };
state.consecutiveFailures += 1;
const cause = classifyFailure(err);
const load = safeLoadSnapshot(deps);
const telemetry: LockRenewalTelemetryCtx = {
cause,
lateness_ms: latenessMs,
overlap_skips: state.overlapSkips,
...load,
};
// Defense-in-depth (codex C4): audit must never escape this catch.
try {
deps.audit.logFailure(state.jobId, state.jobName, state.consecutiveFailures, err);
deps.audit.logFailure(state.jobId, state.jobName, state.consecutiveFailures, err, telemetry);
} catch { /* audit best-effort */ }
const sinceLastSuccess = deps.now() - state.lastSuccessfulRenewalAt;
const deadline = state.lockDurationMs - state.knobs.safetyMarginMs;
if (sinceLastSuccess >= deadline) {
try {
deps.audit.logGaveUp(state.jobId, state.jobName, state.consecutiveFailures, err);
} catch { /* audit best-effort */ }
return { kind: 'should_abort', reason: 'lock-renewal-failed' };
}
// issue #1678 (Codex #2): not yet at the deadline, so we'll retry on the
// next tick. If the engine can rebuild its pool, do it ONCE now (bounded
// by callTimeoutMs) so the next renewLock sees a live connection instead
// of throwing the same reaped-socket error until the deadline. Best-effort:
// a reconnect throw/timeout is swallowed (next tick retries) and must NEVER
// escape this catch — that would re-introduce the unhandledRejection class
// this module was built to close.
if (deps.reconnect) {
const reconnect = deps.reconnect;
try {
await Promise.race([
// Thread the triggering renewLock error (CODEX impl review #2) so the
// engine can classify a CONNECTION_ENDED pooler reap as `reap_detected`.
reconnect({ error: err }),
new Promise<never>((_, reject) => {
deps.setTimeout(
() => reject(new Error(`reconnect timed out after ${state.knobs.callTimeoutMs}ms`)),
state.knobs.callTimeoutMs,
);
}),
]);
} catch { /* reconnect best-effort; next tick retries against a fresh attempt */ }
// [CDX-4] Cadence-aware trigger: run the at-deadline VERIFY when the
// NEXT tick would land past the soft deadline — `>= deadline` alone is
// unreachable under cadence quantization (a 300s lease with a 60s
// cadence has no tick between 240s and expiry; the first eligible tick
// would already be past the lease).
if (sinceLastSuccess + state.intervalMs < deadline) {
// Not near the deadline: retry on the next tick.
// issue #1678 (Codex #2): if the engine can rebuild its pool, do it
// ONCE now (bounded) so the next renewLock sees a live connection.
await attemptReconnectOnce(deps, state, err);
if (state.cancelled()) return { kind: 'cancelled' };
return { kind: 'ok' }; // counter incremented; not yet at deadline
}
return { kind: 'ok' }; // counter incremented; not yet at deadline
// ── At the deadline: VERIFY before evicting (#4145) ──────────────────
// The throw above is NOT evidence of loss (db-lock.ts doctrine:
// fenced-false = certain, throw = transient). Under event-loop
// starvation the renewal may even have LANDED server-side while our
// local race timeout won. renewLock is fenced on lock_token and does
// NOT check lock_until, so an expired-but-unstolen lease renews fine —
// ask the DB the authoritative question.
//
// Reconciling with queue.ts's "renewLock is deliberately not
// retry-wrapped" rationale (two-holders risk): that comment forbids
// BACKGROUND retries that outlive this tick's own timeout race. This
// verify is a synchronous, cancelled()-guarded, callTimeoutMs-bounded
// call INSIDE the tick's flow, and both UPDATEs are same-token
// idempotent lease extensions — a fenced row cannot gain two holders.
let verified: boolean | null = null; // null = the verify itself threw
let verifyErr: unknown = null;
try {
verified = await racedRenewLock(deps, state);
} catch (vErr) {
verifyErr = vErr;
}
if (state.cancelled()) return { kind: 'cancelled' };
if (verified === true) {
// Starved-but-ours: the lease is re-extended; the incident-saving path.
try {
deps.audit.logSuccessAfterFailure(
state.jobId, state.jobName, state.consecutiveFailures, { via: 'verify' },
);
} catch { /* audit best-effort */ }
state.consecutiveFailures = 0;
state.lastSuccessfulRenewalAt = deps.now();
try { deps.onRenewalSuccess?.(); } catch { /* telemetry best-effort */ }
return { kind: 'ok' };
}
if (verified === false) {
// Fenced miss: CERTAIN loss (stall sweep reclaimed / pauseJob).
return { kind: 'lock_lost', cause: 'fenced-lost', via: 'verify' };
}
// The verify was unreachable too — that is a second failed attempt.
// NOTE for audit readers: at the deadline `attempt` advances by 2 per
// tick (primary + verify) — the counter counts ATTEMPTS, not ticks.
state.consecutiveFailures += 1;
const verifyCause = classifyFailure(verifyErr);
// Re-sample load: the bounded verify can consume up to callTimeoutMs,
// and the verify-failure event should carry the load at ITS failure,
// not a snapshot stale by the verify's whole duration.
const verifyLoad = safeLoadSnapshot(deps);
const verifyTelemetry: LockRenewalTelemetryCtx = {
cause: verifyCause,
lateness_ms: latenessMs,
overlap_skips: state.overlapSkips,
...verifyLoad,
};
// Recompute elapsed AFTER the verify: the bounded verify itself can
// consume up to callTimeoutMs, and comparing the stale pre-verify value
// would defer one extra cadence past the advertised backstop.
const sinceLastSuccessAfterVerify = deps.now() - state.lastSuccessfulRenewalAt;
if (sinceLastSuccessAfterVerify >= state.knobs.hardEvictMs) {
// Hard backstop: a LOCAL decision under uncertainty, by design —
// bounds how long non-fenced external side effects run blind during
// a total outage. DB writes stay split-brain-safe via the fence.
try {
deps.audit.logGaveUp(
state.jobId, state.jobName, state.consecutiveFailures, verifyErr ?? err, verifyTelemetry,
);
} catch { /* audit best-effort */ }
return {
kind: 'should_abort',
reason: 'lock-renewal-failed',
cause: verifyCause,
latenessMs,
sinceLastSuccessMs: sinceLastSuccessAfterVerify,
overlapSkips: state.overlapSkips,
...verifyLoad,
};
}
// Deferred past the soft deadline: keep the job and retry next tick —
// the fence is the correctness backstop (a reclaim surfaces as a
// fenced-false on the next attempt; no attempt is burned). CEO-F3:
// give the next tick a live pool.
try {
deps.audit.logFailure(
state.jobId, state.jobName, state.consecutiveFailures, verifyErr ?? err,
{ ...verifyTelemetry, deadline_deferred: true },
);
} catch { /* audit best-effort */ }
await attemptReconnectOnce(deps, state, verifyErr ?? err);
if (state.cancelled()) return { kind: 'cancelled' };
return { kind: 'ok' };
}
if (state.cancelled()) return { kind: 'cancelled' };
@@ -308,8 +573,9 @@ export async function runLockRenewalTick(
// Token-fence failure: another worker reclaimed the row, or pauseJob
// cleared the token. NOT an infrastructure fault — no audit event
// (audit channel is for infrastructure faults only). The worker
// observes `lock_lost` and stderr-warns + aborts.
return { kind: 'lock_lost' };
// observes `lock_lost` and stderr-warns + aborts. This is the ONLY
// CERTAIN loss signal (exactly 0 rows matched the fence).
return { kind: 'lock_lost', cause: 'fenced-lost', via: 'renewal' };
}
if (state.consecutiveFailures > 0) {
@@ -318,10 +584,97 @@ export async function runLockRenewalTick(
state.jobId,
state.jobName,
state.consecutiveFailures,
{ via: 'renewal' },
);
} catch { /* audit best-effort */ }
state.consecutiveFailures = 0;
}
state.lastSuccessfulRenewalAt = deps.now();
// R2-9: let the worker reset its event-loop-delay histogram so the next
// eviction-time sample attributes to the window since THIS success.
try { deps.onRenewalSuccess?.(); } catch { /* telemetry best-effort */ }
return { kind: 'ok' };
}
/**
* CEO-F2: telemetry must never throw into the tick's control flow — a
* throwing loadavg probe re-opening the unhandledRejection class would
* be a bitter irony. On throw, the event logs without load fields.
*/
function safeLoadSnapshot(deps: LockRenewalDeps): { load1?: number; cores?: number } {
try {
const s = deps.loadSnapshot?.();
return s ? { load1: s.load1, cores: s.cores } : {};
} catch {
return {};
}
}
/**
* One bounded renewal attempt: renewLock raced against callTimeoutMs.
* When the timeout wins the race it also ABORTS the per-call signal so the
* losing UPDATE releases its pool slot instead of holding it until the
* server finishes (issue #6 — an abandoned racer under a saturated pooler
* pinned a checked-out connection for minutes). On the win path the
* late-firing timer aborts an already-settled query, which runUnsafe
* ignores (abort listener removed in its .finally). Cancellation is
* BEST-EFFORT (CDX-2/R2-2 — the fence is the correctness authority; PGLite
* ignores the signal and resolves via the race alone). The race attaches
* handlers to both contenders, so a late loser settlement is absorbed,
* never an unhandledRejection.
*/
function racedRenewLock(deps: LockRenewalDeps, state: LockRenewalState): Promise<boolean> {
const controller = new AbortController();
let timer: unknown;
return Promise.race([
deps.renewLock(state.jobId, state.lockToken, state.lockDurationMs, { signal: controller.signal }),
new Promise<never>((_, reject) => {
timer = deps.setTimeout(() => {
try { controller.abort(); } catch { /* best-effort */ }
reject(new RenewalCallTimeoutError('renewLock', state.knobs.callTimeoutMs));
}, state.knobs.callTimeoutMs);
}),
]).finally(() => {
// Win-path hygiene: clear the losing timer so it can't fire a stray
// late abort at a settled query (absorbed by runUnsafe, but noisy).
// Test fakes may return null from the seam; clearTimeout(null) is a
// harmless no-op.
try { clearTimeout(timer as ReturnType<typeof setTimeout>); } catch { /* best-effort */ }
}) as Promise<boolean>;
}
function classifyFailure(err: unknown): RenewalFailureCause {
return err instanceof Error && err.name === 'RenewalCallTimeoutError' ? 'call-timeout' : 'refused';
}
/**
* issue #1678 (Codex #2): bounded, best-effort, ONCE-per-tick pool rebuild
* so the NEXT renewal attempt sees a live connection instead of throwing
* the same reaped-socket error. Threads the triggering error so the engine
* can classify a CONNECTION_ENDED pooler reap as `reap_detected`. A
* reconnect throw/timeout is swallowed — it must NEVER escape into the
* tick's catch (the unhandledRejection class this module exists to close).
*/
async function attemptReconnectOnce(
deps: LockRenewalDeps,
state: LockRenewalState,
err: unknown,
): Promise<void> {
if (!deps.reconnect) return;
const reconnect = deps.reconnect;
let timer: unknown;
try {
await Promise.race([
reconnect({ error: err }),
new Promise<never>((_, reject) => {
timer = deps.setTimeout(
() => reject(new Error(`reconnect timed out after ${state.knobs.callTimeoutMs}ms`)),
state.knobs.callTimeoutMs,
);
}),
]);
} catch { /* reconnect best-effort; next tick retries against a fresh attempt */
} finally {
try { clearTimeout(timer as ReturnType<typeof setTimeout>); } catch { /* best-effort */ }
}
}
+111 -14
View File
@@ -16,7 +16,10 @@ import type {
import { rowToMinionJob, rowToInboxMessage, rowToAttachment } from './types.ts';
import { validateAttachment } from './attachments.ts';
import { isProtectedJobName } from './protected-names.ts';
import { defaultTimeoutMsFor, HANDLER_DEFAULT_TIMEOUT_MS } from './handler-timeouts.ts';
import {
defaultTimeoutMsFor, HANDLER_DEFAULT_TIMEOUT_MS,
defaultLockDurationMsFor, HANDLER_DEFAULT_LOCK_DURATION_MS, clampLockDurationMs,
} from './handler-timeouts.ts';
import {
withRetry, BULK_RETRY_OPTS, resolveBulkRetryOpts, computeNextDelay,
isRetryableConnError,
@@ -38,6 +41,62 @@ export interface TrustedSubmitOpts {
const MIGRATION_VERSION = 7;
const DEFAULT_MAX_SPAWN_DEPTH = 5;
/**
* Stall-sweep reclaim grace (#4145, CDX-7): don't reclaim a row whose
* `lock_until` lapsed within the last N ms. When a CPU-starved worker's
* event loop unblocks, its coalesced renewal tick and the stall sweep
* fire in the same burst if the sweep's UPDATE lands first it steals
* the OWNER'S live job. The grace is a HEAD-START for the owner's
* recovery renewal, not a guarantee: it only covers starvation bursts
* shorter than the grace, and a healthy second worker's sweep still
* wins beyond it. Minion analog of `GBRAIN_LOCK_STEAL_GRACE_SECONDS`
* (db-lock.ts), adapted because minion_jobs has no last_refreshed_at.
*
* Cost: dead-worker recovery becomes lock_until + grace + up to
* stalledInterval. Env `GBRAIN_MINION_STALL_RECLAIM_GRACE_MS` (0 allowed
* restores the exact legacy reclaim predicate).
*/
export const DEFAULT_STALL_RECLAIM_GRACE_MS = 15_000;
const _warnedGraceEnv = new Set<string>();
export function _resetStallGraceWarningsForTests(): void {
_warnedGraceEnv.clear();
}
export function resolveStallReclaimGraceMs(
env: Record<string, string | undefined> = process.env,
): number {
const raw = env.GBRAIN_MINION_STALL_RECLAIM_GRACE_MS;
if (raw === undefined || raw.trim() === '') return DEFAULT_STALL_RECLAIM_GRACE_MS;
// Unlike the lock-renewal knobs, 0 is a VALID value here (legacy reclaim).
if (!/^\d+$/.test(raw.trim())) {
if (!_warnedGraceEnv.has(raw)) {
_warnedGraceEnv.add(raw);
process.stderr.write(
`[minions] env GBRAIN_MINION_STALL_RECLAIM_GRACE_MS=${JSON.stringify(raw)} is not a non-negative integer; ` +
`falling back to default ${DEFAULT_STALL_RECLAIM_GRACE_MS}\n`,
);
}
return DEFAULT_STALL_RECLAIM_GRACE_MS;
}
const n = Number(raw.trim());
// Cap at 10 minutes: an absurd digit string (Number → huge/Infinity)
// would otherwise push the sweep cutoff to -infinity and silently
// disable stalled-job recovery altogether.
const MAX_GRACE_MS = 600_000;
if (n > MAX_GRACE_MS) {
if (!_warnedGraceEnv.has(raw)) {
_warnedGraceEnv.add(raw);
process.stderr.write(
`[minions] env GBRAIN_MINION_STALL_RECLAIM_GRACE_MS=${JSON.stringify(raw)} exceeds the ${MAX_GRACE_MS}ms cap; clamping\n`,
);
}
return MAX_GRACE_MS;
}
return n;
}
const DEFAULT_MAX_ATTACHMENT_BYTES = 5 * 1024 * 1024; // 5 MiB
const TERMINAL_STATUSES = ['completed', 'failed', 'dead', 'cancelled'] as const;
@@ -354,11 +413,11 @@ export class MinionQueue {
const baseCols = `name, queue, status, priority, data, max_attempts, backoff_type,
backoff_delay, backoff_jitter, delay_until, parent_job_id, on_child_fail,
depth, max_children, timeout_ms, remove_on_complete, remove_on_fail, idempotency_key,
depth, max_children, timeout_ms, lock_duration_ms, remove_on_complete, remove_on_fail, idempotency_key,
quiet_hours, stagger_key`;
const baseVals = `$1, $2, $3, $4, $5::jsonb, $6, $7, $8, $9, $10, $11, $12, $13, $14, $15, $16, $17, $18, $19::jsonb, $20`;
const baseVals = `$1, $2, $3, $4, $5::jsonb, $6, $7, $8, $9, $10, $11, $12, $13, $14, $15, $16, $17, $18, $19, $20::jsonb, $21`;
const cols = hasMaxStalled ? `${baseCols}, max_stalled` : baseCols;
const vals = hasMaxStalled ? `${baseVals}, $21` : baseVals;
const vals = hasMaxStalled ? `${baseVals}, $22` : baseVals;
const insertSql = opts?.idempotency_key
? `INSERT INTO minion_jobs (${cols})
@@ -388,6 +447,14 @@ export class MinionQueue {
// sane long wall-clock default stamped at submit when the caller didn't
// pass one, so they aren't killed mid-progress by the short null-default.
opts?.timeout_ms ?? defaultTimeoutMsFor(jobName),
// #4145: same three-layer pattern for the lock lease. Explicit input
// is clamped to [5s,1h]; absent → handler map default; NULL row =
// worker-global lockDuration at claim. INSERT-only (see the
// max_stalled footgun note above): an idempotency-key re-submit
// never mutates the first submitter's lease.
opts?.lock_duration_ms != null
? clampLockDurationMs(opts.lock_duration_ms)
: defaultLockDurationMsFor(jobName),
opts?.remove_on_complete ?? false,
opts?.remove_on_fail ?? false,
opts?.idempotency_key ?? null,
@@ -772,11 +839,26 @@ export class MinionQueue {
// Direct (session-mode) pool: claim opens the lock that renewLock then
// heartbeats. Both must live on a connection the transaction-mode pooler
// won't recycle mid-hold, or the lock orphans and the worker wedges.
//
// #4145: lock_duration_ms resolves row → handler map ($6, RAW object —
// same double-encode rule as $5) → worker default ($2), is STAMPED onto
// the row (durable, like timeout_ms), and lock_until derives from the
// same COALESCE (OLD-row semantics: repeat the expression, don't
// reference the assigned column). Both the stamp and lock_until are
// CASE-clamped to the [5s,1h] bound IN SQL (row/map resolution only —
// the worker-default fallback $2 is operator-configured, not row data,
// and tests/short-lived workers legitimately use sub-5s leases): the exposed
// submit surfaces clamp already, but a bypass-written row (direct SQL
// repair, foreign tooling) must not grant a ~24-day lease to a worker
// that crashes before its first renewal (or a 1ms one that thrashes).
const rows = await this.engine.executeRawDirect<Record<string, unknown>>(
`UPDATE minion_jobs SET
status = 'active',
lock_token = $1,
lock_until = now() + ($2::double precision * interval '1 millisecond'),
lock_until = now() + ((CASE WHEN COALESCE(lock_duration_ms, ($6::jsonb ->> name)::int) IS NULL THEN $2
ELSE LEAST(GREATEST(COALESCE(lock_duration_ms, ($6::jsonb ->> name)::int), 5000), 3600000) END)::double precision * interval '1 millisecond'),
lock_duration_ms = CASE WHEN COALESCE(lock_duration_ms, ($6::jsonb ->> name)::int) IS NULL THEN NULL
ELSE LEAST(GREATEST(COALESCE(lock_duration_ms, ($6::jsonb ->> name)::int), 5000), 3600000) END,
timeout_ms = COALESCE(timeout_ms, ($5::jsonb ->> name)::int),
timeout_at = CASE WHEN COALESCE(timeout_ms, ($5::jsonb ->> name)::int) IS NOT NULL
THEN now() + (COALESCE(timeout_ms, ($5::jsonb ->> name)::int)::double precision * interval '1 millisecond')
@@ -792,7 +874,7 @@ export class MinionQueue {
LIMIT 1
)
RETURNING *`,
[lockToken, lockDurationMs, queue, registeredNames, HANDLER_DEFAULT_TIMEOUT_MS]
[lockToken, lockDurationMs, queue, registeredNames, HANDLER_DEFAULT_TIMEOUT_MS, HANDLER_DEFAULT_LOCK_DURATION_MS]
);
return rows.length > 0 ? rowToMinionJob(rows[0]) : null;
}
@@ -959,7 +1041,7 @@ export class MinionQueue {
AND EXTRACT(EPOCH FROM (now() - started_at)) * 1000 >
CASE
WHEN timeout_ms IS NOT NULL THEN timeout_ms * 2
ELSE $1::double precision * 2 * GREATEST(max_stalled, 1)
ELSE COALESCE(lock_duration_ms, $1)::double precision * 2 * GREATEST(max_stalled, 1)
END`,
[lockDurationMs]
);
@@ -982,7 +1064,7 @@ export class MinionQueue {
AND EXTRACT(EPOCH FROM (now() - started_at)) * 1000 >
CASE
WHEN timeout_ms IS NOT NULL THEN timeout_ms * 2
ELSE $1::double precision * 2 * GREATEST(max_stalled, 1)
ELSE COALESCE(lock_duration_ms, $1)::double precision * 2 * GREATEST(max_stalled, 1)
END
FOR UPDATE SKIP LOCKED
)
@@ -1297,9 +1379,15 @@ export class MinionQueue {
/**
* Renew lock (token-fenced). Returns false if token mismatch (job was reclaimed).
*
* `opts.signal` cancels the in-flight UPDATE (postgres.js `.cancel()`) when the
* caller's timeout race gives up on it otherwise the abandoned query holds a
* checked-out pool slot for its full server-side duration (issue #6).
* Cancellation is BEST-EFFORT (#4145 CDX-2/R2-2): pool acquisition and PG
* protocol cancel are asynchronous, and PGLite ignores the signal so
* correctness never rests on it. A late-landing renewal UPDATE is fenced on
* OUR token, meaning it can only extend a lock nobody else has claimed;
* worst case is a stall-requeue delayed by one lease.
*/
async renewLock(
id: number,
@@ -1370,18 +1458,25 @@ export class MinionQueue {
}
/** Detect and handle stalled jobs. Single CTE, no off-by-one. Returns affected jobs. */
async handleStalled(): Promise<{ requeued: MinionJob[]; dead: MinionJob[] }> {
async handleStalled(graceMsOverride?: number): Promise<{ requeued: MinionJob[]; dead: MinionJob[] }> {
// W0 fix-wave (Tier-1 #4): the dead-letter branch previously emitted NO
// child_done and never unblocked aggregator parents — a child that died
// via max-stall stranded its parent in 'waiting-children' forever (the
// exact hang the v0.15 comment says was fixed for timeouts; there was no
// compensating sweep anywhere). Restructured into the parents-first
// discover/lock/kill shape (D5.12) with the shared killJobs() tail.
//
// #4145 (CDX-7): the reclaim predicate carries a grace — see
// resolveStallReclaimGraceMs. Callers (tests) may pass an explicit
// override; the worker sweep resolves from env/default.
const graceMs = graceMsOverride ?? resolveStallReclaimGraceMs();
return this.engine.transaction(async (tx) => {
const candidates = await tx.executeRaw<{ id: number; parent_job_id: number | null; stalled_counter: number; max_stalled: number }>(
`SELECT id, parent_job_id, stalled_counter, max_stalled
FROM minion_jobs
WHERE status = 'active' AND lock_until < now()`
WHERE status = 'active'
AND lock_until < now() - ($1::double precision * interval '1 millisecond')`,
[graceMs]
);
if (candidates.length === 0) return { requeued: [], dead: [] };
const ids = candidates.map(c => c.id);
@@ -1399,12 +1494,13 @@ export class MinionQueue {
WHERE id IN (
SELECT id FROM minion_jobs
WHERE id = ANY($1::bigint[])
AND status = 'active' AND lock_until < now()
AND status = 'active'
AND lock_until < now() - ($2::double precision * interval '1 millisecond')
AND stalled_counter + 1 < max_stalled
FOR UPDATE SKIP LOCKED
)
RETURNING *`,
[ids]
[ids, graceMs]
);
const deadRows = await tx.executeRaw<Record<string, unknown>>(
`UPDATE minion_jobs SET
@@ -1415,12 +1511,13 @@ export class MinionQueue {
WHERE id IN (
SELECT id FROM minion_jobs
WHERE id = ANY($1::bigint[])
AND status = 'active' AND lock_until < now()
AND status = 'active'
AND lock_until < now() - ($2::double precision * interval '1 millisecond')
AND stalled_counter + 1 >= max_stalled
FOR UPDATE SKIP LOCKED
)
RETURNING *`,
[ids]
[ids, graceMs]
);
// THE FIX: stall-death now notifies + unblocks parents like every
// other terminal kill. Outcome 'dead' (not 'timeout') so consumers can
+5
View File
@@ -71,6 +71,8 @@ export interface MinionJob {
max_children: number | null;
timeout_ms: number | null;
timeout_at: Date | null;
/** Per-job lock lease (ms, #4145). NULL = worker-global lockDuration default. */
lock_duration_ms: number | null;
remove_on_complete: boolean;
remove_on_fail: boolean;
idempotency_key: string | null;
@@ -128,6 +130,8 @@ export interface MinionJobInput {
max_children?: number;
/** Wall-clock per-job deadline in ms. Set on claim → timeout_at. Terminal on expire (no retry). */
timeout_ms?: number;
/** Per-job lock lease in ms (#4145). Clamped to [5s,1h]; NULL/undefined → handler map, then worker default. INSERT-only: an idempotency-key re-submit never mutates the first submitter's lease. */
lock_duration_ms?: number;
/** DELETE row on successful completion (after token rollup + child_done insert). */
remove_on_complete?: boolean;
/** DELETE row on terminal failure (after parent failure hook). */
@@ -435,6 +439,7 @@ export function rowToMinionJob(row: Record<string, unknown>): MinionJob {
depth: (row.depth as number) ?? 0,
max_children: (row.max_children as number) ?? null,
timeout_ms: (row.timeout_ms as number) ?? null,
lock_duration_ms: (row.lock_duration_ms as number) ?? null,
timeout_at: row.timeout_at ? new Date(row.timeout_at as string) : null,
remove_on_complete: row.remove_on_complete === true,
remove_on_fail: row.remove_on_fail === true,
+164 -16
View File
@@ -30,9 +30,12 @@ import { logLeasePressure } from './lease-pressure-audit.ts';
import {
runLockRenewalTick,
resolveLockRenewalKnobs,
renewalIntervalFor,
type LockRenewalDeps,
type LockRenewalState,
type TickResult,
} from './lock-renewal-tick.ts';
import { clampLockDurationMs } from './handler-timeouts.ts';
import {
runDbProbe,
getConnectionRouting,
@@ -48,6 +51,8 @@ import {
ChildNotClaimedError,
} from './child-job-runner.ts';
import { lockRenewalAudit } from '../audit/lock-renewal-audit.ts';
import { loadavg, cpus } from 'os';
import { monitorEventLoopDelay } from 'perf_hooks';
import { isRetryableConnError } from '../retry-matcher.ts';
import { reconnectAfterConnectionError as reconnectEngineAfterConnError } from './reconnect.ts';
@@ -230,6 +235,23 @@ export class MinionWorker extends EventEmitter {
private opts: Required<MinionWorkerOpts>;
/**
* Event-loop-delay histogram (CDX-1/R2-9, issue #4145): the DIRECT
* measurement of local starvation, sampled at eviction time and RESET
* on every successful lock renewal so a sample attributes to the
* window since the last success not process lifetime. The histogram
* is deliberately WORKER-global, not per-job: the event loop is one
* shared resource, and ANY job's successful renewal proves the loop was
* healthy enough to process a round-trip at that moment a legitimate
* truncation of the starvation window even for a sibling job that
* evicts moments later (its per-job discriminator is tick lateness,
* which IS per-job). Null when the runtime doesn't ship
* `monitorEventLoopDelay` (fail-open: eviction logs omit eld fields).
*/
private eldHistogram: ReturnType<typeof monitorEventLoopDelay> | null = null;
/** Core count cached once — pairs with raw loadavg in eviction telemetry. */
private readonly cpuCores: number;
constructor(
private engine: BrainEngine,
opts?: MinionWorkerOpts & MinionQueueOpts,
@@ -239,6 +261,17 @@ export class MinionWorker extends EventEmitter {
maxSpawnDepth: opts?.maxSpawnDepth,
maxAttachmentBytes: opts?.maxAttachmentBytes,
});
let cores = 0;
try { cores = cpus().length; } catch { /* telemetry best-effort */ }
this.cpuCores = cores;
try {
if (typeof monitorEventLoopDelay === 'function') {
// Created DISABLED: start() enables and stop() disables, so a
// constructed-but-never-started worker (setup failures, probe
// instances) never holds a native sampling timer.
this.eldHistogram = monitorEventLoopDelay({ resolution: 20 });
}
} catch { this.eldHistogram = null; /* fail-open */ }
this.opts = {
queue: opts?.queue ?? 'default',
concurrency: opts?.concurrency ?? 1,
@@ -346,6 +379,10 @@ export class MinionWorker extends EventEmitter {
await this.queue.ensureSchema();
this.running = true;
// R2-9 lifecycle: (re-)enable the event-loop-delay histogram for this
// run; stop() disables it so embedding hosts / test suites that cycle
// start()/stop() don't leak a ~50Hz native sampling timer per instance.
try { this.eldHistogram?.enable(); } catch { /* fail-open */ }
// Graceful shutdown. Fires shutdownAbort so handlers subscribed to
// `ctx.shutdownSignal` (currently: shell handler) can run their own cleanup
@@ -805,6 +842,7 @@ export class MinionWorker extends EventEmitter {
/** Stop the worker gracefully. */
stop(): void {
this.running = false;
try { this.eldHistogram?.disable(); } catch { /* fail-open */ }
}
/**
@@ -923,6 +961,40 @@ export class MinionWorker extends EventEmitter {
* `failJob` throwing during the same DB outage) can't propagate to
* the process-level handler and crash the daemon.
*/
/**
* One formatter for the classified abort telemetry (R2-7) so the
* should_abort warn and the 30s-later grace-evict line can never drift
* apart (they briefly did: `load1:` vs `load1_at_abort:`).
*/
private formatAbortMeta(meta: Extract<TickResult, { kind: 'lock_lost' | 'should_abort' }>): string {
if (meta.kind === 'lock_lost') {
return `cause: ${meta.cause}, via: ${meta.via}`;
}
return `cause: ${meta.cause}, since_last_success_ms: ${Math.round(meta.sinceLastSuccessMs)}, ` +
`tick_lateness_ms: ${Math.round(meta.latenessMs)}, overlap_skips: ${meta.overlapSkips}` +
`${meta.load1 !== undefined ? `, load1: ${meta.load1.toFixed(2)}/${meta.cores} cores` : ''}`;
}
/**
* Event-loop-delay sample for eviction log lines (CDX-1). The histogram
* resets on every successful renewal (R2-9 via deps.onRenewalSuccess),
* so these numbers attribute to the window since the last success
* i.e. exactly the window in which renewal was failing. nsms. Empty
* string when the runtime lacks the histogram or sampling throws
* (fail-open: never let telemetry break the eviction path).
*/
private formatEvictionTelemetry(): string {
const h = this.eldHistogram;
if (h === null) return '';
try {
const p99Ms = Math.round(h.percentile(99) / 1e6);
const maxMs = Math.round(h.max / 1e6);
return ` [event_loop_delay since last renewal: p99 ${p99Ms}ms, max ${maxMs}ms]`;
} catch {
return '';
}
}
private launchJob(job: MinionJob, lockToken: string): void {
const abort = new AbortController();
@@ -930,18 +1002,46 @@ export class MinionWorker extends EventEmitter {
let cancelled = false;
// --- re-entrancy guard for overlapping ticks during PgBouncer stalls ---
let tickInFlight = false;
// --- R2-7: the tick's final result, stashed at abort time so the ---
// --- grace-evict log (which fires 30s LATER) can report cause/ ---
// --- lateness/load instead of just the Error string. ---
let abortMeta: Extract<TickResult, { kind: 'lock_lost' | 'should_abort' }> | null = null;
// R2-4: ALL elapsed-time arithmetic in the renewal state machine runs
// on a monotonic clock — a wall-clock jump (NTP step, DST bug) must
// never evict or indefinitely defer. Date.now stays only in log/audit
// timestamps (the audit writer stamps its own `ts`).
const monotonicNow = () => performance.now();
// --- D3: pure-function lock renewal ---
const knobs = resolveLockRenewalKnobs(process.env, this.opts.lockDuration);
// #4145: the EFFECTIVE lease is per-job (claim stamped it from the
// handler map / explicit submit; NULL = worker default). The cadence
// clamps to 60s so a 300s lease renews 5x per window (matching the
// cycle refresher's multiple-chances philosophy) instead of the bare
// lease/2 = every 150s; leases ≤120s keep the legacy /2 exactly.
// Defense-in-depth: re-clamp the row value at consumption. The exposed
// submit surfaces already clamp, but the claim COALESCE trusts the row
// and the DB CHECK only enforces > 0 — a writer that bypasses add()
// (direct SQL repair, foreign tooling) could otherwise stamp a 1ms
// lease (renewal-storm setInterval) or a ~25-day one (weeks-long
// dead-worker pin).
const effectiveLockMs = job.lock_duration_ms != null
? clampLockDurationMs(job.lock_duration_ms)
: this.opts.lockDuration;
const renewalIntervalMs = renewalIntervalFor(effectiveLockMs);
const knobs = resolveLockRenewalKnobs(process.env, effectiveLockMs, renewalIntervalMs);
const renewalState: LockRenewalState = {
jobId: job.id,
jobName: job.name,
lockToken,
lockDurationMs: this.opts.lockDuration,
lockDurationMs: effectiveLockMs,
knobs,
lastSuccessfulRenewalAt: Date.now(),
lastSuccessfulRenewalAt: monotonicNow(),
consecutiveFailures: 0,
cancelled: () => cancelled,
intervalMs: renewalIntervalMs,
lastTickFiredAt: monotonicNow(),
overlapSkips: 0,
};
// issue #1678 (Codex #2): hand the tick a bounded reconnect-once hook when
// the engine owns a pool that a transaction-mode pooler can reap. Postgres
@@ -951,15 +1051,30 @@ export class MinionWorker extends EventEmitter {
const renewalDeps: LockRenewalDeps = {
renewLock: (id, tok, dur, opts) => this.queue.renewLock(id, tok, dur, opts),
audit: lockRenewalAudit,
now: Date.now,
// R2-4: monotonic — see monotonicNow above.
now: monotonicNow,
setTimeout: (cb, ms) => globalThis.setTimeout(cb, ms),
// Forward the tick's classified error (CODEX impl review #2) so a pooler
// reap during lock renewal is audited as reap_detected, not reconnect_other.
...(engineReconnect ? { reconnect: (ctx?: { error?: unknown }) => engineReconnect.call(this.engine, ctx) } : {}),
// Issue #4145 telemetry: raw loadavg + cached cores (CEO-F2: the tick
// try/catches every call), and the R2-9 histogram reset-on-success.
loadSnapshot: () => ({ load1: loadavg()[0], cores: this.cpuCores }),
onRenewalSuccess: () => { try { this.eldHistogram?.reset(); } catch { /* fail-open */ } },
};
const lockTimer = setInterval(() => {
if (tickInFlight) return;
if (tickInFlight) {
// Overlap skip (CDX-13): a prior tick is still awaiting its
// renewal call. Count it — this is NOT a missed interval (those
// coalesce and show up as tick LATENESS instead) — and ADVANCE the
// lateness baseline: this callback fired on schedule, so the next
// executed tick must not book the skipped window as event-loop
// lateness (that would misclassify a slow DB call as starvation).
renewalState.overlapSkips += 1;
renewalState.lastTickFiredAt = monotonicNow();
return;
}
tickInFlight = true;
void runLockRenewalTick(renewalDeps, renewalState)
.then((result) => {
@@ -970,13 +1085,24 @@ export class MinionWorker extends EventEmitter {
return;
case 'lock_lost':
if (!abort.signal.aborted) {
console.warn(`Lock lost for job ${job.id}, aborting execution`);
abortMeta = result;
console.warn(
`Lock lost for job ${job.id}, aborting execution ` +
`(${this.formatAbortMeta(result)}${this.formatEvictionTelemetry()})`,
);
clearInterval(lockTimer);
abort.abort(new Error('lock-lost'));
}
return;
case 'should_abort':
if (!abort.signal.aborted) {
abortMeta = result;
// Issue #4145 request 3: the one line that saves the 8h of
// forensics — WHY renewal failed + was the loop starved.
console.warn(
`Lock renewal failed for job ${job.id} (${job.name}); aborting ` +
`(${this.formatAbortMeta(result)}${this.formatEvictionTelemetry()})`,
);
clearInterval(lockTimer);
abort.abort(new Error(result.reason));
}
@@ -996,7 +1122,7 @@ export class MinionWorker extends EventEmitter {
.finally(() => {
tickInFlight = false;
});
}, this.opts.lockDuration / 2);
}, renewalIntervalMs);
// --- D8b: universal grace-eviction timer ---
// Fires for ANY abort reason (not just job.timeout_ms). Without
@@ -1012,18 +1138,35 @@ export class MinionWorker extends EventEmitter {
const reason = abort.signal.reason instanceof Error
? abort.signal.reason.message
: String(abort.signal.reason);
// R2-7: abortMeta carries the tick's classified cause + starvation
// telemetry captured AT abort time — the Error string alone would
// make this line read like an orphan leak (the #4145 forensics trap).
const meta = abortMeta === null ? '' : ` (${this.formatAbortMeta(abortMeta)})`;
console.warn(
`Job ${job.id} (${job.name}) did not exit within 30s of abort (reason: ${reason}). ` +
`Job ${job.id} (${job.name}) did not exit within 30s of abort (reason: ${reason}).${meta} ` +
`Force-evicting from inFlight to unblock worker. ` +
`The handler is still running but the worker will claim new jobs.`
`The handler is still running but the worker will claim new jobs.` +
this.formatEvictionTelemetry()
);
clearInterval(lockTimer);
this.inFlight.delete(job.id);
// D8a: don't failJob on infrastructure aborts (stall detector
// reclaims after lock expiry). Isolation mode: also skip — the
// group SIGKILL already fired and executeJob's own recording
// follows; a competing evict failJob('dead') could dead-letter a
// job with attempts remaining (adversarial-review P3).
// R2-1 generation-safety: delete ONLY our own execution's entry.
// After a force-evict, this job id can be requeued and re-claimed
// by THIS worker while the old handler is still alive — an
// unconditional delete-by-id would then remove the NEW
// execution's entry (concurrency undercount, lost tracking).
// The lockToken is minted per claim, so it is the generation.
if (this.inFlight.get(job.id)?.lockToken === lockToken) {
this.inFlight.delete(job.id);
}
// D8a: don't failJob if the abort was infrastructure. The stall
// detector will reclaim the row cleanly: a lock-renewal abort
// now fires only after the at-deadline VERIFY either returned
// fenced-false (row already reclaimed) or stayed unreachable
// past hardEvictMs (lease long expired) — see #4145
// verify-before-evict in lock-renewal-tick.ts. Isolation mode:
// also skip — the group SIGKILL already fired and executeJob's
// own recording follows; a competing evict failJob('dead') could
// dead-letter a job with attempts remaining (adversarial-review P3).
if (!INFRASTRUCTURE_ABORT_REASONS.has(reason) && this.opts.jobIsolation !== 'process') {
this.queue.failJob(
job.id,
@@ -1066,7 +1209,12 @@ export class MinionWorker extends EventEmitter {
clearInterval(lockTimer);
if (timeoutTimer) clearTimeout(timeoutTimer);
if (graceTimer) clearTimeout(graceTimer);
this.inFlight.delete(job.id);
// R2-1 generation-safety: a force-evicted execution's finally can
// fire long after the same job id was re-claimed by this worker.
// Only delete the entry if it is still OURS (token = generation).
if (this.inFlight.get(job.id)?.lockToken === lockToken) {
this.inFlight.delete(job.id);
}
this.jobsCompleted += 1;
this.checkMemoryLimit('post-job');
})
+5
View File
@@ -3588,6 +3588,7 @@ const submit_job: Operation = {
max_attempts: { type: 'number', description: 'Max retry attempts (default: 3)' },
delay: { type: 'number', description: 'Delay in ms before eligible' },
timeout_ms: { type: 'number', description: 'Per-job wall-clock timeout in ms; aborted job goes to dead' },
lock_duration_ms: { type: 'number', description: 'Per-job lock lease in ms (#4145). Out-of-range values are clamped to [5000, 3600000] — remote writers cannot pin an immortal lock. Omit to use the handler-type default (300s for long LLM handlers) or the worker default (30s).' },
},
mutating: true,
scope: 'admin',
@@ -3635,6 +3636,10 @@ const submit_job: Operation = {
max_attempts: (p.max_attempts as number) || 3,
delay: (p.delay as number) || undefined,
timeout_ms: (p.timeout_ms as number) || undefined,
// #4145 [CEO-F7/R2-6]: range enforcement lives in queue.add's
// clampLockDurationMs (ParamDef has no min/max support; wrong TYPE is
// rejected by the shared number validation upstream of this handler).
lock_duration_ms: (p.lock_duration_ms as number) || undefined,
}, trusted);
// v0.35.8.0: submit_job audit-log parity with the CLI path (codex F-CDX-4).
+7 -1
View File
@@ -3913,8 +3913,14 @@ export class PGLiteEngine implements BrainEngine {
COUNT(DISTINCT n.last_link_type) AS edge_count,
array_agg(DISTINCT n.last_link_type)
FILTER (WHERE n.last_link_type IS NOT NULL) AS via_link_types,
-- Final path tie-break (lexicographic) makes the pick deterministic
-- when a node is reachable at the same depth from multiple seeds;
-- without it the winner is plan/heap-order dependent and the two
-- engines (or two runs) can disagree. Relational retrieval is
-- documented deterministic; keep in lockstep with postgres-engine.ts.
(array_agg(array_to_string(n.path, chr(9))
ORDER BY n.depth ASC, array_length(n.path, 1) ASC))[1] AS path_str,
ORDER BY n.depth ASC, array_length(n.path, 1) ASC,
array_to_string(n.path, chr(9)) ASC))[1] AS path_str,
(SELECT cc.id FROM content_chunks cc
WHERE cc.page_id = n.id ORDER BY cc.chunk_index ASC LIMIT 1) AS canonical_chunk_id
FROM walk n
+3 -1
View File
@@ -462,6 +462,7 @@ CREATE TABLE IF NOT EXISTS minion_jobs (
depth INTEGER NOT NULL DEFAULT 0,
max_children INTEGER,
timeout_ms INTEGER,
lock_duration_ms INTEGER,
timeout_at TIMESTAMPTZ,
remove_on_complete BOOLEAN NOT NULL DEFAULT FALSE,
remove_on_fail BOOLEAN NOT NULL DEFAULT FALSE,
@@ -482,7 +483,8 @@ CREATE TABLE IF NOT EXISTS minion_jobs (
CONSTRAINT chk_nonnegative CHECK (attempts_made >= 0 AND attempts_started >= 0 AND stalled_counter >= 0 AND max_attempts >= 1 AND max_stalled >= 0),
CONSTRAINT chk_depth_nonnegative CHECK (depth >= 0),
CONSTRAINT chk_max_children_positive CHECK (max_children IS NULL OR max_children > 0),
CONSTRAINT chk_timeout_positive CHECK (timeout_ms IS NULL OR timeout_ms > 0)
CONSTRAINT chk_timeout_positive CHECK (timeout_ms IS NULL OR timeout_ms > 0),
CONSTRAINT chk_lock_duration_positive CHECK (lock_duration_ms IS NULL OR (lock_duration_ms >= 5000 AND lock_duration_ms <= 3600000))
);
CREATE INDEX IF NOT EXISTS idx_minion_jobs_claim ON minion_jobs (queue, priority ASC, created_at ASC) WHERE status = 'waiting';
+23 -11
View File
@@ -3785,8 +3785,14 @@ export class PostgresEngine implements BrainEngine {
COUNT(DISTINCT n.last_link_type) AS edge_count,
array_agg(DISTINCT n.last_link_type)
FILTER (WHERE n.last_link_type IS NOT NULL) AS via_link_types,
-- Final path tie-break (lexicographic) makes the pick deterministic
-- when a node is reachable at the same depth from multiple seeds;
-- without it the winner is plan/heap-order dependent and the two
-- engines (or two runs) can disagree. Relational retrieval is
-- documented deterministic; keep in lockstep with pglite-engine.ts.
(array_agg(array_to_string(n.path, chr(9))
ORDER BY n.depth ASC, array_length(n.path, 1) ASC))[1] AS path_str,
ORDER BY n.depth ASC, array_length(n.path, 1) ASC,
array_to_string(n.path, chr(9)) ASC))[1] AS path_str,
(SELECT cc.id FROM content_chunks cc
WHERE cc.page_id = n.id ORDER BY cc.chunk_index ASC LIMIT 1) AS canonical_chunk_id
FROM walk n
@@ -6242,18 +6248,17 @@ export class PostgresEngine implements BrainEngine {
params?: unknown[],
opts?: { signal?: AbortSignal },
): Promise<T[]> {
// #4145 R2-2 preflight: an ALREADY-aborted signal must short-circuit
// BEFORE the query is dispatched — the previous order created the
// pending query first and cancelled it after, which still burned a
// round-trip (and on a saturated pool, a slot). Cancellation remains
// BEST-EFFORT overall (PG protocol cancel is async); callers that need
// correctness must rely on their own fencing, not this signal.
if (opts?.signal?.aborted) {
throw new DOMException('aborted', 'AbortError');
}
const pending = conn.unsafe(sql, params as Parameters<typeof conn.unsafe>[1]);
if (opts?.signal) {
if (opts.signal.aborted) {
// .cancel() is fire-and-forget; the awaited query rejects with the
// postgres "query was cancelled" error which the caller catches.
try {
(pending as unknown as { cancel?: () => void }).cancel?.();
} catch {
// best-effort
}
throw new DOMException('aborted', 'AbortError');
}
const onAbort = () => {
try {
(pending as unknown as { cancel?: () => void }).cancel?.();
@@ -6312,6 +6317,13 @@ export class PostgresEngine implements BrainEngine {
params?: unknown[],
opts?: { signal?: AbortSignal },
): Promise<T[]> {
// #4145 R2-2: observe the signal BEFORE (potentially slow) direct-pool
// acquisition — a caller whose timeout already fired must not queue for
// a pool slot just to be cancelled afterwards. runUnsafe re-checks after
// acquisition.
if (opts?.signal?.aborted) {
throw new DOMException('aborted', 'AbortError');
}
// Inside an open transaction, _sql is the reserved tx connection (set via
// defineProperty in transaction()); never reroute off it.
const inTransaction = this._sql !== null && this.connectionManager?.peekReadPool() !== this._sql;
+3 -1
View File
@@ -926,6 +926,7 @@ CREATE TABLE IF NOT EXISTS minion_jobs (
depth INTEGER NOT NULL DEFAULT 0,
max_children INTEGER,
timeout_ms INTEGER,
lock_duration_ms INTEGER,
timeout_at TIMESTAMPTZ,
remove_on_complete BOOLEAN NOT NULL DEFAULT FALSE,
remove_on_fail BOOLEAN NOT NULL DEFAULT FALSE,
@@ -942,7 +943,8 @@ CREATE TABLE IF NOT EXISTS minion_jobs (
CONSTRAINT chk_nonnegative CHECK (attempts_made >= 0 AND attempts_started >= 0 AND stalled_counter >= 0 AND max_attempts >= 1 AND max_stalled >= 0),
CONSTRAINT chk_depth_nonnegative CHECK (depth >= 0),
CONSTRAINT chk_max_children_positive CHECK (max_children IS NULL OR max_children > 0),
CONSTRAINT chk_timeout_positive CHECK (timeout_ms IS NULL OR timeout_ms > 0)
CONSTRAINT chk_timeout_positive CHECK (timeout_ms IS NULL OR timeout_ms > 0),
CONSTRAINT chk_lock_duration_positive CHECK (lock_duration_ms IS NULL OR (lock_duration_ms >= 5000 AND lock_duration_ms <= 3600000))
);
CREATE INDEX IF NOT EXISTS idx_minion_jobs_claim ON minion_jobs (queue, priority ASC, created_at ASC) WHERE status = 'waiting';
+3 -1
View File
@@ -922,6 +922,7 @@ CREATE TABLE IF NOT EXISTS minion_jobs (
depth INTEGER NOT NULL DEFAULT 0,
max_children INTEGER,
timeout_ms INTEGER,
lock_duration_ms INTEGER,
timeout_at TIMESTAMPTZ,
remove_on_complete BOOLEAN NOT NULL DEFAULT FALSE,
remove_on_fail BOOLEAN NOT NULL DEFAULT FALSE,
@@ -938,7 +939,8 @@ CREATE TABLE IF NOT EXISTS minion_jobs (
CONSTRAINT chk_nonnegative CHECK (attempts_made >= 0 AND attempts_started >= 0 AND stalled_counter >= 0 AND max_attempts >= 1 AND max_stalled >= 0),
CONSTRAINT chk_depth_nonnegative CHECK (depth >= 0),
CONSTRAINT chk_max_children_positive CHECK (max_children IS NULL OR max_children > 0),
CONSTRAINT chk_timeout_positive CHECK (timeout_ms IS NULL OR timeout_ms > 0)
CONSTRAINT chk_timeout_positive CHECK (timeout_ms IS NULL OR timeout_ms > 0),
CONSTRAINT chk_lock_duration_positive CHECK (lock_duration_ms IS NULL OR (lock_duration_ms >= 5000 AND lock_duration_ms <= 3600000))
);
CREATE INDEX IF NOT EXISTS idx_minion_jobs_claim ON minion_jobs (queue, priority ASC, created_at ASC) WHERE status = 'waiting';
+1 -1
View File
@@ -1,6 +1,6 @@
# gbrain agent workspace — template
<!-- gbrain-template-stamp: 0.46.5.0 -->
<!-- gbrain-template-stamp: 0.46.6.0 -->
This repository is the **"Use this template"** distribution artifact for a
[gbrain](https://github.com/garrytan/gbrain) personal-agent workspace — the same
+63
View File
@@ -85,6 +85,69 @@ describe('lockRenewalAudit: 4-outcome contract', () => {
});
});
describe('lockRenewalAudit: v0.46 (#4145) additive telemetry fields', () => {
test('case 9a — ctx fields round-trip through the JSONL (cause/lateness/overlap/load/via)', async () => {
await withEnv({ GBRAIN_AUDIT_DIR: tmpDir }, async () => {
lockRenewalAudit.logFailure(7, 'subagent', 2, new Error('x'), {
cause: 'call-timeout',
lateness_ms: 40_000,
overlap_skips: 1,
load1: 28.12,
cores: 32,
deadline_deferred: true,
});
lockRenewalAudit.logSuccessAfterFailure(7, 'subagent', 2, { via: 'verify' });
const result = readRecentLockRenewalEvents(24);
expect(result.events).toHaveLength(2);
expect(result.events[0]).toMatchObject({
outcome: 'failure',
cause: 'call-timeout',
lateness_ms: 40_000,
overlap_skips: 1,
load1: 28.12,
cores: 32,
deadline_deferred: true,
});
expect(result.events[1]).toMatchObject({ outcome: 'success_after_failure', via: 'verify' });
});
});
test('case 9b — omitted ctx leaves the new keys OUT of the JSONL entirely (no undefined noise)', async () => {
await withEnv({ GBRAIN_AUDIT_DIR: tmpDir }, async () => {
lockRenewalAudit.logGaveUp(8, 'sync', 3, new Error('y'));
const result = readRecentLockRenewalEvents(24);
expect(result.events).toHaveLength(1);
const raw = result.events[0] as unknown as Record<string, unknown>;
for (const key of ['cause', 'lateness_ms', 'overlap_skips', 'load1', 'cores', 'via', 'deadline_deferred']) {
expect(key in raw).toBe(false);
}
});
});
test('case 9c — pre-upgrade JSONL lines (no telemetry fields) still parse in readback', async () => {
await withEnv({ GBRAIN_AUDIT_DIR: tmpDir }, async () => {
// A line exactly as a pre-v0.46 build would have written it.
const legacy = JSON.stringify({
ts: new Date().toISOString(),
job_id: 5,
job_name: 'embed',
attempt: 1,
outcome: 'failure',
error_message_summary: 'Connection terminated',
error_code: '08006',
});
const file = path.join(tmpDir, computeIsoWeekFilename(LOCK_RENEWAL_FEATURE_NAME, new Date()));
fs.mkdirSync(path.dirname(file), { recursive: true });
fs.writeFileSync(file, `${legacy}\n`);
const result = readRecentLockRenewalEvents(24);
expect(result.corrupted_lines).toBe(0);
expect(result.events).toHaveLength(1);
expect(result.events[0].outcome).toBe('failure');
expect(result.events[0].cause).toBeUndefined();
});
});
});
describe('lockRenewalAudit: privacy via redactor (D9)', () => {
test('case 5a — logFailure with PG connection-failure error: no DSN/IP in JSONL', async () => {
await withEnv({ GBRAIN_AUDIT_DIR: tmpDir }, async () => {
+7
View File
@@ -170,6 +170,13 @@ describe('verifyWorkspace — keyless pass', () => {
// Probe cleanup [G13]: pages, files, and the reconciled fact are gone.
expect(existsSync(join(ws, 'brain', `${VERIFY_PROBE_SLUG}.md`))).toBe(false);
expect(existsSync(join(ws, 'brain', `${VERIFY_PROBE_ENTITY_SLUG}.md`))).toBe(false);
// Tombstone-proof: the cleanup HARD-deletes via engine.deletePage — a
// soft delete (deleted_at tombstone) would leave these rows countable.
const probeRows = await engine.executeRaw<{ n: string }>(
`SELECT count(*)::text AS n FROM pages WHERE slug = ANY($1::text[])`,
[[VERIFY_PROBE_SLUG, VERIFY_PROBE_ENTITY_SLUG]],
);
expect(probeRows[0].n).toBe('0');
const facts = await engine.executeRaw<{ fact: string }>(
`SELECT fact FROM facts WHERE source_id = $1 AND fact LIKE $2`,
['workspace', `%${VERIFY_MAGIC_TOKEN}%`],
+7
View File
@@ -30,6 +30,13 @@ function run(args: string[]): { exitCode: number; stdout: string; stderr: string
const env = { ...process.env, HOME: tmp } as Record<string, string | undefined>;
delete env.DATABASE_URL;
delete env.GBRAIN_DATABASE_URL;
// Cross-file poisoning guard: sibling test files in the same bun process
// set process.env.GBRAIN_HOME (preferences, friction, bootstrap-* et al),
// and doctor resolves ~/.gbrain via resolveGbrainHome — which prefers
// GBRAIN_HOME over HOME. A leaked value makes the seeded
// $HOME/.gbrain/migrations fixture invisible and doctor exits 0 where the
// test expects the FAIL exit. Scrub it like the DB URLs above.
delete env.GBRAIN_HOME;
try {
const stdout = execFileSync('bun', ['run', CLI, ...args], {
env: env as Record<string, string>,
+1 -1
View File
@@ -217,7 +217,7 @@ describeIfDB('autopilot fan-out — Postgres E2E', () => {
// expired-lock active must NOT suppress (wedge detectors stay fed):
// the next slot INSERTS a fresh waiting row.
await engine.executeRaw(
`UPDATE minion_jobs SET lock_until = now() - interval '1 second'
`UPDATE minion_jobs SET lock_until = now() - interval '30 seconds'
WHERE id = $1`, [claimed!.id],
);
const r2 = await dispatchPerSource(engine, queue, mkOpts('rl-slot-2'));
@@ -70,11 +70,22 @@ describe('bootstrap harness lifecycle E2E (PGLite + real serve --http)', () => {
// remapped HOME (it reads the password database), so HOME alone does NOT
// sandbox user-scope writes — that leak is exactly why claudeUserSettingsPath
// honors CLAUDE_CONFIG_DIR/HOME explicitly now.
//
// DATABASE_URL/GBRAIN_DATABASE_URL must be scrubbed for the IN-PROCESS
// runBootstrap lane too (the beforeAll already scrubs them for its
// subprocesses): since v0.31.3 (9c60b3a06, #801) an env DATABASE_URL
// deliberately overrides the file-backed PGLite engine in loadConfig().
// Under the DATABASE_URL-bearing e2e wrapper, a leaked URL retargets the
// mint at the shared Postgres test DB — no PGLite single-writer lock, so
// the mint-refusal contract under a live serve never fires and the
// fresh-minted token fails the bearer smoke against the PGLite serve.
const envFor = () => ({
GBRAIN_HOME: parent,
HOME: sandboxHome,
CLAUDE_CONFIG_DIR: join(sandboxHome, '.claude'),
CODEX_HOME: codexHome,
DATABASE_URL: undefined,
GBRAIN_DATABASE_URL: undefined,
});
beforeAll(async () => {
@@ -286,10 +286,18 @@ describe.skipIf(!DATABASE_URL)('Postgres bootstrap verify (real Postgres)', () =
assertSafeE2eDatabaseUrl(DATABASE_URL!);
await engine.connect({ database_url: DATABASE_URL! });
await engine.initSchema();
// This file runs against the shared e2e DB WITHOUT setupDB's TRUNCATE, so
// a prior standalone run's `workspace` source row survives and addSource
// (whose `force` only bypasses git validation, not the id-collision check)
// would throw source_id_taken. Sweep it first; the FK cascade removes any
// leftover pages/facts under it.
await engine.executeRaw(`DELETE FROM sources WHERE id = 'workspace'`, []);
await addSource(engine, { id: 'workspace', localPath: join(ws, 'brain'), force: true });
}, 60_000);
afterAll(async () => {
// Leave the shared DB clean for the next file / next standalone run.
try { await engine.executeRaw(`DELETE FROM sources WHERE id = 'workspace'`, []); } catch { /* noop */ }
try { await engine.disconnect(); } catch { /* noop */ }
if (prevHome === undefined) delete process.env.GBRAIN_HOME;
else process.env.GBRAIN_HOME = prevHome;
+8 -2
View File
@@ -27,6 +27,7 @@ import {
import {
configureGateway,
resetGateway,
__unconfigureGatewayForTests,
__setEmbedTransportForTests,
} from '../../src/core/ai/gateway.ts';
import type { ResolvedColumn } from '../../src/core/types.ts';
@@ -261,8 +262,13 @@ describe('upsertChunks — model provenance uses gateway-resolved model, not com
test('#3461: unconfigured gateway falls back to the brain config model, never the compiled default', async () => {
await engine.setConfig('embedding_model', 'voyage:voyage-3-large');
// The preload's beforeEach re-configures the gateway before every test,
// so the reset must happen INSIDE the test body.
resetGateway();
// so the unconfigure must happen INSIDE the test body. Since commit
// 3aa064bcc (#3554), `resetGateway()` RESTORES the preload's OpenAI/1536
// baseline instead of unconfiguring — this test needs genuine no-gateway
// behavior (getEmbeddingModel() must THROW), which is exactly what
// `__unconfigureGatewayForTests()` was added for. The preload's
// beforeEach restores the baseline before the next test.
__unconfigureGatewayForTests();
await engine.putPage('docs/provenance-throw-path', {
type: 'concept',
+14 -3
View File
@@ -740,9 +740,20 @@ describeBoth('Engine parity — Postgres vs PGLite', () => {
expect(pgRow.updated_at).toBeInstanceOf(Date);
// markPagesExtractedBatch: stamp one → count drops to 2 on both.
const stampAt = new Date().toISOString();
await pgEngine.markPagesExtractedBatch([{ slug: 'sp/1', source_id: SRC }], stampAt);
await pgliteEngine.markPagesExtractedBatch([{ slug: 'sp/1', source_id: SRC }], stampAt);
// Stamp with the row's OWN updated_at_iso (per-ref extractedAt — the
// #1768/D4 production semantics used by extractStaleFromDB), NOT client
// `new Date()`: the test client's clock and the DB server's clock are
// different clocks (docker VM drift under load), so a client-now stamp can
// land before the row's server-side `updated_at`, leaving sp/1 flagged
// `updated_at > links_extracted_at` and the count stuck at 3.
for (const eng of [pgEngine, pgliteEngine]) {
const sp1 = (await eng.listStalePagesForExtraction({ batchSize: 10, sourceId: SRC }))
.find((r) => r.slug === 'sp/1')!;
await eng.markPagesExtractedBatch(
[{ slug: 'sp/1', source_id: SRC, extractedAt: sp1.updated_at_iso }],
sp1.updated_at_iso,
);
}
expect(await pgEngine.countStalePagesForExtraction({ sourceId: SRC })).toBe(2);
expect(await pgliteEngine.countStalePagesForExtraction({ sourceId: SRC })).toBe(2);
+19 -5
View File
@@ -12,6 +12,12 @@
* 3. sourceId scoping isolates between two seeded sources (no leak)
* 4. ANY($2::text[]) binding actually filters by type set
*
* Type allowlist updated for e1e1f3bac (PR #2615): discovery now honors the
* active schema pack's `extractable: true` flags in addition to the legacy
* 6-type floor. Under the default `gbrain-base` pack that makes `note`
* extractable; the non-extractable control type here is `person`
* (pack-declared `extractable: false`).
*
* ~4 structural assertions; ~3-5s wallclock budget.
* Skips gracefully when DATABASE_URL is unset.
*/
@@ -37,8 +43,10 @@ afterAll(async () => {
beforeEach(async () => {
if (skip) return;
// Clean test-source rows + atoms + meeting pages between tests
await engine.executeRaw(`DELETE FROM pages WHERE source_id IN ('default', 'dept-x') AND (type = 'atom' OR type IN ('meeting', 'source', 'article', 'video', 'book', 'original'))`);
// Clean test-source rows + atoms + seeded pages between tests. Includes
// 'note' (pack-extractable since e1e1f3bac / PR #2615) and 'person' (the
// non-extractable control) so seeds can't leak into later tests.
await engine.executeRaw(`DELETE FROM pages WHERE source_id IN ('default', 'dept-x') AND (type = 'atom' OR type IN ('meeting', 'source', 'article', 'video', 'book', 'original', 'note', 'person'))`);
await engine.executeRaw(`DELETE FROM sources WHERE id = 'dept-x'`);
});
@@ -74,13 +82,17 @@ describeIfDB('v0.41.2.1 D10 — discoverExtractablePages on real Postgres', () =
test('returns extractable rows when seeded', async () => {
await seedPage({ slug: 'meeting/a', type: 'meeting', content_hash: 'hash-A-1234567890abc' });
await seedPage({ slug: 'source/b', type: 'source', content_hash: 'hash-B-1234567890abc' });
await seedPage({ slug: 'notes/skip', type: 'note', content_hash: 'hash-N-1234567890abc' });
// e1e1f3bac (PR #2615): `note` is pack-extractable under gbrain-base, so
// it IS discovered now. `person` (extractable: false) is the skip control.
await seedPage({ slug: 'notes/kept', type: 'note', content_hash: 'hash-N-1234567890abc' });
await seedPage({ slug: 'people/skip', type: 'person', content_hash: 'hash-P-1234567890abc' });
const discovered = await discoverExtractablePages(engine, 'default');
const slugs = discovered.map((d) => d.slug).sort();
expect(slugs).toContain('meeting/a');
expect(slugs).toContain('source/b');
expect(slugs).not.toContain('notes/skip');
expect(slugs).toContain('notes/kept');
expect(slugs).not.toContain('people/skip');
});
test('ANY($::text[]) bind works through postgres.unsafe (PGLite parity proof)', async () => {
@@ -90,7 +102,9 @@ describeIfDB('v0.41.2.1 D10 — discoverExtractablePages on real Postgres', () =
for (const type of ['meeting', 'source', 'article', 'video', 'book', 'original']) {
await seedPage({ slug: `${type}/x`, type, content_hash: `hash-${type}-1234567890ab` });
}
await seedPage({ slug: 'note/skip', type: 'note', content_hash: 'hash-note-1234567890' });
// e1e1f3bac (PR #2615): `note` is now pack-extractable, so the
// non-extractable control is `person` (extractable: false in gbrain-base).
await seedPage({ slug: 'person/skip', type: 'person', content_hash: 'hash-pers-1234567890' });
const discovered = await discoverExtractablePages(engine, 'default');
const slugs = discovered.map((d) => d.slug).sort();
+1 -1
View File
@@ -173,7 +173,7 @@ describeE2E('E2E: Minions resilience (OpenClaw real-world patterns)', () => {
VALUES
('rescue-me', 'default', 'active', 0, '{}'::jsonb, 3, 1, 1,
'exponential', 1000, 0.2, 0, 3,
'crashed-worker:123', now() - interval '10 seconds', 'fail_parent', 0, false, false,
'crashed-worker:123', now() - interval '30 seconds', 'fail_parent', 0, false, false,
now() - interval '1 minute')
RETURNING id
`);
+41 -10
View File
@@ -18,10 +18,10 @@
* ship to ClawHub).
* 2. `openclaw plugins install --link` against an isolated `--profile`
* directory.
* 3. `openclaw plugins inspect <id> --runtime --json` imports the plugin and
* reads our default-export shape
* back from the runtime registry (`status: 'loaded'`, `imported: true`,
* id/name/description match).
* 3. `openclaw plugins inspect <id> --json` (with `--runtime` on older
* CLIs see inspectRuntime) imports the plugin and reads our
* default-export shape back from the runtime registry
* (`status: 'loaded'`, `imported: true`, id/name/description match).
* 4. `openclaw config set plugins.slots.contextEngine gbrain-context`
* `openclaw config validate` confirms the slot binding is accepted.
* 5. `openclaw plugins doctor` surfaces zero error-level diagnostics for
@@ -82,6 +82,25 @@ function runOpenclaw(args: string[], opts: { timeoutMs?: number } = {}): {
};
}
/**
* Version-robust runtime inspect. The test was pinned to
* `plugins inspect <id> --runtime --json` (#3742), but OpenClaw has since
* folded the runtime import into the default inspect and REMOVED the
* `--runtime` flag (observed on OpenClaw 2026.4.10: `error: unknown option
* '--runtime'`, while plain `inspect --json` reports status/imported/
* activated + diagnostics). Try the flagged form first for older CLIs and
* fall back to the plain form when the flag is unknown, so the assertions
* pin the plugin-load contract rather than one CLI version's flag surface.
*/
function inspectRuntime(id: string): { exitCode: number; stdout: string; stderr: string } {
const flagged = runOpenclaw(['plugins', 'inspect', id, '--runtime', '--json'], { timeoutMs: 30_000 });
if (flagged.exitCode === 0) return flagged;
if (/unknown option '--runtime'/.test(`${flagged.stdout}\n${flagged.stderr}`)) {
return runOpenclaw(['plugins', 'inspect', id, '--json'], { timeoutMs: 30_000 });
}
return flagged;
}
function cleanup() {
if (!OPENCLAW) return;
// Best-effort: uninstall the plugin and rm the profile dir. Both may
@@ -121,17 +140,29 @@ describe('openclaw-plugin-load-real (Tier 2 e2e)', () => {
readFileSync(join(fixtureTemplate, 'openclaw.plugin.json.template'), 'utf8'),
);
// Build our real entry to a single JS bundle. This is the same source
// Build our real entry into the fixture dir. This is the same source
// (`src/openclaw-context-engine.ts`) that the release ships; only the
// packaging layer (test fixture's package.json) is test-specific.
//
// `--outdir` (not `--outfile`): since the Retrieval Reflex ladder
// (v0.42.39.0, 8f45624e5 #2019) the entry's import chain reaches
// engine-factory → pglite-engine → @electric-sql/pglite, whose WASM/
// data assets become sibling build outputs — and `bun build` refuses
// `--outfile` when a build produces multiple output files. The fixed
// `--entry-naming` keeps the bundle at `entry.js`, matching the
// fixture package.json's `openclaw.extensions` entry; the assets land
// alongside it in the same directory, where the bundle's relative
// references resolve.
const buildResult = spawnSync(
'bun',
[
'build',
join(repoRoot, 'src', 'openclaw-context-engine.ts'),
'--target=bun',
'--outfile',
join(fixtureDir, 'entry.js'),
'--outdir',
fixtureDir,
'--entry-naming',
'[dir]/entry.[ext]',
],
{ encoding: 'utf8', timeout: 60_000 },
);
@@ -168,7 +199,7 @@ describe('openclaw-plugin-load-real (Tier 2 e2e)', () => {
it.skipIf(SKIP)(
'openclaw imports the entry file and reports status=loaded',
() => {
const r = runOpenclaw(['plugins', 'inspect', PLUGIN_ID, '--runtime', '--json'], { timeoutMs: 30_000 });
const r = inspectRuntime(PLUGIN_ID);
expect(r.exitCode).toBe(0);
const inspect = JSON.parse(r.stdout);
@@ -184,7 +215,7 @@ describe('openclaw-plugin-load-real (Tier 2 e2e)', () => {
it.skipIf(SKIP)(
'default export carries the expected id / name / description metadata',
() => {
const r = runOpenclaw(['plugins', 'inspect', PLUGIN_ID, '--runtime', '--json'], { timeoutMs: 30_000 });
const r = inspectRuntime(PLUGIN_ID);
expect(r.exitCode).toBe(0);
const inspect = JSON.parse(r.stdout);
@@ -199,7 +230,7 @@ describe('openclaw-plugin-load-real (Tier 2 e2e)', () => {
it.skipIf(SKIP)(
'register(api) ran without producing error-level diagnostics',
() => {
const r = runOpenclaw(['plugins', 'inspect', PLUGIN_ID, '--runtime', '--json'], { timeoutMs: 30_000 });
const r = inspectRuntime(PLUGIN_ID);
expect(r.exitCode).toBe(0);
const inspect = JSON.parse(r.stdout);
+8
View File
@@ -96,6 +96,14 @@ beforeAll(() => {
delete runEnv.OPENAI_API_KEY;
delete runEnv.ANTHROPIC_API_KEY;
delete runEnv.GOOGLE_API_KEY;
// Strip DB-URL env vars: since v0.31.3 (9c60b3a06, #801) an env
// DATABASE_URL deliberately overrides a file-backed PGLite engine
// selection in loadConfig(). This whole file is a hermetic-PGLite
// suite; when run under the DATABASE_URL-bearing e2e wrapper, an
// inherited URL would silently retarget every subprocess (including
// the torn-WAL fixture below) at the shared Postgres test DB.
delete runEnv.DATABASE_URL;
delete runEnv.GBRAIN_DATABASE_URL;
// NOTE: init grew strict flag validation (#2201); `--repo`/`--yes` were
// never real init flags (previously silently ignored). The repo is wired
+27 -16
View File
@@ -235,27 +235,38 @@ describeMaybe('phantom-redirect E2E (Postgres)', () => {
FROM facts WHERE source_id='default'
ORDER BY id`,
);
// After migrateFactsToCanonical, the row is now under canonical.
// The migrate step preserves embedding. Then the main reconcile
// visits canonical (added via touched_canonicals) and does
// wipe-then-insert from fence — which DROPS embedding because
// the fence doesn't carry it. So embedding ends up NULL.
// After migrateFactsToCanonical, the row is now under canonical with
// every other column — including embedding — preserved (the UPDATE
// rewrites only the slug columns). The main reconcile then visits
// canonical (added via touched_canonicals); since 54a807064 (#2932,
// idempotent extract_facts) an in-sync page is a NO-OP instead of the
// old wipe-then-reinsert, so the migrated row and its embedding
// SURVIVE the pass. (Pre-#2932 the wipe dropped the embedding to
// NULL, which this test used to document.)
//
// This test EXISTS to document this baseline behavior: the migrate
// step itself does NOT corrupt the embedding column on Postgres
// (the round-12 concern), but the subsequent fence reconcile
// intentionally re-derives from fence and embedding is regenerated
// by the embed phase.
//
// The pinning assertion: at NO point is the embedding column
// populated with a STRING (postgres-js's text shape leak — that
// bug class would produce a non-null text-shaped value here, not
// a clean NULL).
// The round-12 pinning assertions:
// 1. The embedding survived the migrate + reconcile round-trip
// non-NULL at its original dimensionality — postgres-js did not
// mangle it through its text representation.
// 2. At NO point is the embedding column populated with a
// non-vector-typed value. Since v0.31.0 (89ae72095, migration
// v40) the facts.embedding column is HALFVEC(1536) on pgvector
// >= 0.7 (full-precision VECTOR fallback below that), so BOTH
// real vector types are legitimate here.
const survived = await engine.executeRaw<{ ct: string; dims: number | null }>(
`SELECT COUNT(*)::text AS ct, MIN(vector_dims(embedding::vector)) AS dims
FROM facts
WHERE source_id='default'
AND source_markdown_slug='people/alice-example'
AND embedding IS NOT NULL`,
);
expect(parseInt(survived[0].ct, 10)).toBe(1);
expect(Number(survived[0].dims)).toBe(1536);
const stringShaped = await engine.executeRaw<{ ct: string }>(
`SELECT COUNT(*)::text AS ct FROM facts
WHERE source_id='default'
AND embedding IS NOT NULL
AND pg_typeof(embedding)::text != 'vector'`,
AND pg_typeof(embedding)::text NOT IN ('vector', 'halfvec')`,
);
expect(parseInt(stringShaped[0].ct, 10)).toBe(0);
expect(rows.length).toBeGreaterThan(0);
+15 -1
View File
@@ -580,9 +580,23 @@ describeE2E('serve-http OAuth 2.1 E2E (v0.26.1 + v0.26.2 + v0.26.3)', () => {
const postgres = (await import('postgres')).default;
const sql = postgres(process.env.GBRAIN_DATABASE_URL || process.env.DATABASE_URL || '', { prepare: false });
try {
// Plain-array bind, NOT `sql.array([...])`: sql.array resolves its
// array OID (and serializer) through postgres.js's typeArrayMap, which
// is fetched asynchronously on connection startup. This INSERT is the
// FIRST query on this fresh connection, so the map is still empty and
// sql.array falls back to the element OID (25 = text) with scalar
// serialization — real Postgres rejects it with 42804 ("column scopes
// is of type text[] but expression is of type text"; an explicit
// ::text[] cast just shifts the failure to 22P02 "malformed array
// literal" because the value still serializes as a bare scalar). A
// plain JS array always serializes to the `{...}` literal and binds
// with an unspecified OID, so Postgres coerces it from column context
// deterministically — same untyped-bind approach as pgArray() in
// src/core/oauth-provider.ts. Latent since d61808d80 (v0.42.64.0):
// CI's e2e.yml never runs this file.
await sql`
INSERT INTO oauth_tokens (token_hash, token_type, client_id, scopes, expires_at)
VALUES (${tokenHash}, ${'access'}, ${publicClientId!}, ${sql.array(['read'])}, ${Math.floor(Date.now() / 1000) + 3600})
VALUES (${tokenHash}, ${'access'}, ${publicClientId!}, ${['read']}, ${Math.floor(Date.now() / 1000) + 3600})
`;
} finally {
await sql.end();
+23
View File
@@ -70,11 +70,31 @@ function gitCommit(repoPath: string, message: string) {
execSync(`git add -A && git commit -m "${message}"`, { cwd: repoPath, stdio: 'pipe' });
}
/**
* #2114 (commit 636628fdb): global sync.* anchors only move for the brain repo
* they describe. `writeSyncAnchor` proves ownership via `ownsGlobalSyncAnchor`,
* which falls back to the default source row's `local_path` when
* `config.sync.repo_path` is unset and `setupDB()` truncates `config` but
* NOT `sources`, so a stale `local_path` from a previously-run e2e file (e.g.
* sync-credential-preflight.test.ts, which sorts before this file in the full
* lane) survives in the shared DB and silently refuses every anchor write
* here. That wedges the bookmark: every sync re-runs as `first_sync` and
* `sync.last_commit` never persists. Reset the default-source identity so this
* file's mkdtemp repo is a legitimate fresh-brain bootstrap.
*/
async function resetBrainRepoIdentity() {
const engine = getEngine();
await engine.executeRaw(
`UPDATE sources SET local_path = NULL, last_commit = NULL WHERE id = 'default'`,
);
}
describeE2E('E2E: Git-to-DB Sync Pipeline', () => {
let repoPath: string;
beforeAll(async () => {
await setupDB();
await resetBrainRepoIdentity();
repoPath = createTestRepo();
}, 30_000);
@@ -417,6 +437,9 @@ describeE2E('E2E: sync --skip-failed structured summary loop (v0.22.12, issue #5
beforeAll(async () => {
await setupDB();
// #2114: see resetBrainRepoIdentity above — setupDB truncates config but
// not sources, and this block syncs a brand-new mkdtemp repo.
await resetBrainRepoIdentity();
// Save+clear the real ~/.gbrain/sync-failures.jsonl so the test starts from
// a known-empty state. Restored in afterAll. This file is per-machine, NOT
@@ -13,6 +13,9 @@
// - re-running is idempotent (total_applied: 0)
import { afterAll, beforeAll, beforeEach, describe, expect, it } from 'bun:test';
import { mkdtempSync, rmSync } from 'fs';
import { tmpdir } from 'os';
import { join } from 'path';
import { PGLiteEngine } from '../../src/core/pglite-engine.ts';
import { resetPgliteState } from '../helpers/reset-pglite.ts';
import { runUnifyTypes } from '../../src/core/schema-pack/unify-types-handler.ts';
@@ -21,7 +24,25 @@ import { _resetPackCacheForTests } from '../../src/core/schema-pack/registry.ts'
let engine: PGLiteEngine;
// GBRAIN_HOME isolation (in-process; configDir() reads process.env at call
// time). Two leaks without it, both through the file-plane config:
// 1. checkPackUpgradeAvailable() reads loadConfigFileOnly() — an ambient
// ~/.gbrain/config.json carrying `schema_pack: gbrain-base-v2` (any
// machine whose brain already unified) makes the pre-unify check return
// 'ok' instead of 'warn' and the first test fails.
// 2. runUnifyTypes({apply: true}) WRITES the flip via saveConfig() — under
// bare `bun test` that lands in the operator's REAL config (the exact
// breach scripts/run-e2e.sh's md5 check exists to catch), and under the
// full e2e lane it lands in the wrapper's shared tmp HOME, poisoning
// every later loadActivePack caller in the same invocation.
// Same in-process pattern as test/preferences.test.ts.
let tmpHome: string;
let origGbrainHome: string | undefined;
beforeAll(async () => {
origGbrainHome = process.env.GBRAIN_HOME;
tmpHome = mkdtempSync(join(tmpdir(), 'gbrain-type-uni-e2e-'));
process.env.GBRAIN_HOME = tmpHome;
engine = new PGLiteEngine();
await engine.connect({});
await engine.initSchema();
@@ -29,11 +50,17 @@ beforeAll(async () => {
afterAll(async () => {
await engine.disconnect();
if (origGbrainHome === undefined) delete process.env.GBRAIN_HOME;
else process.env.GBRAIN_HOME = origGbrainHome;
try { rmSync(tmpHome, { recursive: true, force: true }); } catch { /* best-effort */ }
});
beforeEach(async () => {
await resetPgliteState(engine);
_resetPackCacheForTests();
// The first test's apply flips schema_pack in the isolated file-plane
// config; wipe it so every test starts pre-unify (order-independence).
try { rmSync(join(tmpHome, '.gbrain'), { recursive: true, force: true }); } catch { /* best-effort */ }
});
function ctxOf() {
+34 -9
View File
@@ -10,7 +10,13 @@
* 3. handler invocation + JSON serialization (ToolResult shape)
* 4. Error path: OperationError isError + JSON envelope
* 5. Trust gate: ctx.remote === true on get_recent_transcripts must
* reach the handler and produce a permission_denied error.
* reach the handler and produce a permission_denied error. Since
* commit 6a905a1e5 (v0.45.13.0, #4096 WP1/D7) localOnly ops only
* DISPATCH on the stdio local pipe (transport: 'stdio'); any other
* or unset transport is denied fail-closed with the unknown_tool
* envelope BEFORE the handler (pinned in
* test/dispatch-localonly.test.ts). The trust axis (`remote`) is a
* separate, in-handler check.
*
* Runs against PGLite in-memory. No DATABASE_URL, no API keys.
*/
@@ -111,11 +117,13 @@ describe('v0.29 E2E — dispatchToolCall for the three new ops', () => {
test('get_recent_transcripts rejects with permission_denied when ctx.remote === true', async () => {
// Defense-in-depth: even though serve-http filters localOnly: true ops
// out of the MCP tool list, the in-handler ctx.remote check is the
// last line. dispatchToolCall defaults remote=true, which is what
// every MCP transport sets, so the reject must fire here.
// last line. This dispatch shape (remote: true, transport: 'stdio') is
// exactly what the real stdio MCP server sets (src/mcp/server.ts) —
// stdio passes the #4096 WP1/D7 locality backstop but stays
// remote/untrusted, so the in-handler trust gate must fire.
const result = await dispatchToolCall(engine, 'get_recent_transcripts', {
days: 7,
}, { remote: true, sourceId: 'default' });
}, { remote: true, transport: 'stdio', sourceId: 'default' });
expect(result.isError).toBe(true);
const err = JSON.parse(result.content[0].text);
@@ -124,13 +132,30 @@ describe('v0.29 E2E — dispatchToolCall for the three new ops', () => {
expect(err.message.toLowerCase()).toContain('local-only');
});
test('get_recent_transcripts succeeds when ctx.remote === false (CLI path)', async () => {
// The local-CLI path explicitly sets remote: false. Op should run
// (returning [] is fine — no corpus dir is configured in this test
// fixture; the test just asserts the trust gate didn't reject).
test('get_recent_transcripts is denied fail-closed (unknown_tool) when the transport marker is unset', async () => {
// #4096 WP1/D7 backstop: localOnly ops dispatch only on the stdio local
// pipe. An unset transport marker — even from a trusted (remote: false)
// caller — gets the same envelope as a nonexistent op, so the catalog
// never leaks which localOnly names exist.
for (const remote of [true, false]) {
const result = await dispatchToolCall(engine, 'get_recent_transcripts', {
days: 7,
}, { remote, sourceId: 'default' });
expect(result.isError).toBe(true);
expect(JSON.parse(result.content[0].text).error).toBe('unknown_tool');
}
});
test('get_recent_transcripts succeeds when ctx.remote === false (trusted local dispatch)', async () => {
// Trusted local callers set remote: false; the dispatch must arrive on
// the stdio local pipe to pass the #4096 locality backstop (the real
// CLI path in src/cli.ts invokes handlers directly with remote: false
// and never crosses the backstop). Op should run (returning [] is fine
// — no corpus dir is configured in this test fixture; the test just
// asserts the trust gate didn't reject).
const result = await dispatchToolCall(engine, 'get_recent_transcripts', {
days: 7,
}, { remote: false });
}, { remote: false, transport: 'stdio' });
expect(result.isError).toBeFalsy();
const rows = JSON.parse(result.content[0].text);
@@ -0,0 +1,164 @@
/**
* E2E: verify-before-evict under real Postgres (#4145, CDX-12/R2-5).
*
* The hermetic suite (test/worker-lock-renewal.test.ts) proves the tick's
* state machine, including the fake-time incident replay. These tests prove
* the DB-level invariants the verify RELIES on, against real Postgres:
*
* 1. renewLock revives an expired-but-UNSTOLEN lease (it fences on
* lock_token and deliberately does not check lock_until) the
* foundation of the starved-but-ours recovery path.
* 2. The stall-sweep reclaim grace holds the sweep off a freshly-lapsed
* lease (the same-burst self-steal race), while grace=0 restores the
* legacy predicate.
* 3. After a genuine reclaim, the owner's renewal is fenced-false the
* verify's CERTAIN-loss signal and the requeue burned no attempt.
* 4. Worker end-to-end: a synchronously-blocked event loop past lease
* expiry does NOT evict a healthy job it completes with zero
* stall bounces (the #4145 incident's user-visible contract).
*
* A faithful cross-process starvation replay (blocked worker + concurrent
* foreign sweeper) needs a second OS process and lives out of scope; the
* hermetic incident replay carries that contract deterministically.
*
* Run: DATABASE_URL=... bun test test/e2e/worker-lock-renewal-starvation.test.ts
*/
import { describe, test, expect, beforeAll, afterAll, beforeEach } from 'bun:test';
import { hasDatabase, setupDB, teardownDB, getConn, getEngine } from './helpers.ts';
import { PostgresEngine } from '../../src/core/postgres-engine.ts';
import { MinionQueue } from '../../src/core/minions/queue.ts';
import { MinionWorker } from '../../src/core/minions/worker.ts';
import { runMigrations } from '../../src/core/migrate.ts';
const skip = !hasDatabase();
const describeE2E = skip ? describe.skip : describe;
if (skip) {
console.log('Skipping E2E lock-renewal starvation tests (DATABASE_URL not set)');
}
async function makeEngine(): Promise<PostgresEngine> {
const engine = new PostgresEngine();
await engine.connect({ engine: 'postgres', database_url: process.env.DATABASE_URL!, poolSize: 4 });
return engine;
}
/** Synchronously block the event loop — the incident's starvation shape. */
function blockEventLoop(ms: number): void {
const until = Date.now() + ms;
while (Date.now() < until) { /* spin */ }
}
describeE2E('E2E: lock-renewal verify-before-evict foundations (#4145)', () => {
beforeAll(async () => {
await setupDB();
await runMigrations(getEngine());
}, 30_000);
afterAll(async () => {
await teardownDB();
});
beforeEach(async () => {
const conn = getConn();
await conn.unsafe(`TRUNCATE minion_attachments, minion_inbox, minion_jobs RESTART IDENTITY CASCADE`);
});
test('renewLock revives an expired-but-unstolen lease; grace holds the sweep; reclaim yields fenced-false', async () => {
const engine = await makeEngine();
try {
const queue = new MinionQueue(engine);
const job = await queue.add('starve-target', {});
const claimed = await queue.claim('tok-owner', 60_000, 'default', ['starve-target']);
expect(claimed?.id).toBe(job.id);
// Lapse the lease as a starved owner would (2s past — inside the 15s grace).
await engine.executeRaw(
`UPDATE minion_jobs SET lock_until = now() - interval '2 seconds' WHERE id = $1`,
[job.id],
);
// (2) The default-grace sweep does NOT steal the freshly-lapsed lease.
const held = await queue.handleStalled();
expect(held.requeued).toHaveLength(0);
expect(held.dead).toHaveLength(0);
// (1) The owner's (verify) renewal revives the expired-but-unstolen lease.
const revived = await queue.renewLock(job.id, 'tok-owner', 60_000);
expect(revived).toBe(true);
const afterRevive = await queue.getJob(job.id);
expect(afterRevive!.status).toBe('active');
expect(afterRevive!.lock_until!.getTime()).toBeGreaterThan(Date.now() + 30_000);
// Lapse again; grace=0 restores the legacy predicate and reclaims.
await engine.executeRaw(
`UPDATE minion_jobs SET lock_until = now() - interval '2 seconds' WHERE id = $1`,
[job.id],
);
const swept = await queue.handleStalled(0);
expect(swept.requeued).toHaveLength(1);
// (3) The owner's next renewal is fenced-false — CERTAIN loss — and
// the infrastructure requeue burned no attempt.
const fenced = await queue.renewLock(job.id, 'tok-owner', 60_000);
expect(fenced).toBe(false);
const requeued = await queue.getJob(job.id);
expect(requeued!.status).toBe('waiting');
expect(requeued!.attempts_made).toBe(0);
expect(requeued!.stalled_counter).toBe(1);
} finally {
await engine.disconnect();
}
}, 30_000);
test('worker survives a blocked event loop past lease expiry: job completes, zero stall bounces', async () => {
const engine = await makeEngine();
try {
const queue = new MinionQueue(engine);
const job = await queue.add('starved-but-healthy', {});
const worker = new MinionWorker(engine, {
concurrency: 1,
pollInterval: 50,
lockDuration: 1_000, // lease expires DURING the synchronous block
stalledInterval: 200,
});
let blocked = false;
worker.register('starved-but-healthy', async () => {
// The incident shape: the process is healthy but the loop is
// saturated past the entire lease window. No renewal (and no
// foreign steal — single worker), so the lease lapses; the
// post-block renewal must recover it rather than evict.
blockEventLoop(2_500);
blocked = true;
return { survived: true };
});
const p = worker.start();
const started = Date.now();
let completed = false;
while (Date.now() - started < 10_000) {
const j = await queue.getJob(job.id);
if (j?.status === 'completed') { completed = true; break; }
await new Promise(r => setTimeout(r, 50));
}
worker.stop();
await p;
expect(blocked).toBe(true);
expect(completed).toBe(true);
const final = await queue.getJob(job.id);
expect(final!.status).toBe('completed');
expect(final!.result).toEqual({ survived: true });
// The user-visible #4145 contract: a starved-but-healthy job is not
// bounced through the stall detector, and no attempt is burned
// (attempts_made only bumps on failure; one clean claim).
expect(final!.stalled_counter).toBe(0);
expect(final!.attempts_made).toBe(0);
expect(final!.attempts_started).toBe(1);
} finally {
await engine.disconnect();
}
}, 30_000);
});
+17
View File
@@ -82,3 +82,20 @@ describe('formatJobDetail timeout/deadline lines', () => {
expect(out).toContain('null-default wall-clock sweep applies');
});
});
describe('lock lease rendering (#4145)', () => {
test('stamped row value renders with the cadence note', () => {
const out = formatJobDetail(job({ lock_duration_ms: 120000 }));
expect(out).toContain('Lock lease: 120000ms (renewed at min(lease/2, 60s) cadence)');
});
test('unset lease on a mapped handler renders the claim-time default', () => {
const out = formatJobDetail(job({ name: 'subagent', lock_duration_ms: null }));
expect(out).toContain('Lock lease: (unset) — handler default 300000ms stamps at claim');
});
test('unset lease on an unmapped handler renders no lease line (worker default applies)', () => {
const out = formatJobDetail(job({ name: 'sync', lock_duration_ms: null }));
expect(out).not.toContain('Lock lease:');
});
});
+121
View File
@@ -0,0 +1,121 @@
/**
* #4145 migration v130 (minion_jobs_lock_duration_ms).
*
* Pinned contracts:
* 1. v130 exists in MIGRATIONS with the canonical name, idempotent flag, and
* one engine-agnostic sql block; adds the column AND the CHECK via the
* idempotent drop-then-add pattern (v7 precedent) so migrated brains
* carry the same DB bound as fresh installs.
* 2. NO backfill: NULL lock_duration_ms means "worker default" (pre-#4145
* behavior); the claim-time COALESCE owns all defaulting.
* 3. SQL-level idempotency: re-executing the v130 statements directly on an
* already-migrated schema changes nothing and throws nothing.
* 4. The CHECK holds: 0 / negative direct writes are rejected; NULL and
* positive values pass.
* 5. A pre-v130-shaped table (column dropped) gains the column on re-run.
*/
import { describe, test, expect, beforeAll, afterAll, beforeEach } from 'bun:test';
import { PGLiteEngine } from '../src/core/pglite-engine.ts';
import { MinionQueue } from '../src/core/minions/queue.ts';
import { MIGRATIONS, LATEST_VERSION } from '../src/core/migrate.ts';
let engine: PGLiteEngine;
let queue: MinionQueue;
const V130_SQL = MIGRATIONS.find(m => m.version === 130)?.sql ?? '';
const V130_STATEMENTS = V130_SQL.split(';').map(s => s.trim()).filter(Boolean);
async function execV130Directly(): Promise<void> {
for (const stmt of V130_STATEMENTS) {
await engine.executeRaw(stmt);
}
}
beforeAll(async () => {
engine = new PGLiteEngine();
await engine.connect({ database_url: '' }); // in-memory
await engine.initSchema();
queue = new MinionQueue(engine);
});
afterAll(async () => {
await engine.disconnect();
});
beforeEach(async () => {
await engine.executeRaw('DELETE FROM minion_jobs');
});
describe('migration v130 — structure', () => {
test('exists with canonical name, idempotent flag, engine-agnostic sql', () => {
const v130 = MIGRATIONS.find(m => m.version === 130);
expect(v130).toBeDefined();
expect(v130?.name).toBe('minion_jobs_lock_duration_ms');
expect(v130?.idempotent).toBe(true);
expect(v130?.sqlFor).toBeUndefined();
expect(LATEST_VERSION).toBeGreaterThanOrEqual(130);
});
test('adds the column IF NOT EXISTS and the CHECK via drop-then-add (v7 precedent); NO backfill', () => {
expect(V130_SQL).toContain('ADD COLUMN IF NOT EXISTS lock_duration_ms INTEGER');
expect(V130_SQL).toContain('DROP CONSTRAINT IF EXISTS chk_lock_duration_positive');
expect(V130_SQL).toContain('ADD CONSTRAINT chk_lock_duration_positive CHECK (lock_duration_ms IS NULL OR (lock_duration_ms >= 5000 AND lock_duration_ms <= 3600000))');
// NULL = worker default = pre-#4145 behavior; a backfill would change
// legacy rows' semantics for no benefit (claim COALESCE owns defaulting).
expect(V130_SQL).not.toContain('UPDATE minion_jobs');
});
});
describe('migration v130 — semantics (PGLite)', () => {
test('SQL idempotency: direct re-run on a migrated schema is a clean no-op', async () => {
await execV130Directly();
await execV130Directly(); // twice — the drop-then-add pair must converge
const rows = await engine.executeRaw<{ count: string }>(
`SELECT count(*)::text AS count FROM information_schema.columns
WHERE table_name = 'minion_jobs' AND column_name = 'lock_duration_ms'`,
);
expect(rows[0].count).toBe('1');
});
test('CHECK holds: out-of-range rejected, NULL + in-range pass', async () => {
const job = await queue.add('lease-check', {});
await engine.executeRaw(`UPDATE minion_jobs SET lock_duration_ms = 300000 WHERE id = $1`, [job.id]);
await engine.executeRaw(`UPDATE minion_jobs SET lock_duration_ms = NULL WHERE id = $1`, [job.id]);
// The CHECK enforces the full advertised [5s,1h] range so a bypass
// writer can't stamp a thrash-lease or a weeks-long one (codex P2).
for (const bad of [0, -5, 1, 4999, 3_600_001]) {
await expect(
engine.executeRaw(`UPDATE minion_jobs SET lock_duration_ms = ${bad} WHERE id = $1`, [job.id]),
).rejects.toThrow(/chk_lock_duration_positive/);
}
});
test('pre-v130 shape (column dropped) gains column + CHECK on re-run', async () => {
await engine.executeRaw(`ALTER TABLE minion_jobs DROP CONSTRAINT IF EXISTS chk_lock_duration_positive`);
await engine.executeRaw(`ALTER TABLE minion_jobs DROP COLUMN IF EXISTS lock_duration_ms`);
await execV130Directly();
const job = await queue.add('lease-regain', {});
const row = await queue.getJob(job.id);
expect(row!.lock_duration_ms).toBeNull(); // unmapped name → no default stamped
await expect(
engine.executeRaw(`UPDATE minion_jobs SET lock_duration_ms = 0 WHERE id = $1`, [job.id]),
).rejects.toThrow(/chk_lock_duration_positive/);
});
test('claim SQL clamps a bypass-written lease before deriving lock_until (codex P2)', async () => {
// Simulate foreign tooling stamping a lease outside the advertised
// range directly (the CHECK blocks this on current schemas, so drop it
// for the simulation — the claim clamp is the layer under test).
await engine.executeRaw(`ALTER TABLE minion_jobs DROP CONSTRAINT IF EXISTS chk_lock_duration_positive`);
const job = await queue.add('bypass-lease', {});
await engine.executeRaw(`UPDATE minion_jobs SET lock_duration_ms = 2147483647 WHERE id = $1`, [job.id]);
const before = Date.now();
const claimed = await queue.claim('tok-bypass', 30_000, 'default', ['bypass-lease']);
expect(claimed!.lock_duration_ms).toBe(3_600_000); // stamped clamped
const horizon = claimed!.lock_until!.getTime() - before;
expect(horizon).toBeLessThan(3_700_000); // lock_until bounded to ~1h, not ~24.8 days
// Restore the range CHECK for subsequent tests.
await engine.executeRaw(`ALTER TABLE minion_jobs ADD CONSTRAINT chk_lock_duration_positive CHECK (lock_duration_ms IS NULL OR (lock_duration_ms >= 5000 AND lock_duration_ms <= 3600000))`);
});
});
+314 -12
View File
@@ -210,7 +210,7 @@ describe('MinionQueue: Stall Detection', () => {
await queue.claim('tok1', 30000, 'default', ['sync']);
// Force lock_until to the past
await engine.executeRaw(
"UPDATE minion_jobs SET lock_until = now() - interval '1 second' WHERE id = $1",
"UPDATE minion_jobs SET lock_until = now() - interval '30 seconds' WHERE id = $1",
[job.id]
);
const { requeued, dead } = await queue.handleStalled();
@@ -227,7 +227,7 @@ describe('MinionQueue: Stall Detection', () => {
// First stall: counter 0+1=1 < 3, requeued
await queue.claim('tok1', 30000, 'default', ['sync']);
await engine.executeRaw(
"UPDATE minion_jobs SET lock_until = now() - interval '1 second' WHERE id = $1",
"UPDATE minion_jobs SET lock_until = now() - interval '30 seconds' WHERE id = $1",
[job.id]
);
const r1 = await queue.handleStalled();
@@ -237,7 +237,7 @@ describe('MinionQueue: Stall Detection', () => {
// Second stall: counter 1+1=2 < 3, requeued
await queue.claim('tok2', 30000, 'default', ['sync']);
await engine.executeRaw(
"UPDATE minion_jobs SET lock_until = now() - interval '1 second' WHERE id = $1",
"UPDATE minion_jobs SET lock_until = now() - interval '30 seconds' WHERE id = $1",
[job.id]
);
const r2 = await queue.handleStalled();
@@ -246,7 +246,7 @@ describe('MinionQueue: Stall Detection', () => {
// Third stall: counter 2+1=3 >= 3, dead-lettered
await queue.claim('tok3', 30000, 'default', ['sync']);
await engine.executeRaw(
"UPDATE minion_jobs SET lock_until = now() - interval '1 second' WHERE id = $1",
"UPDATE minion_jobs SET lock_until = now() - interval '30 seconds' WHERE id = $1",
[job.id]
);
const r3 = await queue.handleStalled();
@@ -260,7 +260,7 @@ describe('MinionQueue: Stall Detection', () => {
await engine.executeRaw('UPDATE minion_jobs SET max_stalled = 0 WHERE id = $1', [job.id]);
await queue.claim('tok1', 30000, 'default', ['sync']);
await engine.executeRaw(
"UPDATE minion_jobs SET lock_until = now() - interval '1 second' WHERE id = $1",
"UPDATE minion_jobs SET lock_until = now() - interval '30 seconds' WHERE id = $1",
[job.id]
);
const { requeued, dead } = await queue.handleStalled();
@@ -317,7 +317,7 @@ describe('MinionQueue: #1737 attempt accounting on dead-letter', () => {
// First stall: requeued, attempts_made stays 0 (lease-loss recovery, not an app attempt).
await queue.claim('tok1', 30000, 'default', ['sync']);
await engine.executeRaw(
"UPDATE minion_jobs SET lock_until = now() - interval '1 second' WHERE id = $1",
"UPDATE minion_jobs SET lock_until = now() - interval '30 seconds' WHERE id = $1",
[job.id]
);
const r1 = await queue.handleStalled();
@@ -327,7 +327,7 @@ describe('MinionQueue: #1737 attempt accounting on dead-letter', () => {
// Second stall: dead-lettered, attempts_made now increments.
await queue.claim('tok2', 30000, 'default', ['sync']);
await engine.executeRaw(
"UPDATE minion_jobs SET lock_until = now() - interval '1 second' WHERE id = $1",
"UPDATE minion_jobs SET lock_until = now() - interval '30 seconds' WHERE id = $1",
[job.id]
);
const r2 = await queue.handleStalled();
@@ -444,7 +444,7 @@ describe('MinionQueue: v0.13.1 max_stalled schema default (#219)', () => {
for (let i = 0; i < 4; i++) {
await queue.claim(`tok-${i}`, 30000, 'default', ['noop']);
await engine.executeRaw(
"UPDATE minion_jobs SET lock_until = now() - interval '1 second' WHERE id = $1",
"UPDATE minion_jobs SET lock_until = now() - interval '30 seconds' WHERE id = $1",
[job.id]
);
const { requeued, dead } = await queue.handleStalled();
@@ -456,7 +456,7 @@ describe('MinionQueue: v0.13.1 max_stalled schema default (#219)', () => {
// With stalled_counter now at 4, next stall: 4+1=5 >= 5 = dead.
await queue.claim('tok-final', 30000, 'default', ['noop']);
await engine.executeRaw(
"UPDATE minion_jobs SET lock_until = now() - interval '1 second' WHERE id = $1",
"UPDATE minion_jobs SET lock_until = now() - interval '30 seconds' WHERE id = $1",
[job.id]
);
const { dead } = await queue.handleStalled();
@@ -885,13 +885,13 @@ describe('MinionQueue: Cancel & Retry', () => {
// one requeue stall, then one dead-lettering stall.
await queue.claim('tok1', 30000, 'default', ['sync']);
await engine.executeRaw(
"UPDATE minion_jobs SET lock_until = now() - interval '1 second' WHERE id = $1",
"UPDATE minion_jobs SET lock_until = now() - interval '30 seconds' WHERE id = $1",
[job.id],
);
await queue.handleStalled();
await queue.claim('tok2', 30000, 'default', ['sync']);
await engine.executeRaw(
"UPDATE minion_jobs SET lock_until = now() - interval '1 second' WHERE id = $1",
"UPDATE minion_jobs SET lock_until = now() - interval '30 seconds' WHERE id = $1",
[job.id],
);
const r2 = await queue.handleStalled();
@@ -906,7 +906,7 @@ describe('MinionQueue: Cancel & Retry', () => {
expect(retried!.stalled_counter).toBe(0);
await queue.claim('tok3', 30000, 'default', ['sync']);
await engine.executeRaw(
"UPDATE minion_jobs SET lock_until = now() - interval '1 second' WHERE id = $1",
"UPDATE minion_jobs SET lock_until = now() - interval '30 seconds' WHERE id = $1",
[job.id],
);
const r3 = await queue.handleStalled();
@@ -3203,3 +3203,305 @@ describe('MinionWorker: self-health-check behavior (v0.22.14)', () => {
expect(() => new MinionWorker(engine, {})).not.toThrow();
});
});
// --- v0.46 (#4145 R2-1): inFlight generation-safety ---
describe('MinionWorker: inFlight generation-safety (#4145 R2-1)', () => {
test('a stale execution\'s finally does not delete the reclaimed execution\'s entry', async () => {
const worker = new MinionWorker(engine, { concurrency: 2, pollInterval: 50, lockDuration: 60000 });
// Two gated executions of the SAME job id: A (stale, will be superseded)
// and B (the same-worker re-claim). Each handler invocation blocks on
// its own gate so the test controls the interleave deterministically.
const gates: Array<() => void> = [];
const gatePromises = [
new Promise<void>(r => gates.push(r)),
new Promise<void>(r => gates.push(r)),
];
let invocation = 0;
worker.register('gensafe', async () => {
const idx = invocation++;
await gatePromises[idx];
return { ok: true };
});
const row = await queue.add('gensafe', {});
// Execution A claims + launches.
const claimedA = await queue.claim('tok-A', 60000, 'default', ['gensafe']);
expect(claimedA?.id).toBe(row.id);
(worker as unknown as { launchJob(j: MinionJob, t: string): void }).launchJob(claimedA!, 'tok-A');
// Simulate the post-force-evict requeue (what handleStalled does) and a
// SAME-WORKER re-claim as execution B while A's handler is still alive.
await engine.executeRaw(
`UPDATE minion_jobs SET status='waiting', lock_token=NULL, lock_until=NULL, started_at=NULL WHERE id = $1`,
[row.id]
);
const claimedB = await queue.claim('tok-B', 60000, 'default', ['gensafe']);
expect(claimedB?.id).toBe(row.id);
(worker as unknown as { launchJob(j: MinionJob, t: string): void }).launchJob(claimedB!, 'tok-B');
const inFlight = (worker as unknown as { inFlight: Map<number, { lockToken: string }> }).inFlight;
expect(inFlight.get(row.id)?.lockToken).toBe('tok-B');
// Release stale execution A: its completeJob is fenced-false ("completion
// dropped") and its finally fires. Pre-fix, that finally deleted B's
// entry by bare job.id — the R2-1 generation race.
gates[0]();
await new Promise(r => setTimeout(r, 150));
expect(inFlight.get(row.id)?.lockToken).toBe('tok-B'); // B survived A's finally
// Release B: its OWN finally removes its own entry and completes the row.
gates[1]();
await new Promise(r => setTimeout(r, 150));
expect(inFlight.has(row.id)).toBe(false);
const final = await queue.getJob(row.id);
expect(final!.status).toBe('completed');
});
});
// --- v0.46 (#4145 CDX-7): stall-sweep reclaim grace ---
describe('MinionQueue: stall-sweep reclaim grace (#4145)', () => {
async function activeJobWithLockLapsedMs(msAgo: number): Promise<MinionJob> {
await queue.add('grace-test', {});
const claimed = await queue.claim('tok-grace', 60000, 'default', ['grace-test']);
await engine.executeRaw(
`UPDATE minion_jobs SET lock_until = now() - ($1::double precision * interval '1 millisecond') WHERE id = $2`,
[msAgo, claimed!.id]
);
return claimed!;
}
test('a lock that lapsed WITHIN the grace window is NOT reclaimed (starved-owner head start)', async () => {
const job = await activeJobWithLockLapsedMs(5_000); // grace default = 15_000
const { requeued, dead } = await queue.handleStalled();
expect(requeued).toHaveLength(0);
expect(dead).toHaveLength(0);
const still = await queue.getJob(job.id);
expect(still!.status).toBe('active');
expect(still!.lock_token).toBe('tok-grace');
});
test('a lock that lapsed BEYOND the grace window IS reclaimed', async () => {
const job = await activeJobWithLockLapsedMs(20_000);
const { requeued, dead } = await queue.handleStalled();
expect(requeued).toHaveLength(1);
expect(dead).toHaveLength(0);
const requeuedJob = await queue.getJob(job.id);
expect(requeuedJob!.status).toBe('waiting');
expect(requeuedJob!.lock_token).toBeNull();
});
test('grace=0 restores the exact legacy predicate (lock_until < now())', async () => {
const job = await activeJobWithLockLapsedMs(100);
const { requeued } = await queue.handleStalled(0);
expect(requeued).toHaveLength(1);
const requeuedJob = await queue.getJob(job.id);
expect(requeuedJob!.status).toBe('waiting');
});
test('env knob GBRAIN_MINION_STALL_RECLAIM_GRACE_MS resolves; bad value warns + falls back', async () => {
const { resolveStallReclaimGraceMs, DEFAULT_STALL_RECLAIM_GRACE_MS, _resetStallGraceWarningsForTests } =
await import('../src/core/minions/queue.ts');
_resetStallGraceWarningsForTests();
expect(resolveStallReclaimGraceMs({})).toBe(DEFAULT_STALL_RECLAIM_GRACE_MS);
expect(resolveStallReclaimGraceMs({ GBRAIN_MINION_STALL_RECLAIM_GRACE_MS: '0' })).toBe(0);
expect(resolveStallReclaimGraceMs({ GBRAIN_MINION_STALL_RECLAIM_GRACE_MS: '25000' })).toBe(25_000);
expect(resolveStallReclaimGraceMs({ GBRAIN_MINION_STALL_RECLAIM_GRACE_MS: '-5' })).toBe(DEFAULT_STALL_RECLAIM_GRACE_MS);
expect(resolveStallReclaimGraceMs({ GBRAIN_MINION_STALL_RECLAIM_GRACE_MS: 'abc' })).toBe(DEFAULT_STALL_RECLAIM_GRACE_MS);
// Cap: an absurd digit string must not become Infinity and push the
// sweep cutoff to -infinity (which would disable stalled-job recovery).
expect(resolveStallReclaimGraceMs({ GBRAIN_MINION_STALL_RECLAIM_GRACE_MS: '9'.repeat(40) })).toBe(600_000);
});
test('grace env warn fires once per bad value, not per call (warn-once dedupe)', async () => {
const { resolveStallReclaimGraceMs, _resetStallGraceWarningsForTests } =
await import('../src/core/minions/queue.ts');
_resetStallGraceWarningsForTests();
const captured: string[] = [];
const origWrite = process.stderr.write.bind(process.stderr);
(process.stderr as { write: (chunk: string | Uint8Array) => boolean }).write = (chunk) => {
captured.push(typeof chunk === 'string' ? chunk : Buffer.from(chunk).toString('utf8'));
return true;
};
try {
resolveStallReclaimGraceMs({ GBRAIN_MINION_STALL_RECLAIM_GRACE_MS: 'bogus' });
resolveStallReclaimGraceMs({ GBRAIN_MINION_STALL_RECLAIM_GRACE_MS: 'bogus' });
} finally {
process.stderr.write = origWrite;
}
expect(captured.filter(c => c.includes('GBRAIN_MINION_STALL_RECLAIM_GRACE_MS')).length).toBe(1);
});
});
// --- v0.46 (#4145): per-job lock_duration_ms — three-layer lease resolution ---
describe('MinionQueue: per-job lock lease (#4145)', () => {
test('claim stamps the handler-map default (300s) for subagent and derives lock_until from it', async () => {
await queue.add('subagent', {}, undefined, { allowProtectedSubmit: true });
const before = Date.now();
const claimed = await queue.claim('tok-lease', 30_000, 'default', ['subagent']);
expect(claimed).not.toBeNull();
expect(claimed!.lock_duration_ms).toBe(300_000); // stamped from the map
const horizon = claimed!.lock_until!.getTime() - before;
// lock_until derives from the 300s lease, NOT the worker's 30s default.
expect(horizon).toBeGreaterThan(250_000);
expect(horizon).toBeLessThan(360_000);
});
test('an unmapped handler keeps NULL lease → worker default horizon (legacy behavior)', async () => {
await queue.add('shortling', {});
const before = Date.now();
const claimed = await queue.claim('tok-short', 30_000, 'default', ['shortling']);
expect(claimed!.lock_duration_ms).toBeNull();
const horizon = claimed!.lock_until!.getTime() - before;
expect(horizon).toBeGreaterThan(20_000);
expect(horizon).toBeLessThan(40_000);
});
test('explicit submit value wins over the map and is clamped to [5s, 1h]', async () => {
const explicit = await queue.add('subagent', {}, { lock_duration_ms: 120_000 }, { allowProtectedSubmit: true });
expect(explicit.lock_duration_ms).toBe(120_000);
const floored = await queue.add('floorling', {}, { lock_duration_ms: 1 });
expect(floored.lock_duration_ms).toBe(5_000);
const ceiled = await queue.add('ceiling', {}, { lock_duration_ms: 99_999_999 });
expect(ceiled.lock_duration_ms).toBe(3_600_000);
});
test('claim precedence: an explicit row lease beats the handler map at the claim UPDATE', async () => {
// The claim COALESCE is (row, map, worker default) in that order — if it
// were ever flipped (map before row) the explicit lease would be silently
// overwritten at claim while the add()-time tests stayed green.
await queue.add('subagent', {}, { lock_duration_ms: 120_000 }, { allowProtectedSubmit: true });
const before = Date.now();
const claimed = await queue.claim('tok-precedence', 30_000, 'default', ['subagent']);
expect(claimed!.lock_duration_ms).toBe(120_000); // row wins, not the 300s map
const horizon = claimed!.lock_until!.getTime() - before;
expect(horizon).toBeGreaterThan(90_000);
expect(horizon).toBeLessThan(150_000);
});
test('worker renews with the per-job lease, not the worker default (launchJob wiring)', async () => {
// GAP-1 pin: effectiveLockMs = row lease drives BOTH the renewal call's
// duration arg and the cadence. A 5s lease (clamp floor) under a worker
// configured at 60s yields a 2.5s cadence — observable within test time.
const worker = new MinionWorker(engine, { concurrency: 1, pollInterval: 50, lockDuration: 60_000 });
let release: () => void = () => {};
const gate = new Promise<void>(r => { release = r; });
worker.register('leased-renewal', async () => { await gate; return { ok: true }; });
await queue.add('leased-renewal', {}, { lock_duration_ms: 5_000 });
const claimed = await queue.claim('tok-lease-renew', 5_000, 'default', ['leased-renewal']);
expect(claimed!.lock_duration_ms).toBe(5_000);
const durs: number[] = [];
const q = (worker as unknown as { queue: MinionQueue }).queue;
const orig = q.renewLock.bind(q);
q.renewLock = ((id: number, tok: string, dur: number, opts?: { signal?: AbortSignal }) => {
durs.push(dur);
return orig(id, tok, dur, opts);
}) as typeof q.renewLock;
(worker as unknown as { launchJob(j: MinionJob, t: string): void }).launchJob(claimed!, 'tok-lease-renew');
// Cadence = min(5000/2, 60000) = 2500ms; wait for at least one tick.
const started = Date.now();
while (durs.length === 0 && Date.now() - started < 8_000) {
await new Promise(r => setTimeout(r, 100));
}
release();
await new Promise(r => setTimeout(r, 150));
expect(durs.length).toBeGreaterThanOrEqual(1);
// Every renewal used the per-job 5s lease — NOT the worker's 60s default.
expect(new Set(durs)).toEqual(new Set([5_000]));
});
test('MCP submit_job threads lock_duration_ms through the shared clamp (round-trip)', async () => {
const { operationsByName } = await import('../src/core/operations.ts');
const op = operationsByName['submit_job'];
const ctx = { engine, remote: false, dryRun: false } as never;
const clamped = await op.handler(ctx, { name: 'lease-op-test', lock_duration_ms: 99_999_999 }) as { id: number };
expect((await queue.getJob(clamped.id))!.lock_duration_ms).toBe(3_600_000); // ceiling
const exact = await op.handler(ctx, { name: 'lease-op-test', lock_duration_ms: 60_000 }) as { id: number };
expect((await queue.getJob(exact.id))!.lock_duration_ms).toBe(60_000);
// Boundary pin: 0 is falsy through the op's `|| undefined` coercion and
// falls to the handler-map/worker default (NULL for an unmapped name) —
// the documented remote semantics, distinct from the CLI's exit-1 reject.
const zero = await op.handler(ctx, { name: 'lease-op-test', lock_duration_ms: 0 }) as { id: number };
expect((await queue.getJob(zero.id))!.lock_duration_ms).toBeNull();
});
test('idempotent re-submit never mutates the first submitter\'s lease (INSERT-only)', async () => {
const first = await queue.add('lease-idem', {}, { lock_duration_ms: 60_000, idempotency_key: 'lease-key-1' });
expect(first.lock_duration_ms).toBe(60_000);
const second = await queue.add('lease-idem', {}, { lock_duration_ms: 600_000, idempotency_key: 'lease-key-1' });
expect(second.id).toBe(first.id);
expect(second.lock_duration_ms).toBe(60_000); // unchanged
});
test('REGRESSION pin: NULL-lease rows keep the exact legacy wall-clock null-fallback', async () => {
// handleWallClockTimeouts' null-timeout branch is COALESCE(lock_duration_ms, $1)
// — rows WITHOUT a lease must behave exactly as before (worker default drives
// the 2x * max_stalled bound), and rows WITH a lease use their own.
const legacy = await queue.add('wallclock-legacy', {}, { max_stalled: 1 });
await queue.claim('tok-wc-legacy', 1_000, 'default', ['wallclock-legacy']);
// started 10s ago; NULL lease → threshold = 2 * 1000ms (worker default $1) * 1 = 2s → dead.
await engine.executeRaw(
`UPDATE minion_jobs SET started_at = now() - interval '10 seconds', timeout_ms = NULL, timeout_at = NULL WHERE id = $1`,
[legacy.id]
);
const killedLegacy = await queue.handleWallClockTimeouts(1_000);
expect(killedLegacy.map(j => j.id)).toContain(legacy.id);
// Same shape WITH a 60s lease: threshold = 2 * 60000 * 1 = 120s → survives 10s.
const leased = await queue.add('wallclock-leased', {}, { max_stalled: 1, lock_duration_ms: 60_000 });
await queue.claim('tok-wc-leased', 1_000, 'default', ['wallclock-leased']);
await engine.executeRaw(
`UPDATE minion_jobs SET started_at = now() - interval '10 seconds', timeout_ms = NULL, timeout_at = NULL WHERE id = $1`,
[leased.id]
);
const killedLeased = await queue.handleWallClockTimeouts(1_000);
expect(killedLeased.map(j => j.id)).not.toContain(leased.id);
const survivor = await queue.getJob(leased.id);
expect(survivor!.status).toBe('active');
});
test('repeated infrastructure evictions eventually dead-letter via max_stalled (lifetime accumulation pin)', async () => {
// The "no attempt burned" contract survives only max_stalled - 1
// requeues: stalled_counter accumulates across the job's lifetime and
// the final stall burns one attempt and dead-letters. Known coverage
// gap flagged in the #4145 review — pinned here.
const job = await queue.add('evict-accumulate', {}, { max_stalled: 3 });
for (let round = 1; round <= 2; round++) {
const claimed = await queue.claim(`tok-ev-${round}`, 30_000, 'default', ['evict-accumulate']);
expect(claimed!.id).toBe(job.id);
await engine.executeRaw(
`UPDATE minion_jobs SET lock_until = now() - interval '30 seconds' WHERE id = $1`,
[job.id]
);
const { requeued, dead } = await queue.handleStalled();
expect(requeued.map(j => j.id)).toContain(job.id);
expect(dead).toHaveLength(0);
const after = await queue.getJob(job.id);
expect(after!.stalled_counter).toBe(round);
expect(after!.attempts_made).toBe(0); // no attempt burned on requeue
}
// Third stall: stalled_counter + 1 >= max_stalled → dead + attempt burned.
await queue.claim('tok-ev-3', 30_000, 'default', ['evict-accumulate']);
await engine.executeRaw(
`UPDATE minion_jobs SET lock_until = now() - interval '30 seconds' WHERE id = $1`,
[job.id]
);
const finalSweep = await queue.handleStalled();
expect(finalSweep.dead.map(j => j.id)).toContain(job.id);
const final = await queue.getJob(job.id);
expect(final!.status).toBe('dead');
expect(final!.attempts_made).toBe(1);
expect(final!.error_text).toBe('max stalled count exceeded');
});
});
+2 -2
View File
@@ -52,7 +52,7 @@ test('stall-exhausted child → child_done(dead) in parent inbox + parent unbloc
const claimed = await queue.claim('tok-stall', 30_000, 'default', ['child', 'aggregator']);
expect(claimed?.id).toBe(child.id);
await engine.executeRaw(
`UPDATE minion_jobs SET lock_until = now() - interval '1 second' WHERE id = $1`, [child.id],
`UPDATE minion_jobs SET lock_until = now() - interval '30 seconds' WHERE id = $1`, [child.id],
);
const { requeued, dead } = await queue.handleStalled();
@@ -85,7 +85,7 @@ test('stall-requeued child (budget left) does NOT touch the parent', async () =>
const claimed = await queue.claim('tok-stall2', 30_000, 'default', ['child', 'aggregator']);
expect(claimed?.id).toBe(child.id);
await engine.executeRaw(
`UPDATE minion_jobs SET lock_until = now() - interval '1 second' WHERE id = $1`, [child.id],
`UPDATE minion_jobs SET lock_until = now() - interval '30 seconds' WHERE id = $1`, [child.id],
);
const { requeued, dead } = await queue.handleStalled();
+2 -2
View File
@@ -73,7 +73,7 @@ test("failJob's delayed branch clears started_at (terminal branches keep it)", a
test("handleStalled's requeue branch clears started_at", async () => {
const { id } = await addAndClaim();
await engine.executeRaw(
`UPDATE minion_jobs SET lock_until = now() - interval '1 second' WHERE id = $1`, [id],
`UPDATE minion_jobs SET lock_until = now() - interval '30 seconds' WHERE id = $1`, [id],
);
const { requeued } = await queue.handleStalled();
expect(requeued.map(j => j.id)).toContain(id);
@@ -146,7 +146,7 @@ test('red-team 5th path: a re-claimed aggregator parent survives the wall-clock
// Child stalls to death → killJobs unblocks the parent.
await queue.claim('tok-wc', 30_000, 'default', ['child-wc', 'agg-wallclock']);
await engine.executeRaw(
`UPDATE minion_jobs SET lock_until = now() - interval '1 second' WHERE id = $1`, [child.id],
`UPDATE minion_jobs SET lock_until = now() - interval '30 seconds' WHERE id = $1`, [child.id],
);
await queue.handleStalled();
expect(await jobStatus(parent.id)).toBe('waiting');
+12
View File
@@ -103,6 +103,18 @@ describe('relationalFanout', () => {
expect(a!.path[a!.path.length - 1]).toBe('people/investor-a');
});
test('equal-depth multi-seed tie picks the lexicographically-smallest path (deterministic winner)', async () => {
// people/investor-a is reachable at depth 1 from BOTH seeds; parity alone
// would pass if both engines agreed on a wrong-but-deterministic pick
// (e.g. an ORDER BY direction flip). Pin the WINNER: the final
// lexicographic tie-break must choose the smallest path string, whose
// first hop is 'companies/other-co' (< 'companies/widget-co').
const rows = await eng.relationalFanout(['companies/widget-co', 'companies/other-co'], { direction: 'both' });
const a = rows.find(r => r.slug === 'people/investor-a');
expect(a).toBeDefined();
expect(a!.path[0]).toBe('companies/other-co');
});
test('empty seeds → []', async () => {
expect(await eng.relationalFanout([])).toEqual([]);
});
+31 -4
View File
@@ -41,7 +41,23 @@ beforeAll(async () => {
afterAll(async () => {
await engine.disconnect();
rmSync(dir, { recursive: true, force: true });
// Best-effort tmpdir cleanup with one retry. Bun's recursive rmSync has
// EFAULT'd here on CI (bun 1.3.13, ubuntu-24.04) immediately after the
// WASM engine teardown — a runtime flake, not a test failure. bun treats
// a throwing afterAll as an "(unnamed)" failed test and reds the shard;
// the OS reaps tmpdir anyway, so cleanup must never fail the suite.
try {
rmSync(dir, { recursive: true, force: true });
} catch {
await new Promise((r) => setTimeout(r, 50));
try {
rmSync(dir, { recursive: true, force: true });
} catch (e) {
console.warn(
`[run-child-entry.test] tmpdir cleanup failed (non-fatal): ${e instanceof Error ? e.message : String(e)}`,
);
}
}
});
beforeEach(async () => {
@@ -168,6 +184,7 @@ describe('runChildJobEntry', () => {
const resultPath = join(dir, `sigterm-${job.id}.json`);
let ctxSignalAbortedAtShutdown: boolean | null = null;
const listenersBefore = new Set(process.listeners('SIGTERM'));
const entry = runChildJobEntry(
engine,
{ jobId: job.id, lockToken: 'parent-tok-1', resultPath, parentPid: 0 },
@@ -184,9 +201,19 @@ describe('runChildJobEntry', () => {
}),
);
await new Promise((r) => setTimeout(r, 100));
// Trigger the entry's process.on('SIGTERM') handler in-process without
// sending a real signal to the test runner.
(process as unknown as { emit: (event: string) => boolean }).emit('SIGTERM');
// Trigger ONLY the SIGTERM listener(s) the entry registered. A bare
// process.emit('SIGTERM') broadcasts to EVERY listener in the shared
// bun test process — including process-cleanup.ts's leaked handler,
// whose runCleanupPass().finally(process.exit(143)) kills the whole
// shard mid-suite when an earlier file installed it. That exit code
// reads as rc=143 and gets misclassified as an "external kill" by
// run-unit-parallel.sh (bit three consecutive suite runs under host
// load before being traced here).
const added = process
.listeners('SIGTERM')
.filter((l) => !listenersBefore.has(l));
expect(added.length).toBeGreaterThan(0);
for (const l of added) (l as (...args: unknown[]) => void)('SIGTERM');
const code = await entry;
expect(code).toBe(0);
+10 -5
View File
@@ -144,9 +144,11 @@ describe('G: tickInFlight re-entrancy guard', () => {
test('the setInterval callback checks tickInFlight and bails on re-entry', () => {
const launchJobBody = extractFunctionBody(workerSource, 'private launchJob(');
// The pattern is `if (tickInFlight) return;` — minor whitespace
// variation tolerated.
expect(launchJobBody).toMatch(/if\s*\(\s*tickInFlight\s*\)\s*return/);
// v0.46 (#4145): the guard grew a block body — it counts the overlap
// skip (CDX-13 telemetry) before bailing. The load-bearing shape is
// unchanged: check tickInFlight, return WITHOUT scheduling a tick.
expect(launchJobBody).toMatch(/if\s*\(\s*tickInFlight\s*\)\s*\{[^}]*return/);
expect(launchJobBody).toMatch(/overlapSkips\s*\+=\s*1/);
});
test('the setInterval callback sets tickInFlight=true before scheduling work', () => {
@@ -221,8 +223,11 @@ describe('E: universal grace-evict listener (D8b)', () => {
// Find the addEventListener and look in its function body.
const listenerIdx = launchJobBody.indexOf("abort.signal.addEventListener('abort'");
expect(listenerIdx).toBeGreaterThan(-1);
// Grab ~1500 chars after the listener to capture its body.
const listenerWindow = launchJobBody.slice(listenerIdx, listenerIdx + 1500);
// Grab ~4500 chars after the listener to capture its body (v0.46:
// the grace-evict log gained the #4145 abortMeta/telemetry block AND
// the #4151 isolation-mode failJob guard commentary, both of which sit
// between the listener head and the 30_000 literal).
const listenerWindow = launchJobBody.slice(listenerIdx, listenerIdx + 4500);
expect(listenerWindow).toMatch(/30_000|30000/);
});
});
+350 -45
View File
@@ -38,9 +38,9 @@ import { withEnv } from './helpers/with-env.ts';
// --- fakes ----------------------------------------------------------------
interface AuditLog {
failures: Array<{ jobId: number; jobName: string; attempt: number; err: unknown }>;
recoveries: Array<{ jobId: number; jobName: string; recoveredAfterAttempts: number }>;
gaveUps: Array<{ jobId: number; jobName: string; totalFailures: number; err: unknown }>;
failures: Array<{ jobId: number; jobName: string; attempt: number; err: unknown; ctx?: unknown }>;
recoveries: Array<{ jobId: number; jobName: string; recoveredAfterAttempts: number; ctx?: unknown }>;
gaveUps: Array<{ jobId: number; jobName: string; totalFailures: number; err: unknown; ctx?: unknown }>;
}
function freshAudit(): { sink: LockRenewalAuditSinkLike; log: AuditLog } {
@@ -48,12 +48,12 @@ function freshAudit(): { sink: LockRenewalAuditSinkLike; log: AuditLog } {
return {
log,
sink: {
logFailure: (jobId, jobName, attempt, err) =>
log.failures.push({ jobId, jobName, attempt, err }),
logSuccessAfterFailure: (jobId, jobName, recoveredAfterAttempts) =>
log.recoveries.push({ jobId, jobName, recoveredAfterAttempts }),
logGaveUp: (jobId, jobName, totalFailures, err) =>
log.gaveUps.push({ jobId, jobName, totalFailures, err }),
logFailure: (jobId, jobName, attempt, err, ctx) =>
log.failures.push({ jobId, jobName, attempt, err, ctx }),
logSuccessAfterFailure: (jobId, jobName, recoveredAfterAttempts, ctx) =>
log.recoveries.push({ jobId, jobName, recoveredAfterAttempts, ctx }),
logGaveUp: (jobId, jobName, totalFailures, err, ctx) =>
log.gaveUps.push({ jobId, jobName, totalFailures, err, ctx }),
},
};
}
@@ -88,6 +88,7 @@ const DEFAULT_KNOBS: LockRenewalKnobs = {
maxFailuresForAudit: 3,
callTimeoutMs: 10_000,
safetyMarginMs: 5_000,
hardEvictMs: 60_000, // 2 × lockDuration (the #4145 backstop)
};
function makeState(overrides?: Partial<LockRenewalState>): LockRenewalState {
@@ -100,6 +101,11 @@ function makeState(overrides?: Partial<LockRenewalState>): LockRenewalState {
lastSuccessfulRenewalAt: 0,
consecutiveFailures: 0,
cancelled: () => false,
// v0.46 (#4145) telemetry fields: cadence for lateness math, seeded
// previous-tick timestamp, and the worker-maintained overlap counter.
intervalMs: DEFAULT_LOCK_MS / 2,
lastTickFiredAt: 0,
overlapSkips: 0,
...overrides,
};
}
@@ -178,10 +184,12 @@ describe('runLockRenewalTick: failure counter + audit', () => {
});
});
describe('runLockRenewalTick: time-based abort', () => {
test('case 4 — sustained throws past deadline returns should_abort, gave_up logged', async () => {
describe('runLockRenewalTick: verify-before-evict + hard backstop (#4145)', () => {
test('case 4 — sustained throws past the SOFT deadline are DEFERRED (verify attempted), abort only past hardEvictMs', async () => {
const audit = freshAudit();
// deadline = 30000 - 5000 = 25000; we've been failing for 26s.
// Soft deadline = 30000 - 5000 = 25000; hardEvict = 60000.
// At 26s of failure the pre-#4145 code aborted — the incident. Now the
// tick attempts a verify (which also throws here) and DEFERS.
const deps: LockRenewalDeps = {
renewLock: async () => { throw new Error('persistent outage'); },
audit: audit.sink,
@@ -189,46 +197,177 @@ describe('runLockRenewalTick: time-based abort', () => {
setTimeout: makeFakeTimer().setTimeout,
};
const state = makeState({ lastSuccessfulRenewalAt: 0, consecutiveFailures: 2 });
const result = await runLockRenewalTick(deps, state);
expect(result).toEqual({ kind: 'should_abort', reason: 'lock-renewal-failed' });
expect(audit.log.failures).toHaveLength(1);
const deferred = await runLockRenewalTick(deps, state);
expect(deferred).toEqual({ kind: 'ok' });
// Primary attempt (3) + failed verify (4), the latter deadline_deferred.
expect(state.consecutiveFailures).toBe(4);
expect(audit.log.failures).toHaveLength(2);
expect(audit.log.failures[1].ctx).toMatchObject({ deadline_deferred: true, cause: 'refused' });
expect(audit.log.gaveUps).toHaveLength(0);
// Past the hard backstop the tick gives up: primary (5) + verify (6),
// gave_up carries the classified cause + starvation telemetry.
// lateness = max(0, 61000 - 26000 - 15000) = 20000.
const hardDeps: LockRenewalDeps = { ...deps, now: () => 61_000 };
const result = await runLockRenewalTick(hardDeps, state);
expect(result).toMatchObject({
kind: 'should_abort',
reason: 'lock-renewal-failed',
cause: 'refused',
sinceLastSuccessMs: 61_000,
latenessMs: 20_000,
overlapSkips: 0,
});
expect(state.consecutiveFailures).toBe(6);
expect(audit.log.gaveUps).toHaveLength(1);
expect(audit.log.gaveUps[0].totalFailures).toBe(3);
expect(audit.log.gaveUps[0].totalFailures).toBe(6);
});
test('case 10 — time-based abort fires BEFORE count-based threshold', async () => {
// Critical regression: deadline at 25s, 5 failures over 30s.
// count-based (3-strike) would have aborted at failure #3 — but
// failure #3 happens at t=15s, well inside the 25s deadline.
// Time-based correctly waits until the deadline crosses.
test('case 10 — INCIDENT REPLAY: renewal times out under starvation, verify succeeds → job survives', async () => {
// The #4145 incident shape: the event loop starves, the renewal's
// 10s race timeout wins even though the DB is healthy (external
// SELECT 1 probes ran 32ms). Pre-fix: abort at the 25s deadline,
// discarding ~173s of LLM work. Post-fix: ONE fenced verify — the
// DB is the authority — recovers the lease and the job survives.
const audit = freshAudit();
let calls = 0;
const timer = makeFakeTimer();
const deps: LockRenewalDeps = {
renewLock: async () => {
calls++;
if (calls === 1) return new Promise<boolean>(() => { /* starved: never settles */ });
return true; // the verify — DB was healthy all along
},
audit: audit.sink,
now: () => 26_000, // past the soft deadline of 25000
setTimeout: timer.setTimeout,
};
const state = makeState({ lastSuccessfulRenewalAt: 0 });
const pending = runLockRenewalTick(deps, state);
timer.runAll(); // fire the primary race timeout (the starvation symptom)
const result = await pending;
expect(result).toEqual({ kind: 'ok' }); // NO abort — the incident fix
expect(state.consecutiveFailures).toBe(0); // verify-success resets
expect(state.lastSuccessfulRenewalAt).toBe(26_000);
expect(audit.log.failures).toHaveLength(1); // the primary call-timeout
expect(audit.log.failures[0].ctx).toMatchObject({ cause: 'call-timeout' });
expect(audit.log.recoveries).toHaveLength(1);
expect(audit.log.recoveries[0].ctx).toMatchObject({ via: 'verify' });
expect(audit.log.gaveUps).toHaveLength(0);
});
test('case 10b — verify returns fenced-false: CERTAIN loss → lock_lost via verify', async () => {
const audit = freshAudit();
let calls = 0;
const deps: LockRenewalDeps = {
renewLock: async () => {
calls++;
if (calls === 1) throw new Error('outage');
return false; // the stall sweep reclaimed the row during the blip
},
audit: audit.sink,
now: () => 26_000,
setTimeout: makeFakeTimer().setTimeout,
};
const state = makeState({ lastSuccessfulRenewalAt: 0 });
const result = await runLockRenewalTick(deps, state);
expect(result).toEqual({ kind: 'lock_lost', cause: 'fenced-lost', via: 'verify' });
expect(audit.log.gaveUps).toHaveLength(0); // certain loss ≠ infrastructure gave-up
});
test('case 10c — CDX-4 cadence quantization: 300s lease / 60s cadence verifies at 240s with lease remaining', async () => {
// With the bare `>= deadline` gate there is NO tick between 240s and
// lease expiry (300s): deadline 270s is unreachable and the first
// eligible tick is already past expiry. The next-tick-too-late form
// (sinceLastSuccess + intervalMs >= deadline) verifies at 240s.
const audit = freshAudit();
const knobs: LockRenewalKnobs = {
maxFailuresForAudit: 3,
callTimeoutMs: 10_000,
safetyMarginMs: 5_000,
callTimeoutMs: 15_000,
safetyMarginMs: 30_000, // deadline = 270_000
hardEvictMs: 600_000,
};
let nowMs = 0;
let calls = 0;
const deps: LockRenewalDeps = {
renewLock: async () => { throw new Error('outage'); },
renewLock: async () => {
calls++;
if (calls === 1) throw new Error('blip at the 240s tick');
return true; // verify recovers with 60s of lease left
},
audit: audit.sink,
now: () => nowMs,
now: () => 240_000,
setTimeout: makeFakeTimer().setTimeout,
};
const state = makeState({ knobs, lastSuccessfulRenewalAt: 0 });
const state = makeState({
lockDurationMs: 300_000,
knobs,
intervalMs: 60_000,
lastSuccessfulRenewalAt: 0,
lastTickFiredAt: 180_000,
});
const result = await runLockRenewalTick(deps, state);
expect(result).toEqual({ kind: 'ok' });
expect(calls).toBe(2); // primary + verify — the verify DID fire at 240s
expect(audit.log.recoveries[0].ctx).toMatchObject({ via: 'verify' });
// Five sequential failures at t=5, 10, 15, 20, 26.
for (const t of [5_000, 10_000, 15_000, 20_000]) {
nowMs = t;
const r = await runLockRenewalTick(deps, state);
expect(r.kind).toBe('ok'); // within deadline despite counter > maxFailuresForAudit
}
expect(state.consecutiveFailures).toBe(4);
expect(audit.log.gaveUps).toHaveLength(0);
// Control: at the 180s tick (180 + 60 = 240 < 270) no verify fires.
calls = 0;
const controlState = makeState({
lockDurationMs: 300_000,
knobs,
intervalMs: 60_000,
lastSuccessfulRenewalAt: 0,
lastTickFiredAt: 120_000,
});
const controlDeps: LockRenewalDeps = {
...deps,
renewLock: async () => { calls++; throw new Error('blip'); },
now: () => 180_000,
};
expect(await runLockRenewalTick(controlDeps, controlState)).toEqual({ kind: 'ok' });
expect(calls).toBe(1); // primary only — deferred to the next tick
});
nowMs = 26_000; // crosses deadline of 25000
const final = await runLockRenewalTick(deps, state);
expect(final).toEqual({ kind: 'should_abort', reason: 'lock-renewal-failed' });
expect(audit.log.gaveUps).toHaveLength(1);
test('case 10d — ENG-E1 pin: 30s default verifies on the FIRST failed tick (15s), strictly safer than abort-at-30s', async () => {
// interval 15s, deadline 25s: at the t=15s tick, 15000 + 15000 >= 25000
// → the verify fires immediately on the first failure. This is the
// accepted timing behavior — a renewal(≤10s) + verify(≤10s) pair can
// span 20s and skip one tick via tickInFlight; benign because a
// verify-success re-extends the lease.
let calls = 0;
const deps: LockRenewalDeps = {
renewLock: async () => {
calls++;
if (calls === 1) throw new Error('first-tick blip');
return true;
},
audit: freshAudit().sink,
now: () => 15_000,
setTimeout: makeFakeTimer().setTimeout,
};
const state = makeState({ lastSuccessfulRenewalAt: 0 });
expect(await runLockRenewalTick(deps, state)).toEqual({ kind: 'ok' });
expect(calls).toBe(2);
expect(state.lastSuccessfulRenewalAt).toBe(15_000);
});
test('case 10e — cancelled() flips mid-verify: returns cancelled, no abort', async () => {
let cancelled = false;
let calls = 0;
const deps: LockRenewalDeps = {
renewLock: async () => {
calls++;
if (calls === 1) throw new Error('outage');
cancelled = true; // the job ends while the verify is in flight
return true;
},
audit: freshAudit().sink,
now: () => 26_000,
setTimeout: makeFakeTimer().setTimeout,
};
const state = makeState({ lastSuccessfulRenewalAt: 0, cancelled: () => cancelled });
const result = await runLockRenewalTick(deps, state);
expect(result).toEqual({ kind: 'cancelled' });
});
});
@@ -243,7 +382,9 @@ describe('runLockRenewalTick: lock_lost (token mismatch)', () => {
};
const state = makeState({ lastSuccessfulRenewalAt: 0 });
const result = await runLockRenewalTick(deps, state);
expect(result).toEqual({ kind: 'lock_lost' });
// v0.46 (#4145): lock_lost names its cause — the fenced UPDATE matched
// 0 rows, the only CERTAIN loss signal.
expect(result).toEqual({ kind: 'lock_lost', cause: 'fenced-lost', via: 'renewal' });
expect(audit.log.failures).toHaveLength(0);
expect(audit.log.gaveUps).toHaveLength(0);
expect(audit.log.recoveries).toHaveLength(0);
@@ -374,12 +515,13 @@ describe('runLockRenewalTick: audit defense-in-depth (codex C4)', () => {
const deps: LockRenewalDeps = {
renewLock: async () => { throw new Error('outage'); },
audit,
now: () => 26_000,
// Past hardEvictMs (60000) so the verify-throws path reaches gave_up.
now: () => 61_000,
setTimeout: makeFakeTimer().setTimeout,
};
const state = makeState({ lastSuccessfulRenewalAt: 0 });
const result = await runLockRenewalTick(deps, state);
expect(result).toEqual({ kind: 'should_abort', reason: 'lock-renewal-failed' });
expect(result).toMatchObject({ kind: 'should_abort', reason: 'lock-renewal-failed' });
});
test('case 11c — audit.logSuccessAfterFailure throws: tick still returns ok, counter resets', async () => {
@@ -482,6 +624,42 @@ describe('resolveLockRenewalKnobs', () => {
// a deliberate two-line edit (default + this test).
expect(resolveLockRenewalKnobs({}, 30_000).maxFailuresForAudit).toBe(3);
});
test('case 15a — hardEvictMs defaults to 2×lockDuration; env override + floor to soft deadline (#4145)', () => {
_resetKnobWarningsForTests();
expect(resolveLockRenewalKnobs({}, 30_000).hardEvictMs).toBe(60_000);
expect(resolveLockRenewalKnobs({ GBRAIN_LOCK_RENEWAL_HARD_EVICT_MS: '120000' }, 30_000).hardEvictMs).toBe(120_000);
// Below the soft deadline (25000) → warn-and-floor to the deadline.
const floored = resolveLockRenewalKnobs({ GBRAIN_LOCK_RENEWAL_HARD_EVICT_MS: '1000' }, 30_000);
expect(floored.hardEvictMs).toBe(25_000);
});
test('case 15b — CDX-10 relational validation: margin >= lease/2 and callTimeout > cadence are clamped', () => {
_resetKnobWarningsForTests();
// Margin 20000 >= 30000/2 → clamped back to the default (5000).
const m = resolveLockRenewalKnobs({ GBRAIN_LOCK_RENEWAL_SAFETY_MARGIN_MS: '20000' }, 30_000);
expect(m.safetyMarginMs).toBe(5_000);
// Call timeout 20000 > cadence 15000 → clamped to the cadence.
const c = resolveLockRenewalKnobs({ GBRAIN_LOCK_RENEWAL_CALL_TIMEOUT_MS: '20000' }, 30_000, 15_000);
expect(c.callTimeoutMs).toBe(15_000);
// A valid env override still wins untouched (env-beats-default, passes validation).
const ok = resolveLockRenewalKnobs({ GBRAIN_LOCK_RENEWAL_CALL_TIMEOUT_MS: '12000' }, 30_000, 15_000);
expect(ok.callTimeoutMs).toBe(12_000);
});
test('case 15c — per-job lease knob derivation: 300s lease gets capped 15s/30s defaults + 600s hardEvict', () => {
_resetKnobWarningsForTests();
const knobs = resolveLockRenewalKnobs({}, 300_000, 60_000);
expect(knobs.hardEvictMs).toBe(600_000);
// The lock/3 and lock/6 derivations CAP at 15s/30s for long leases —
// a 100s call timeout would wedge tickInFlight across cadence windows.
expect(knobs.callTimeoutMs).toBe(15_000);
expect(knobs.safetyMarginMs).toBe(30_000);
// 30s worker default keeps today's numbers exactly.
const legacy = resolveLockRenewalKnobs({}, 30_000, 15_000);
expect(legacy.callTimeoutMs).toBe(10_000);
expect(legacy.safetyMarginMs).toBe(5_000);
});
});
// issue #1678 (Codex #2): the bounded reconnect-once hook. NOT a withRetry on
@@ -553,23 +731,150 @@ describe('runLockRenewalTick: reconnect-once dep (issue #1678)', () => {
expect(reconnectCalls).toBe(0);
});
test('reconnect is NOT called when the tick aborts at the deadline', async () => {
test('reconnect IS called on a deadline DEFERRAL (CEO-F3: next tick needs a live pool)', async () => {
let reconnectCalls = 0;
const deps: LockRenewalDeps = {
renewLock: async () => { throw new Error('write CONNECTION_ENDED'); },
audit: freshAudit().sink,
// sinceLastSuccess = 30000 - 0 = 30000 >= deadline (30000-5000=25000) → abort
// Past the soft deadline (25000) but inside hardEvict (60000):
// primary throw → verify throw → DEFER, reconnect-once for next tick.
now: () => 30_000,
setTimeout: makeFakeTimer().setTimeout,
reconnect: async () => { reconnectCalls++; },
};
const state = makeState({ lastSuccessfulRenewalAt: 0 });
const result = await runLockRenewalTick(deps, state);
expect(result).toEqual({ kind: 'should_abort', reason: 'lock-renewal-failed' });
expect(result).toEqual({ kind: 'ok' }); // deferred, not aborted
expect(reconnectCalls).toBe(1);
});
test('reconnect is NOT called when the tick gives up past hardEvictMs', async () => {
let reconnectCalls = 0;
const deps: LockRenewalDeps = {
renewLock: async () => { throw new Error('write CONNECTION_ENDED'); },
audit: freshAudit().sink,
now: () => 61_000, // past hardEvict (60000) → gave_up
setTimeout: makeFakeTimer().setTimeout,
reconnect: async () => { reconnectCalls++; },
};
const state = makeState({ lastSuccessfulRenewalAt: 0 });
const result = await runLockRenewalTick(deps, state);
expect(result).toMatchObject({ kind: 'should_abort', reason: 'lock-renewal-failed' });
expect(reconnectCalls).toBe(0); // pointless to reconnect when we're giving up the lock
});
});
// =============================================================================
// v0.46 (#4145) — failure-cause classification + starvation telemetry
// =============================================================================
describe('runLockRenewalTick: telemetry (issue #4145)', () => {
test('case 13a — race timeout classifies as call-timeout (named error, not message-sniff)', async () => {
const audit = freshAudit();
const timer = makeFakeTimer();
const deps: LockRenewalDeps = {
renewLock: () => new Promise<boolean>(() => { /* hangs forever */ }),
audit: audit.sink,
now: () => 61_000, // past hardEvict so the verify-throws path aborts
setTimeout: timer.setTimeout,
};
const state = makeState({ lastSuccessfulRenewalAt: 0 });
const pending = runLockRenewalTick(deps, state);
timer.runAll(); // fire the PRIMARY race timeout
await new Promise(r => globalThis.setTimeout(r, 0)); // let the catch schedule the verify
timer.runAll(); // fire the VERIFY race timeout
const result = await pending;
expect(result).toMatchObject({ kind: 'should_abort', cause: 'call-timeout' });
});
test('case 13b — audit failure events carry cause + lateness + overlap_skips ctx (primary + deferred verify)', async () => {
const ctxLog: unknown[] = [];
const audit: LockRenewalAuditSinkLike = {
logFailure: (_id, _name, _attempt, _err, ctx) => { ctxLog.push(ctx); },
logSuccessAfterFailure: () => { /* noop */ },
logGaveUp: () => { /* noop */ },
};
const deps: LockRenewalDeps = {
renewLock: async () => { throw new Error('outage'); },
audit,
// lateness = max(0, 20000 - 0 - 15000) = 5000. 20000 + 15000 >= 25000
// → the verify fires (and also throws) → a second, deferred failure.
now: () => 20_000,
setTimeout: makeFakeTimer().setTimeout,
loadSnapshot: () => ({ load1: 28.5, cores: 32 }),
};
const state = makeState({ lastSuccessfulRenewalAt: 0, overlapSkips: 3 });
const result = await runLockRenewalTick(deps, state);
expect(result).toEqual({ kind: 'ok' });
expect(ctxLog).toHaveLength(2);
expect(ctxLog[0]).toMatchObject({
cause: 'refused',
lateness_ms: 5_000,
overlap_skips: 3,
load1: 28.5,
cores: 32,
});
expect(ctxLog[1]).toMatchObject({ cause: 'refused', deadline_deferred: true });
expect(state.consecutiveFailures).toBe(2); // primary + verify each count
});
test('case 13c — a THROWING loadSnapshot never breaks the tick (CEO-F2)', async () => {
const audit = freshAudit();
const deps: LockRenewalDeps = {
renewLock: async () => { throw new Error('outage'); },
audit: audit.sink,
now: () => 61_000, // past hardEvict → the verify-throws path aborts
setTimeout: makeFakeTimer().setTimeout,
loadSnapshot: () => { throw new Error('os.loadavg exploded'); },
};
const state = makeState({ lastSuccessfulRenewalAt: 0 });
const result = await runLockRenewalTick(deps, state);
// Still aborts cleanly; load fields simply absent.
expect(result).toMatchObject({ kind: 'should_abort', cause: 'refused' });
expect('load1' in result).toBe(false);
});
test('case 13d — onRenewalSuccess fires on success (R2-9 histogram reset hook) and its throw is swallowed', async () => {
let resets = 0;
const okDeps: LockRenewalDeps = {
renewLock: async () => true,
audit: freshAudit().sink,
now: () => 1000,
setTimeout: makeFakeTimer().setTimeout,
onRenewalSuccess: () => { resets++; },
};
expect(await runLockRenewalTick(okDeps, makeState())).toEqual({ kind: 'ok' });
expect(resets).toBe(1);
const throwingDeps: LockRenewalDeps = {
...okDeps,
onRenewalSuccess: () => { throw new Error('histogram on fire'); },
};
expect(await runLockRenewalTick(throwingDeps, makeState())).toEqual({ kind: 'ok' });
});
test('case 13e — lateness baseline advances every tick (coalesced-timer semantics)', async () => {
let nowMs = 15_000; // exactly one interval after the seeded baseline (0)
const deps: LockRenewalDeps = {
renewLock: async () => true,
audit: freshAudit().sink,
now: () => nowMs,
setTimeout: makeFakeTimer().setTimeout,
};
const state = makeState();
await runLockRenewalTick(deps, state);
expect(state.lastTickFiredAt).toBe(15_000); // baseline advanced
// Next tick fires 61s later (starved past hardEvict — verify throws too):
// lateness = 76000 - 15000 - 15000 = 46000 attributes the miss to LOCAL
// starvation; sinceLastSuccess = 76000 - 15000 = 61000 >= 60000 → abort.
nowMs = 76_000;
const failDeps: LockRenewalDeps = { ...deps, renewLock: async () => { throw new Error('x'); } };
const result = await runLockRenewalTick(failDeps, state);
expect(result).toMatchObject({ kind: 'should_abort', latenessMs: 46_000, sinceLastSuccessMs: 61_000 });
});
});
describe('runLockRenewalTick: per-call cancellation signal (issue #6)', () => {
test('renewLock receives a live AbortSignal; not aborted on the happy path', async () => {
const audit = freshAudit();