mirror of
https://github.com/garrytan/gbrain.git
synced 2026-08-16 09:52:22 +00:00
Compare commits
| Author | SHA1 | Date | |
|---|---|---|---|
|
|
8bf23abf71 |
@@ -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. -->
|
||||
|
||||
@@ -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 5s–1h; 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 8–9.5 minutes on
|
||||
|
||||
@@ -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
@@ -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
@@ -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`
|
||||
|
||||
|
||||
@@ -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,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
@@ -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",
|
||||
|
||||
@@ -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
@@ -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
@@ -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);
|
||||
|
||||
@@ -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) {
|
||||
|
||||
@@ -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}`);
|
||||
}
|
||||
|
||||
@@ -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'],
|
||||
|
||||
@@ -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
|
||||
|
||||
@@ -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)));
|
||||
}
|
||||
|
||||
@@ -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
@@ -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
|
||||
|
||||
@@ -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
@@ -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. ns→ms. 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');
|
||||
})
|
||||
|
||||
@@ -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).
|
||||
|
||||
@@ -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
|
||||
|
||||
@@ -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
@@ -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;
|
||||
|
||||
@@ -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
@@ -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,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
|
||||
|
||||
@@ -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 () => {
|
||||
|
||||
@@ -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}%`],
|
||||
|
||||
@@ -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>,
|
||||
|
||||
@@ -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;
|
||||
|
||||
@@ -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',
|
||||
|
||||
@@ -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);
|
||||
|
||||
|
||||
@@ -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();
|
||||
|
||||
@@ -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
|
||||
`);
|
||||
|
||||
@@ -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);
|
||||
|
||||
|
||||
@@ -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
|
||||
|
||||
@@ -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);
|
||||
|
||||
@@ -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();
|
||||
|
||||
@@ -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() {
|
||||
|
||||
@@ -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);
|
||||
});
|
||||
@@ -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:');
|
||||
});
|
||||
});
|
||||
|
||||
@@ -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
@@ -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');
|
||||
});
|
||||
});
|
||||
|
||||
@@ -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();
|
||||
|
||||
@@ -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');
|
||||
|
||||
@@ -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([]);
|
||||
});
|
||||
|
||||
@@ -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);
|
||||
|
||||
@@ -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/);
|
||||
});
|
||||
});
|
||||
|
||||
@@ -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();
|
||||
|
||||
Reference in New Issue
Block a user