Skip to content
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
15 changes: 13 additions & 2 deletions .specs/features/store-busy-healing/spec.md
Original file line number Diff line number Diff line change
Expand Up @@ -12,7 +12,10 @@ A causa do segundo escritor (N daemons) é tratada em `daemon-single-instance`.
- [x] `SQLITE_BUSY` (errcode base 5, incluindo 517) não encerra o loop nem marca a sessão: o mesmo evento é retentado com backoff (25ms dobrando, teto 2s) enquanto o daemon roda
- [x] Erros de persistência não-busy mantêm o comportamento atual (`failed`)
- [x] `classifyFailure("database is locked")` → `STORE_BUSY`, `blame: infra`, `retryable: true`
- [ ] (próxima fase) Reconciliador: sessão `failed` com `STORE_BUSY`/`UNKNOWN` de lock e PID vivo com a mesma identidade é reatachada a partir dos offsets persistidos
- [x] Reconciliador no boot (`reviveStoreBusyFailures`, antes do loop de `recover()`): linha `failed` com `failure.code=STORE_BUSY` ou `failure.detail` contendo `database is locked`, com log em disco e PID, volta a `working` e passa pelo mesmo reattach de um restart
- harness vivo (mesma identidade de PID): segue tailando do offset persistido
- harness morto (ou PID reciclado): o log é drenado do offset e o desfecho é classificado; eventos drenados e `completedAt` recebem o mtime do log (os parsers carimbam hora de leitura)
- [x] Harness morto sem frame terminal e com exit não observado (reattach): se o último evento (fora `usage.updated`) é `turn.completed`, sem sinal fatal e sem assinatura de crash no stderr, fecha `completed` com `reason: "turn completed; exit not observed"`; senão segue `failed` "exited without reporting a terminal event"

## Decisions

Expand All @@ -21,14 +24,22 @@ A causa do segundo escritor (N daemons) é tratada em `daemon-single-instance`.
| Retry sem limite | Sim, enquanto não `shuttingDown` | O harness continua vivo e a saída está no log em disco; desistir recria o bug. Um lock eterno é problema do daemon, logado uma vez em `daemon.log` |
| Idempotência do retry | Transação inteira refeita (evento + offsets + status) | ROLLBACK desfaz tudo; dedupe por `sourceKey` protege replays |
| Shutdown durante o retry | Sai do loop sem gravar nada | O drain de shutdown é dono do desfecho (`interrupted`) |
| Reviver `failed` de lock | Só no boot, só com log + PID, nunca `origin=open` | Reusa o caminho de reattach testado; `open` não tem driver para reatachar |
| Horário do backlog drenado | mtime do log (máx. de stdout/stderr) quando o harness já morreu | Parsers usam `new Date()` na leitura; o mtime é o limite superior honesto. O uso por hora agrupa por `created_at`, então só a linha do tempo e `completedAt` mudam |
| Exit não observado | `turn.completed` final conta como fim do turno | `codex exec` sai logo após `turn.completed`; o trabalho do turno está feito. Vale também para restart comum do daemon. Limite: só enxerga eventos lidos desde o reattach |
| Idempotência | O desfecho novo não tem `database is locked` no `detail` | Um boot seguinte não revive a mesma linha de novo |

## Acceptance Criteria

1. WHEN outro processo commita entre a leitura e a escrita da transação do evento THEN todos os eventos SHALL ser persistidos e a sessão SHALL terminar `completed`
2. WHEN `append` lança `SQLITE_BUSY`/`BUSY_SNAPSHOT` THEN o daemon SHALL retentar o mesmo evento e nenhum `session.failed` SHALL ser gravado
3. WHEN `append` lança um erro não-busy THEN a sessão SHALL ser marcada `failed` (sem regressão)
4. WHEN o texto do erro é `database is locked` THEN `classifyFailure` SHALL retornar `STORE_BUSY` com `blame: infra`
5. WHEN o boot encontra uma linha `failed` por lock com harness vivo THEN ela SHALL voltar a `working` e os eventos novos do log SHALL ser persistidos
6. WHEN o harness dessa linha já morreu THEN o log SHALL ser drenado do offset, a sessão SHALL terminar em estado terminal sem `database is locked`, e eventos drenados e `completedAt` SHALL usar o mtime do log
7. WHEN a falha não é de lock, ou não há log THEN a linha SHALL ficar intacta
8. WHEN um reattach vê o PID morrer e o último evento é `turn.completed` THEN a sessão SHALL fechar `completed`; WHEN o log para antes disso, ou há sinal fatal, exit não-zero ou crash no stderr THEN SHALL fechar `failed`

## Validation

