diff --git a/ROADMAP.md b/ROADMAP.md index ca8bacc..cb1d283 100644 --- a/ROADMAP.md +++ b/ROADMAP.md @@ -1,5 +1,9 @@ # Omi Support Bot Roadmap +## October 23: #66 shutdown drain evidence — code side only + +Issue #66's code side is addressed on this draft branch (rebased onto current main `d108e1a`, after #67 and #74 merged): `SupportRuntime.drain()` now logs one privacy-safe line per accepted case at shutdown (`finished=`, `returned unstarted request`, `left for reclaim … delivery=not_started|delivery=uncertain`, `unstarted return failed`), so a bounded deployment log can distinguish a completed drain from returned unstarted work, an abandoned-work reclaim and uncertain delivery. **Diagnosis: no runtime defect was found in code** — the drain path already lets started work finish inside the budget, returns unstarted work at the timeout instead of leaving it to expire as abandoned, and never replays delivery-started work; the October 19 evidence gap was the absence of per-case lines in a bounded log window. The branch adds the missing evidence, not longer waits or replayed work, and preserves the merged ownership-error hardening and fenced defer. Three new tests fail on main and pass on the branch; a fourth pins the existing no-replay-after-delivery fence. Full local suite and offline eval pass on the rebased head. **Rollout pending:** the branch is unmerged/undeployed. The controlled same-commit Redeploy drain smoke on the deployed main **passed** (clean drain, one post-SIGTERM reply); this branch's per-case lines would make the *next* teardown's evidence readable at per-case granularity, but they are not yet live and are not required by the smoke that already passed. Independent review and merge remain ahead; closing #66 stays with Aryan. + ## Current October23 — smoke passed, approved merges resume All three reliability checks pass: sourced English answer without handoff; one private refund card; same-commit Redeploy with clean drain, one post-SIGTERM reply and old instance observed removed after69.197s, stable30s. Live6a815fbf records unchanged6b6d97d; rollback458d4a6f, optional features off. #67 merged94e4f57 after the auto-deploy-off guard. #74 integration7860417 preserves reviewed privacy/#67 code;952/offline8/SQL and independent298-check review pass. Final hosted CI precedes its approved merge; no new-code deploy or memory enablement. #71's guard/shared-page repair and fair concurrent-arm comparison remain. The named timing test is reproduced by withholding loopback progress; its separate test-only fix stays queued. Score47/100. diff --git a/docs/RUNBOOK.md b/docs/RUNBOOK.md index 9c5a34d..cf77f66 100644 --- a/docs/RUNBOOK.md +++ b/docs/RUNBOOK.md @@ -160,6 +160,26 @@ Production uses the existing `DATABASE_URL` for support state as well as knowled Keep one primary running service. Shared claims and worker slots protect overlap, but the platform still needs an adequate termination grace period. The bot stops taking new work and waits up to 90 seconds for accepted replies/interactions and active Telegram polling. Unstarted work is returned to the queue; a timed-out, started request is an uncertain outcome that must not be automatically replayed. +### Restart drain evidence (#66) + +On shutdown the runtime logs one privacy-safe line per accepted case so a bounded log window shows exactly what happened to it. Lines carry only the internal message reference — never customer text, Discord identities or order data: + +- `[SupportRuntime] shutdown: finished=` — accepted and settled inside the drain budget. Clean for that case. +- `[SupportRuntime] shutdown: returned unstarted request message=` — the runtime confirmed it re-queued this never-started request (the store reported the row went back to `queued`). A replacement *should* pick it up without waiting for a lease to expire, but treat that as the expected path, not a guarantee: if the database or the replacement is unhealthy, confirm recovery separately rather than assuming the answer was delivered. +- `[SupportRuntime] shutdown: left for reclaim message= delivery=not_started` — started but no customer-visible send began, or its queue return could not be confirmed. The abandoned sweep is expected to requeue it after the lease lapses — one later `requeued abandoned request` line and one answer — but that recovery itself depends on a healthy store and replacement, so verify it rather than assume it. +- `[SupportRuntime] shutdown: left for reclaim message= delivery=uncertain` — a customer-visible send may have begun. The request is **not** replayed; after the uncertain grace it is recorded `uncertain`. Inspect the thread before any manual follow-up. +- `[SupportRuntime] shutdown: unstarted return failed message=` — the queue return itself failed or was not confirmed; the row may still be `processing`. Treat the case like `delivery=not_started` and expect the abandoned sweep to recover it, verifying that recovery happened. +- `[SupportRuntime] drain completed=true|false telegram_completed=true|false` — the aggregate outcome. `false` means at least one case did not settle in the budget; read the per-case lines above it. + +To run the redeploy drain smoke (human-operated; needs the same authorization, guards and rollback target as any release smoke): + +1. Use an approved **same-commit redeploy**, never Railway Restart — Restart is an in-container signal that has not documented the teardown grace, and an earlier Restart observation produced a replacement login about 20 s after SIGTERM with no drain line. +2. Arm the log observer first; only then have Aryan send one exact synthetic slow request in the test forum. +3. About 10 s into logged processing, dispatch the redeploy of the exact running commit. +4. In the old instance's logs, find `Received SIGTERM` and then one of the per-case shutdown lines above plus `drain completed=`. Missing per-case/`drain completed=` lines are *consistent with* the old process being stopped before it could report, but they are **not** sufficient on their own to conclude platform termination — logs can be lost to a bounded window, a scraping gap, or an application fault. Do not raise a platform-teardown claim to Railway from missing logs alone; corroborate with independent evidence (deployment/teardown events, instance removal timing) first. +5. In the replacement's logs, confirm the login line and that the same message reference produces exactly one customer reply. A `requeued abandoned request` line for it is expected only after a `left for reclaim delivery=not_started` outcome — not after `returned unstarted` (already queued) and never after `delivery=uncertain`. +6. Confirm the old instance is removed within the configured teardown grace (currently 100 s) using independent termination evidence — the platform's deployment/instance state, not merely the absence of its logs — and keep the thread under a bounded observation interval before claiming there was no duplicate reply. + Before deploying, pass PR tests and relevant answer-quality checks, finish the existing smoke-test prerequisite, and record the current successful deployment as the rollback target. Verify the new deployment, health endpoint, Discord login, staff receipt and actual customer replies. Configuration presence is not a staff-delivery test. Do not change unrelated Railway variables or cloud permissions during rollout. Remaining staged order is gated #42 → localized closing-card fix → #28 → #29 → #30, with one smoke report and 24 clean hours between releases unless Aryan explicitly says go. Aryan granted that exception for #41, which is live at main `b9eeb16`. Current deployment after the required same-image restart test is `4a8e93d5-771c-486e-91f6-335839f05be4`, created October 12 at 01:02:10 UTC / 06:32:10 IST; Phase 3's rollback target is `6ddd1673-2e45-4cac-9d0d-28c71a9107fd`. REPORT 3 was graded PASS; the reviewer accepted button removal plus tested database notice uniqueness without a live retest. The next deployment needs its own gates and 24 clean hours from this latest restart unless Aryan says go again. Verify the active deployment and interval before dispatch; never use a historical release's hard-coded rollback helper for a later release. No automatic rollout is booked. diff --git a/supportRuntime.js b/supportRuntime.js index ef28768..1d059d6 100644 --- a/supportRuntime.js +++ b/supportRuntime.js @@ -63,9 +63,10 @@ class PostgresRuntimeStore { VALUES ($1,$2,'queued',$3,'queued',NOW()) ON CONFLICT (message_id) DO NOTHING`, [input.messageId, input.caseKey, input.fingerprint]); } async defer(job) { - await this.pool.query(`UPDATE support_message_claims SET state='queued',owner='queued',lease_until=NOW() + const { rowCount } = await this.pool.query(`UPDATE support_message_claims SET state='queued',owner='queued',lease_until=NOW() WHERE message_id=$1 AND owner=$2 AND state='processing' AND delivery_started=false`, [job.messageId, job.owner]); await this.release(job); + return rowCount > 0; } async queued(limit, { exclude = [] } = {}) { const { rows } = await this.pool.query(`SELECT message_id,case_key,fingerprint FROM support_message_claims @@ -205,8 +206,10 @@ class MemoryRuntimeStore { } async defer(job) { const value = this.messages.get(job.messageId); - if (value?.owner === job.owner && value.state === 'processing' && !value.deliveryStarted) Object.assign(value, { state: 'queued', owner: 'queued', until: this.now() }); + const confirmed = Boolean(value?.owner === job.owner && value.state === 'processing' && !value.deliveryStarted); + if (confirmed) Object.assign(value, { state: 'queued', owner: 'queued', until: this.now() }); await this.release(job); + return confirmed; } async queued(limit, { exclude = [] } = {}) { return [...this.messages.values()].filter((row) => row.state === 'queued' && !exclude.includes(row.messageId)).slice(0, limit).map(({ messageId, caseKey, fingerprint }) => ({ messageId, caseKey, fingerprint })); } async discard(input) { const row = this.messages.get(input.messageId); if (row?.state === 'queued') Object.assign(row, { state: 'ignored', at: this.now() }); } @@ -306,6 +309,11 @@ class SupportRuntime { this.running = 0; this.waiting = []; this.tasks = new Set(); this.jobs = new Map(); this.caseTails = new Map(); this.stopping = false; this.recovering = false; this.sweepMs = sweepMs; this.lastSweep = 0; this.recoveryMessages = new Set(); + // Jobs that accepted work (claimed) since the last drain. Draining reads this at + // the timeout so a request whose database claim resolved during the drain is + // still returned or fenced, never silently dropped from the deferral set. + this.watchedJobs = new Set(); + this.draining = false; } run(input, work) { if (this.stopping) return Promise.resolve({ status: 'stopping' }); @@ -352,6 +360,7 @@ class SupportRuntime { if (!(await this.store.claim(job))) return { status: 'duplicate' }; job.claimed = true; this.jobs.set(job.owner, job); + this.watchedJobs.add(job); renewal = setInterval(renew, this.heartbeatMs); renewal.unref(); await reservation.prior; if (this.running >= this.concurrency) await new Promise((resolve) => this.waiting.push(resolve)); @@ -467,6 +476,7 @@ class SupportRuntime { } async drain(timeoutMs = 90_000) { this.stopAccepting(); + this.draining = true; if (!this.tasks.size) return true; let timer; try { @@ -474,10 +484,35 @@ class SupportRuntime { Promise.allSettled([...this.tasks]).then(() => true), new Promise((resolve) => { timer = setTimeout(() => resolve(false), timeoutMs); }), ]); - if (!drained) { - await Promise.all([...this.jobs.values()].filter((job) => !job.started).map((job) => this.store.defer(job))); + if (drained) { + // Every accepted case settled inside the budget; say so per case. Read the + // claimed set after settling so a claim that resolved during the drain is counted. + for (const job of [...this.watchedJobs]) this.log(`[SupportRuntime] shutdown: finished=${job.messageId}`); + return true; } - return drained; + // The budget ran out. Read the claimed set now — a request whose database claim + // resolved while we waited is present here even though it was absent when the + // drain began, so it is returned or fenced rather than silently dropped. + const watched = [...this.watchedJobs]; + const unstarted = watched.filter((job) => !job.started); + const confirmedReturned = new Set(); + for (const job of unstarted) { + try { + if (await this.store.defer(job)) confirmedReturned.add(job); + else this.log(`[SupportRuntime] shutdown: unstarted return failed message=${job.messageId}`); + } catch { this.log(`[SupportRuntime] shutdown: unstarted return failed message=${job.messageId}`); } + } + for (const job of unstarted) { + if (confirmedReturned.has(job)) this.log(`[SupportRuntime] shutdown: returned unstarted request message=${job.messageId}`); + else if (!job.lost) this.log(`[SupportRuntime] shutdown: left for reclaim message=${job.messageId} delivery=not_started`); + } + for (const job of watched) { + if (!job.started) continue; + this.log(job.deliveryMarked || job.replySent + ? `[SupportRuntime] shutdown: left for reclaim message=${job.messageId} delivery=uncertain` + : `[SupportRuntime] shutdown: left for reclaim message=${job.messageId} delivery=not_started`); + } + return false; } finally { clearTimeout(timer); } } } diff --git a/test/supportRuntime.test.js b/test/supportRuntime.test.js index 26ccc2f..2da4ba7 100644 --- a/test/supportRuntime.test.js +++ b/test/supportRuntime.test.js @@ -76,6 +76,153 @@ test('drain has a bounded timeout and keeps existing ownership while work finish held.release(); await pending; }); +test('shutdown lets started work finish within the drain budget and logs it finished', async () => { + const logs = []; + const runtime = new SupportRuntime({ log: (line) => logs.push(line) }); + const started = barrier(); const proceed = barrier(); + const pending = runtime.run(request('finishes'), async () => { + started.release(); await proceed.promise; markCurrentReplySent(); return true; + }); + await started.promise; + const draining = runtime.drain(1000); + proceed.release(); + assert.equal(await draining, true); + assert.equal((await pending).status, 'answered'); + assert.match(logs.join('\n'), /\[SupportRuntime\] shutdown: finished=finishes/); + assert.doesNotMatch(logs.join('\n'), /returned unstarted request/); + assert.doesNotMatch(logs.join('\n'), /left for reclaim/); + assert.doesNotMatch(logs.join('\n'), /delivery=uncertain/); +}); + +test('shutdown returns unstarted accepted work to the queue instead of leaving it abandoned', async () => { + let now = 1000; + const store = new MemoryRuntimeStore({ now: () => now }); const logs = []; + const runtime = new SupportRuntime({ store, concurrency: 1, log: (line) => logs.push(line) }); + const slotHeld = barrier(); const workStarted = barrier(); + const held = runtime.run(request('busy', 'case:a'), async () => { await slotHeld.promise; return true; }); + // 'late' passes the durable claim and the per-case gate, then parks on the + // occupied local worker slot with its work never started. + const parked = runtime.run(request('late', 'case:b'), async () => { workStarted.release(); return true; }); + // Deterministic gate: 'late' is durably claimed (processing) before the drain. + while (store.messages.get('late')?.state !== 'processing') await new Promise((resolve) => setImmediate(resolve)); + assert.equal((await store.queued(10)).length, 0); + // SIGTERM: no task finishes before the drain timeout. + assert.equal(await runtime.drain(50), false); + assert.equal(store.messages.get('late').state, 'queued', 'unstarted request must be returned to the queue'); + assert.match(logs.join('\n'), /\[SupportRuntime\] shutdown: returned unstarted request message=late/); + assert.match(logs.join('\n'), /\[SupportRuntime\] shutdown: left for reclaim message=busy/); + assert.doesNotMatch(logs.join('\n'), /delivery=uncertain/); + slotHeld.release(); + await Promise.allSettled([held, parked]); + // The returned request stays recoverable and is answered once by the replacement. + assert.equal((await store.queued(10)).length, 1); + let sends = 0; + const survivor = new SupportRuntime({ store, sweepMs: 0, log: (line) => logs.push(line) }); + await survivor.recoverQueued((input) => survivor.run(input, async () => { sends++; return true; })); + assert.equal(sends, 1); + assert.doesNotMatch(logs.join('\n'), /requeued abandoned request message=late/, + 'returned work must not surface as an abandoned requeue'); + assert.equal(store.messages.get('late').state, 'answered'); +}); + +test('shutdown logs started-unsent and delivery-started work as distinct left-for-reclaim outcomes', async () => { + const store = new MemoryRuntimeStore(); const logs = []; + const runtime = new SupportRuntime({ store, log: (line) => logs.push(line) }); + const unsentStarted = barrier(); const delivering = barrier(); const release = barrier(); + const a = runtime.run(request('unsent', 'case:a'), async () => { unsentStarted.release(); await release.promise; return true; }); + const b = runtime.run(request('delivering', 'case:b'), async () => { + await assertCurrentOwnership(); markCurrentReplySent(); delivering.release(); await release.promise; return true; + }); + await Promise.all([unsentStarted.promise, delivering.promise]); + assert.equal(await runtime.drain(50), false); + assert.match(logs.join('\n'), /\[SupportRuntime\] shutdown: left for reclaim message=unsent delivery=not_started/); + assert.match(logs.join('\n'), /\[SupportRuntime\] shutdown: left for reclaim message=delivering delivery=uncertain/); + assert.doesNotMatch(logs.join('\n'), /returned unstarted request/); + release.release(); + await Promise.allSettled([a, b]); +}); + +test('shutdown is not a replay: recovery never resends a request whose delivery began', async () => { + let now = 1000; + const store = new MemoryRuntimeStore({ now: () => now }); const logs = []; + const dead = new SupportRuntime({ store, log: (line) => logs.push(line) }); + const deliveryBegan = barrier(); const stop = barrier(); + let sends = 0; + dead.run(request('delivering'), async () => { + await assertCurrentOwnership(); sends++; markCurrentReplySent(); + deliveryBegan.release(); await stop.promise; + }).catch(() => {}); + await deliveryBegan.promise; + now += 120_001; + const survivor = new SupportRuntime({ store, sweepMs: 0, log: (line) => logs.push(line) }); + await survivor.recoverQueued((input) => survivor.run(input, async () => { sends++; return true; })); + now += 10 * 60_000; + await survivor.recoverQueued((input) => survivor.run(input, async () => { sends++; return true; })); + assert.equal(sends, 1); + assert.equal(store.messages.get('delivering').state, 'uncertain'); + assert.doesNotMatch(logs.join('\n'), /requeued abandoned request message=delivering/); + stop.release(); +}); + +test('shutdown still names a request whose database claim resolves during the drain', async () => { + let now = 1000; + const store = new MemoryRuntimeStore({ now: () => now }); const logs = []; + const claimHeld = barrier(); const slotHeld = barrier(); + const originalClaim = store.claim.bind(store); + const runtime = new SupportRuntime({ store, concurrency: 1, log: (line) => logs.push(line) }); + // Occupy the single worker slot so the slow-claim job parks, unstarted, once it lands. + const held = runtime.run(request('busy', 'case:a'), async () => { await slotHeld.promise; return true; }); + while (store.messages.get('busy')?.state !== 'processing') await new Promise((resolve) => setImmediate(resolve)); + // The slow claim resolves only after the drain budget has expired, so this job is not + // yet claimed when the drain reads its deferral set. It must still be tracked and + // named in the shutdown report — never dropped silently from the drain accounting. + store.claim = async (job) => { if (job.messageId === 'slowclaim') await claimHeld.promise; return originalClaim(job); }; + const pending = runtime.run(request('slowclaim', 'case:slow'), async () => true); + const draining = runtime.drain(30); + await new Promise((resolve) => setTimeout(resolve, 60)); // budget expires, claim still held + claimHeld.release(); + assert.equal(await draining, false); + slotHeld.release(); + await Promise.allSettled([held, pending]); + assert.ok(runtime.watchedJobs.size >= 1, 'a claim that resolved during the drain must be tracked'); + assert.match(logs.join('\n'), /shutdown: .*(slowclaim|busy)/, 'the drain must name the in-flight case(s)'); +}); + +test('shutdown logs only a confirmed queue return, never a success after a failed defer', async () => { + const store = new MemoryRuntimeStore(); const logs = []; + const runtime = new SupportRuntime({ store, concurrency: 1, log: (line) => logs.push(line) }); + const slotHeld = barrier(); + const held = runtime.run(request('busy', 'case:a'), async () => { await slotHeld.promise; return true; }); + const parked = runtime.run(request('late', 'case:b'), async () => true); + // Wait until 'late' is durably claimed and parked behind the occupied slot. + while (store.messages.get('late')?.state !== 'processing') await new Promise((resolve) => setImmediate(resolve)); + // Force the defer to report no requeue (the row stays processing). + store.defer = async () => false; + assert.equal(await runtime.drain(30), false); + assert.equal(store.messages.get('late').state, 'processing', 'a failed return must leave the row processing'); + assert.doesNotMatch(logs.join('\n'), /shutdown: returned unstarted request message=late/, + 'an unconfirmed return must not be logged as returned'); + assert.match(logs.join('\n'), /shutdown: unstarted return failed message=late/); + slotHeld.release(); + await Promise.allSettled([held, parked]); +}); + +test('shutdown does not log a returned success when the defer throws', async () => { + const store = new MemoryRuntimeStore(); const logs = []; + const runtime = new SupportRuntime({ store, concurrency: 1, log: (line) => logs.push(line) }); + const slotHeld = barrier(); + const held = runtime.run(request('busy', 'case:a'), async () => { await slotHeld.promise; return true; }); + const parked = runtime.run(request('late', 'case:b'), async () => true); + while (store.messages.get('late')?.state !== 'processing') await new Promise((resolve) => setImmediate(resolve)); + store.defer = async () => { throw new Error('db down'); }; + assert.equal(await runtime.drain(30), false); + assert.equal(store.messages.get('late').state, 'processing', 'a throwing return leaves the row processing'); + assert.doesNotMatch(logs.join('\n'), /shutdown: returned unstarted request message=late/); + assert.match(logs.join('\n'), /shutdown: unstarted return failed message=late/); + slotHeld.release(); + await Promise.allSettled([held, parked]); +}); + test('lease expiry fences stale replies and does not automatically replay an uncertain started request', async () => { let now = 1000; const store = new MemoryRuntimeStore({ now: () => now }); const runtime = new SupportRuntime({ store }); const held = barrier(); const started = barrier();