`tests/daemon-store-busy.test.ts` (AC 1-4). AC 1 reproduz a intercalação real com uma segunda `DatabaseSync` e falhava antes do fix com só `session.failed` no log de eventos.
`tests/daemon-store-busy.test.ts` (AC 1-4), `tests/daemon-heal-store-busy.test.ts` (AC 5-8), `tests/terminal-synth.test.ts` (AC 8). AC 1 reproduz a intercalação real com uma segunda `DatabaseSync` e falhava antes do fix com só `session.failed` no log de eventos.
68 changes: 65 additions & 3 deletions src/daemon/daemon.ts
Original file line number Diff line number Diff line change
Expand Up @@ -132,6 +132,9 @@ class Daemon {
private startTime = Date.now();
private startupReconcilePromise: Promise<void> = Promise.resolve();
private sessionLocks = new Set<string>();
// Sessions recover() revived from a store-busy failure: the sequence the
// drain starts after, and the log mtime when the harness is already dead.
private healing = new Map<string, { fromSequence: number; endedAt?: Date }>();
// Power-shutdown state. `shuttingDown` is set synchronously by the signal
// handler so concurrent handleRequest calls are refused during the drain.
private shuttingDown = false;
Expand Down Expand Up @@ -398,6 +401,7 @@ class Daemon {
// streaming; a dead one is drained and classified from its log tail.
private async recover(): Promise<void> {
const paths = getPaths();
this.reviveStoreBusyFailures(paths.logsDir);
const actives = this.sessions.listActive();
for (const s of actives) {
// Power-shutdown rows are terminal: never reattach, never flip. A
Expand Down Expand Up @@ -468,7 +472,10 @@ class Daemon {
// Never attach to or signal a PID whose identity changed while the
// daemon was away. The original harness is gone; the replacement is
// somebody else's process.
if (pidReused) {
// A revived row died long ago: its PID may be anyone's by now, but its
// log is still its own, so drain it as dead instead of failing it.
const healing = this.healing.has(s.id);
if (pidReused && !healing) {
const failure: FailureInfo = {
code: "HARNESS_CRASH",
blame: "harness",
Expand All @@ -490,13 +497,14 @@ class Daemon {
continue;
}

const alive = processPresent;
// Only a healing row reaches here with a reused PID; it counts as dead.
const alive = processPresent && !pidReused;
const stdoutPath = path.join(paths.logsDir, `${s.id}.ndjson`);
const stderrPath = path.join(paths.logsDir, `${s.id}.stderr.log`);
const hasDetachedLogs = fs.existsSync(stdoutPath) || fs.existsSync(stderrPath);
// A live PID without a recorded identity is unsafe to attach: it may be
// a recycled process. A dead PID is safe to drain from its own log.
const identityVerified = !processPresent || (recordedStart !== undefined && currentStart === recordedStart);
const identityVerified = !alive || (recordedStart !== undefined && currentStart === recordedStart);

if (typeof driver.attach === "function" && pid != null && hasDetachedLogs && identityVerified) {
try {
Expand Down Expand Up @@ -543,6 +551,59 @@ class Daemon {
}
}

// A session the old event loop failed on "database is locked" was never
// over: the harness kept writing its log past the persisted offset. Flip
// such rows back to working so the reattach loop below drains the log
// (dead harness) or keeps tailing it (live one), exactly as after a restart.
private reviveStoreBusyFailures(logsDir: string): void {
for (const s of this.sessions.listStoreBusyFailures()) {
if (s.origin === "open") continue;
const logs = [path.join(logsDir, `${s.id}.ndjson`), path.join(logsDir, `${s.id}.stderr.log`)]
.filter((file) => fs.existsSync(file));
const metadata = readSessionProcessMetadata(s.id);
const pid = metadata?.pid ?? s.pid;
if (logs.length === 0 || pid == null) continue;
const recordedStart = metadata?.pidStartTime ?? s.pidStartTime;
const alive = processAlive(pid) && (recordedStart === undefined || processStartTime(pid) === recordedStart);
// Parsers stamp events with read time. For a dead harness the last log
// write is the best bound on when the backlog really happened.
const endedAt = alive
? undefined
: new Date(Math.max(...logs.map((file) => fs.statSync(file).mtimeMs)));
const last = this.db.getHandle().prepare(
`SELECT COALESCE(MAX(sequence), 0) AS seq FROM events WHERE session_id = ?`,
).get(s.id) as { seq: number };
this.healing.set(s.id, { fromSequence: last.seq, endedAt });
this.sessions.setStatus(s.id, "working", {
failure: null,
completedAt: null,
lastEvent: "healing after a store-busy failure",
});
appendDaemonLog(`healing ${s.id} from store-busy failure (${alive ? "live" : "dead"} harness)`);
}
}

// Once a revived session's stream ends, pin the drained backlog and the
// terminal time to the log mtime instead of the replay time.
private finishHeal(sessionId: string): void {
const heal = this.healing.get(sessionId);
if (!heal) return;
this.healing.delete(sessionId);
if (!heal.endedAt) return;
const endedAt = heal.endedAt.toISOString();
try {
this.db.getHandle().prepare(`
UPDATE events
SET timestamp = ?, normalized_payload = json_set(normalized_payload, '$.timestamp', ?)
WHERE session_id = ? AND sequence > ? AND timestamp > ?
`).run(endedAt, endedAt, sessionId, heal.fromSequence, endedAt);
const s = this.sessions.get(sessionId);
if (s && isTerminalStatus(s.status)) this.sessions.update(sessionId, { completedAt: heal.endedAt });
} catch (error) {
appendDaemonLog(`heal timestamps for ${sessionId} failed: ${error instanceof Error ? error.message : String(error)}`);
}
}

private async reconcileOpenUsage(sessionId: string, nativeIds?: readonly string[]): Promise<void> {
const session = this.sessions.get(sessionId);
if (!session || session.origin !== "open" || session.agent !== "claude") return;
Expand Down Expand Up @@ -1769,6 +1830,7 @@ class Daemon {
this.sessions.setStatus(sessionId, "failed", { lastEvent: error.slice(0, 200), failure });
}
}
this.finishHeal(sessionId);
// A message queued while the turn ran starts now as the next turn.
// tryDispatch rechecks resumability under the lifecycle lock; a stale
// or unresumable slot stays put for a manual send.
Expand Down
4 changes: 4 additions & 0 deletions src/drivers/session-runtime.ts
Original file line number Diff line number Diff line change
Expand Up @@ -33,6 +33,8 @@ export interface RuntimeHooks {
hasTerminal: boolean;
hasMessage: boolean;
stderr: string;
// Last non-usage event is turn.completed (see synthesizeTerminalEvent).
endedOnTurnCompleted: boolean;
}) => AgentEvent[];
}

Expand Down Expand Up @@ -333,13 +335,15 @@ export class SessionRuntime {
const hasTerminal = this.buffer.some((e) => e.type === "session.completed" || e.type === "session.failed");
if (!hasTerminal && !this.stopRequested && !this.shutdownRequested) {
const hasMessage = this.buffer.some((e) => e.type === "message" || e.type === "text.delta");
const lastFrame = this.buffer.findLast((e) => e.type !== "usage.updated");
for (const ev of this.hooks.synthesizeTerminal({
sessionId: this.sessionId,
exitCode,
signal,
hasTerminal,
hasMessage,
stderr: this.stderrBuf,
endedOnTurnCompleted: lastFrame?.type === "turn.completed",
})) {
this.push(ev);
}
Expand Down
19 changes: 19 additions & 0 deletions src/drivers/terminal.ts
Original file line number Diff line number Diff line change
Expand Up @@ -15,9 +15,28 @@ export function synthesizeTerminalEvent(input: {
hasTerminal: boolean;
hasMessage: boolean;
stderr: string;
// The last frame (usage aside) was turn.completed.
endedOnTurnCompleted?: boolean;
}): AgentEvent | null {
if (input.hasTerminal) return null;
const ts = new Date().toISOString();
// No exit code and no signal: the death was learned by polling the pid
// after a reattach. A harness that writes no terminal frame (codex) still
// said its turn finished; a crash signature in stderr overrides that.
if (
input.exitCode === null &&
!input.signal &&
input.endedOnTurnCompleted &&
classifyFailure(input.stderr).code !== "HARNESS_CRASH"
) {
return {
type: "session.completed",
sessionId: input.sessionId,
timestamp: ts,
reason: "turn completed; exit not observed",
raw: { stderr: input.stderr.slice(0, 2000) },
} as AgentEvent;
}
if (input.exitCode === 0) {
// Exit 0 with produced output is completion. Exit 0 with NO output but
// stderr content is how "exit 0 anyway" crashes look — treat as failure.
Expand Down
13 changes: 13 additions & 0 deletions src/store/sessions.ts
Original file line number Diff line number Diff line change
Expand Up @@ -223,6 +223,19 @@ export class SessionStore {
return rows.map(rowToSession);
}

// Rows the pre-STORE_BUSY event loop failed on a locked SQLite store
// ("database is locked" was classified UNKNOWN), plus STORE_BUSY rows.
listStoreBusyFailures(): Session[] {
const rows = this.db.prepare(`
SELECT * FROM sessions
WHERE status = 'failed' AND failure IS NOT NULL
AND (json_extract(failure, '$.code') = 'STORE_BUSY'
OR json_extract(failure, '$.detail') LIKE '%database is locked%')
ORDER BY updated_at DESC
`).all() as unknown as SessionRow[];
return rows.map(rowToSession);
}

getByRunId(runId: string): Session[] {
const rows = this.db.prepare(
`SELECT * FROM sessions WHERE run_id = ? ORDER BY updated_at DESC`,
Expand Down
Loading
Loading