ReviewOS
Reload

also looking at this

stacks/drone

test: retain execution HTTP lifecycle evidence

#95
Closed chris wants to merge codex/http-fixture-observations into codex/vtol-wind-phase-cases
3 files +150 -58

Review threads live on the whole diff, not on one commit, so none are shown here - a thread's line means something in the branch's final form, and painting it into an intermediate step would put it on code it is not about.

docs/public-safety-execution.mdmodified+29-0
@@ -116,3 +116,32 @@ EXECUTION_BROWSER_QA=true BROWSE_BROWSER=/path/to/google-chrome bun test tests/u
116116Native controller and HTTP checks separately cover authority replacement,
117117elapsed deadlines, stream capacity, cleanup and durable COMMIT with a withheld
118118response. The existing workspace browser scenarios remain required regressions.
119
120### HTTP fixture failure observations
121
122The native HTTP fixture records parent and child Bun identity separately, bounded
123phase timings and the actual settled exit code and signal. Parent and child
124elapsed times have separate local monotonic origins. The original 35,000 ms
125SIGKILL guard and 40,000 ms test limit remain unchanged.
126
127To collect a focused observation in an operator-controlled private directory:
128
129```sh
130EXECUTION_HTTP_EVIDENCE="$HOME/private-drone-http-evidence" bun test tests/unit/public-safety-execution-http-limits.test.ts --test-name-pattern 'native execution HTTP limits nativeRoutes=true'
131```
132
133Successful, fully captured fixtures are removed. A failed fixture or unavailable
134evidence write retains its directory, including available `fixture.stdout`,
135`fixture.stderr` and `lifecycle.json`. Failed fixture databases contain generated
136test credentials and remain private. Evidence write failures are reported without
137replacing the child's settled result.
138
139`watchdogFired` records that the parent's guard callback ran; `watchdogKill`
140records its SIGKILL request. `cleanupKill` records a separate cleanup request.
141The actual child signal and settled status are independent observations. Exit 137
142alone does not identify the kill actor. A missing child runtime record remains
143unknown, including when termination precedes entry-module evaluation.
144
145These observations support the [open HTTP timeout investigation](https://github.com/stacksjs/drone/issues/93).
146They do not establish its original cause or turn a later passing control into a
147fix for an earlier failed run.
tests/fixtures/public-safety-access/execution-http-limits.tsmodified+73-48
@@ -2,21 +2,36 @@ import assert from 'node:assert/strict'
22import { writeFile } from 'node:fs/promises'
33import { join, resolve } from 'node:path'
44import type { ExecutionView } from '../../../resources/functions/drone/public-safety/execution/types'
5import { setupHandoverFixture } from './handover-setup'
65
76const scenario = Bun.argv[2]
87assert(['limits', 'preflight', 'middleware', 'chunk', 'admission'].includes(scenario!))
9const f = await setupHandoverFixture()
8const began = performance.now()
9let observations = 0
10async function observe<T>(phase: string, work: () => T | Promise<T>): Promise<T> {
11 const emit = (outcome: 'began' | 'settled' | 'rejected') => {
12 if (observations >= 128) return
13 // Diagnostic output must not replace an actual native failure.
14 try { console.log(JSON.stringify({ oracle: 'execution-http-phase', scenario, pid: process.pid, ordinal: observations++, phase, outcome, elapsedMs: performance.now() - began })) }
15 catch {}
16 }
17 emit('began')
18 try { const result = await work(); emit('settled'); return result }
19 catch (error) { emit('rejected'); throw error }
20}
21try { console.log(JSON.stringify({ oracle: 'execution-http-runtime', scenario, pid: process.pid, bunVersion: Bun.version, executable: process.execPath, platform: process.platform, arch: process.arch })) }
22catch {}
23const { setupHandoverFixture } = await observe('setup-module', () => import('./handover-setup'))
24const f = await observe('setup', setupHandoverFixture)
1025const source = resolve(import.meta.dir, '../../..')
11await writeFile(join(process.cwd(), 'app/Gates.ts'), `export { default } from ${JSON.stringify(join(source, 'app/Gates.ts'))}`)
12const { initializeAuthorization } = await import('@stacksjs/auth/policy')
13await initializeAuthorization()
14const { Gate } = await import('@stacksjs/auth/gate')
15const { getCurrentRequest, route } = await import('@stacksjs/router')
16const { emit, setReplayBuffer, stopServer } = await import('@stacksjs/realtime')
17const { executionOwner } = await import('../../../resources/functions/drone/public-safety/execution/state')
18const { executionWords } = await import('../../../resources/functions/drone/public-safety/execution/protocol')
19await route.register(join(source, 'routes/api.ts'), { prefix: '/api' })
26await observe('gate-override', () => writeFile(join(process.cwd(), 'app/Gates.ts'), `export { default } from ${JSON.stringify(join(source, 'app/Gates.ts'))}`))
27const { initializeAuthorization } = await observe('authorization-module', () => import('@stacksjs/auth/policy'))
28await observe('authorization', initializeAuthorization)
29const { Gate } = await observe('gate-module', () => import('@stacksjs/auth/gate'))
30const { getCurrentRequest, route } = await observe('router-module', () => import('@stacksjs/router'))
31const { emit, setReplayBuffer, stopServer } = await observe('realtime-module', () => import('@stacksjs/realtime'))
32const { executionOwner } = await observe('execution-state-module', () => import('../../../resources/functions/drone/public-safety/execution/state'))
33const { executionWords } = await observe('protocol-module', () => import('../../../resources/functions/drone/public-safety/execution/protocol'))
34await observe('route-register', () => route.register(join(source, 'routes/api.ts'), { prefix: '/api' }))
2035let deadline = 0, crossed = 0
2136const cross = async () => {
2237 assert(Date.now() < deadline, 'Actual native response/check must be current before the wall crossing')
@@ -30,7 +45,7 @@ route.use(async (request: Request, next: () => Promise<Response | null> | Respon
3045 return response
3146})
3247const nativeRoutes = process.env.INCIDENT_NATIVE_ROUTES === 'true'
33const server = await route.serve({ hostname: '127.0.0.1', port: 0, nativeRoutes })
48const server = await observe('server-start', () => route.serve({ hostname: '127.0.0.1', port: 0, nativeRoutes }))
3449type DiagnosticSlot = { control: Int32Array, subscriber: unknown, worker: Worker | null, producer: string, admission: string, phase: string, reason: string | null }
3550let slot: DiagnosticSlot | undefined, started: ExecutionView | undefined
3651const readers = new Set<ReadableStreamDefaultReader<Uint8Array>>()
@@ -51,13 +66,13 @@ try {
5166 // Chunk/admission must first complete an actual run. Give that setup margin;
5267 // the subsequent native release still has to cross this genuine wall deadline.
5368 const retentionMs = scenario === 'chunk' || scenario === 'admission' ? 20000 : expiring ? 8000 : 86400000
54 const seeded = await f.seed(`execution-http-${scenario}`, retentionMs)
69 const seeded = await observe('seed', () => f.seed(`execution-http-${scenario}`, retentionMs))
5570 deadline = Date.parse(seeded.config.retention.expiresAt)
5671 const base = `http://127.0.0.1:${server.port}/api/public-safety/incidents/${seeded.key}/workspace`
5772 const headers = { authorization: `Bearer ${f.senderToken}` }
58 const workspace = await fetch(base, { headers }); assert.equal(workspace.status, 200)
59 const { scope } = await workspace.json() as { scope: string }
60 const initialVersion = Number((await f.snapshot(seeded.key)).incident!.version)
73 const workspace = await observe('workspace-request', () => fetch(base, { headers })); assert.equal(workspace.status, 200)
74 const { scope } = await observe('workspace-body', () => workspace.json()) as { scope: string }
75 const initialVersion = Number((await observe('initial-snapshot', () => f.snapshot(seeded.key))).incident!.version)
6176 const statusUrl = `${base}/execution?scope=${scope}`
6277 const send = (suffix: string, body: unknown, extra: Record<string, string> = {}) => fetch(`${base}/execution${suffix}`, { method: 'POST', headers: { ...headers, 'content-type': 'application/json', ...extra }, body: JSON.stringify(body) })
6378 cleanup = async () => {
@@ -74,35 +89,35 @@ try {
7489 }
7590 if (scenario === 'preflight') {
7691 stall = true
77 const response = await fetch(statusUrl, { headers: { ...headers, 'x-fixture-execution-stall': '1' } })
92 const response = await observe('preflight-request', () => fetch(statusUrl, { headers: { ...headers, 'x-fixture-execution-stall': '1' } }))
7893 assert.equal(response.status, 404)
7994 assert(held)
8095 assert.equal(executionOwner().pendingChecks, 1, 'Timed-out actual HTTP preflight remains charged until genuine native settlement')
8196 resume!(); stall = false
82 await wait(() => executionOwner().pendingChecks === 0, 'Native preflight must settle before its shared budget is released')
97 await observe('preflight-settlement', () => wait(() => executionOwner().pendingChecks === 0, 'Native preflight must settle before its shared budget is released'))
8398 assert.equal((await fetch(statusUrl, { headers })).status, 200)
8499 assert.equal(executionOwner().slot, null)
85100 }
86101 else if (scenario === 'middleware') {
87 const response = await fetch(statusUrl, { headers: { ...headers, 'x-fixture-execution-middleware': '1' } })
102 const response = await observe('middleware-request', () => fetch(statusUrl, { headers: { ...headers, 'x-fixture-execution-middleware': '1' } }))
88103 assert.equal(response.status, 404, 'Null status response retains preflight deadline across awaited native middleware')
89104 assert.equal(crossed, 1)
90105 assert.deepEqual(Object.keys(await response.json() as object), ['error'])
91106 }
92107 else {
93 const response = await send('', { intent: crypto.randomUUID(), scope, scenario: 'nominal', seconds: 8 })
108 const response = await observe('execution-start', () => send('', { intent: crypto.randomUUID(), scope, scenario: 'nominal', seconds: 8 }))
94109 assert.equal(response.status, 202); started = await response.json() as ExecutionView
95110 slot = executionOwner().slot as DiagnosticSlot
96111 const events = `${base}/execution/${started.execution}/events?scope=${scope}`
97112 const channel = `private-public-safety.execution.${started.execution}`
98 const open = async (extra: Record<string, string> = {}) => {
113 const open = (extra: Record<string, string> = {}) => observe('events-open', async () => {
99114 const abort = new AbortController(); aborts.add(abort)
100115 const result = await route.handleRequest(new Request(events, { headers: { ...headers, ...extra }, signal: abort.signal }) as Parameters<typeof route.handleRequest>[0])
101116 assert.equal(result?.status, 200)
102117 const reader = result!.body!.getReader(); readers.add(reader)
103118 assert(new TextDecoder().decode((await reader.read()).value).includes(': connected'))
104119 return { reader, abort }
105 }
120 })
106121 const drainClosed = async (reader: ReadableStreamDefaultReader<Uint8Array>) => {
107122 for (let count = 0; count < 100; count++) if ((await reader.read()).done) return
108123 assert.fail('Native stream must close without unbounded pending frames')
@@ -141,26 +156,30 @@ try {
141156 }
142157 else {
143158 const live = await open({ 'x-fixture-execution-chunk': '1' })
144 let complete: ExecutionView | undefined, text = ''
145 const decoder = new TextDecoder()
146 while (!complete) {
147 const part = await live.reader.read()
148 if (part.done) console.log(JSON.stringify({ oracle: 'terminal-preparation-ended', scenario, nativeRoutes, remainingMs: deadline - Date.now(), phase: slot.phase, reason: slot.reason, producer: slot.producer, credit: Atomics.load(slot.control, executionWords.credit), emitted: Atomics.load(slot.control, executionWords.emitted), returned: Atomics.load(slot.control, executionWords.returned), pending: executionOwner().pendingChecks }))
149 assert(!part.done)
150 text += decoder.decode(part.value, { stream: true })
151 for (let end = text.indexOf('\n\n'); end >= 0; end = text.indexOf('\n\n')) {
152 const frame = text.slice(0, end); text = text.slice(end + 2)
153 if (!frame.startsWith('data: ')) continue
154 const value = JSON.parse(frame.slice(6)) as { data: ExecutionView }
155 if (value.data.phase === 'completed') complete = value.data
159 const activeSlot = slot
160 const complete = await observe('producer-terminal', async () => {
161 let complete: ExecutionView | undefined, text = ''
162 const decoder = new TextDecoder()
163 while (!complete) {
164 const part = await live.reader.read()
165 if (part.done) console.log(JSON.stringify({ oracle: 'terminal-preparation-ended', scenario, nativeRoutes, remainingMs: deadline - Date.now(), phase: activeSlot.phase, reason: activeSlot.reason, producer: activeSlot.producer, credit: Atomics.load(activeSlot.control, executionWords.credit), emitted: Atomics.load(activeSlot.control, executionWords.emitted), returned: Atomics.load(activeSlot.control, executionWords.returned), pending: executionOwner().pendingChecks }))
166 assert(!part.done)
167 text += decoder.decode(part.value, { stream: true })
168 for (let end = text.indexOf('\n\n'); end >= 0; end = text.indexOf('\n\n')) {
169 const frame = text.slice(0, end); text = text.slice(end + 2)
170 if (!frame.startsWith('data: ')) continue
171 const value = JSON.parse(frame.slice(6)) as { data: ExecutionView }
172 if (value.data.phase === 'completed') complete = value.data
173 }
156174 }
157 }
175 return complete
176 })
158177 console.log(JSON.stringify({ oracle: 'terminal-preparation-completed', scenario, nativeRoutes, remainingMs: deadline - Date.now(), phase: slot.phase, reason: slot.reason, producer: slot.producer, credit: Atomics.load(slot.control, executionWords.credit), emitted: Atomics.load(slot.control, executionWords.emitted), returned: Atomics.load(slot.control, executionWords.returned) }))
159178 if (scenario === 'chunk') {
160179 live.abort.abort(); await live.reader.cancel()
161180 // Leave no native queue idle while waiting. Reconnect the SAME retained
162181 // execution within one heartbeat of expiry, then hold its final read.
163 await Bun.sleep(Math.max(1, deadline - Date.now() - 1500))
182 await observe('terminal-reconnect-wait', () => Bun.sleep(Math.max(1, deadline - Date.now() - 1500)))
164183 const final = await open({ 'x-fixture-execution-final-chunk': '1' })
165184 await Bun.sleep(10)
166185 await wait(() => executionOwner().pendingChecks === 0, 'Terminal reconnect setup native checks must settle', 500)
@@ -169,7 +188,7 @@ try {
169188 f.database.db.primary.setTransactionDefaults({ afterCommit: async () => {
170189 if (!crossed && getCurrentRequest()?.headers.has('x-fixture-execution-final-chunk')) await cross()
171190 } })
172 assert.equal((await final.reader.read()).done, true, 'Opaque chunk is withheld when its actual native check COMMIT crosses retention')
191 assert.equal((await observe('final-chunk-read', () => final.reader.read())).done, true, 'Opaque chunk is withheld when its actual native check COMMIT crosses retention')
173192 assert.equal(crossed, 1)
174193 }
175194 else {
@@ -182,7 +201,7 @@ try {
182201 f.database.db.primary.setTransactionDefaults({ afterCommit: async () => {
183202 if (inserted && !crossed && getCurrentRequest()?.headers.has('x-fixture-execution-admission')) await cross()
184203 } })
185 const result = await send('/admission', { execution: started.execution, scope, digest: complete.completion!.digest, expectedVersion: initialVersion }, { 'x-fixture-execution-admission': '1' })
204 const result = await observe('admission-request', () => send('/admission', { execution: started!.execution, scope, digest: complete.completion!.digest, expectedVersion: initialVersion }, { 'x-fixture-execution-admission': '1' }))
186205 assert.equal(result.status, 404, 'A genuinely committed admission cannot release past its authority deadline')
187206 assert.equal(crossed, 1)
188207 assert(inserted, 'The actual checked writer inserted the source before its native COMMIT wait')
@@ -213,15 +232,21 @@ finally {
213232 f.database.db.primary.setTransactionDefaults({ afterCommit: undefined })
214233 removeQueries?.()
215234 for (const abort of aborts) abort.abort()
216 await Promise.allSettled([...readers].map(reader => reader.cancel()))
217 await cleanup?.()
218 if (slot?.producer === 'pending') {
219 const until = Date.now() + 4000
220 while (slot.producer === 'pending' && Date.now() < until) await Bun.sleep(20)
221 if (slot.producer === 'pending') slot.worker?.terminate()
222 }
223 const until = Date.now() + 5000
224 while (executionOwner().pendingChecks && Date.now() < until) await Bun.sleep(10)
235 await observe('cleanup-readers', () => Promise.allSettled([...readers].map(reader => reader.cancel())))
236 await observe('cleanup-execution', async () => { await cleanup?.() })
237 await observe('cleanup-producer', async () => {
238 if (slot?.producer === 'pending') {
239 const until = Date.now() + 4000
240 while (slot.producer === 'pending' && Date.now() < until) await Bun.sleep(20)
241 if (slot.producer === 'pending') slot.worker?.terminate()
242 }
243 })
244 await observe('cleanup-pending-checks', async () => {
245 const until = Date.now() + 5000
246 while (executionOwner().pendingChecks && Date.now() < until) await Bun.sleep(10)
247 })
225248 assert.equal(executionOwner().pendingChecks, 0)
226 await server.stop(true); await stopServer(); await f.database.closeDatabaseConnection()
249 await observe('cleanup-server', async () => { await server.stop(true) })
250 await observe('cleanup-realtime', stopServer)
251 await observe('cleanup-database', () => f.database.closeDatabaseConnection())
227252}
tests/unit/public-safety-execution-http-limits.test.tsmodified+48-10
@@ -1,25 +1,63 @@
11import { expect, test } from 'bun:test'
2import { mkdtemp, rm, writeFile } from 'node:fs/promises'
2import { mkdir, mkdtemp, rm, writeFile } from 'node:fs/promises'
33import { tmpdir } from 'node:os'
4import { join } from 'node:path'
4import { join, resolve } from 'node:path'
55
66for (const nativeRoutes of [false, true]) for (const scenario of ['limits', 'preflight', 'middleware', 'chunk', 'admission']) test(`native execution HTTP ${scenario} nativeRoutes=${nativeRoutes}`, async () => {
7 const directory = await mkdtemp(join(tmpdir(), 'drone-incident-access-execution-http-limits-'))
7 const evidence = process.env.EXECUTION_HTTP_EVIDENCE
8 if (evidence) await mkdir(resolve(evidence), { recursive: true, mode: 0o700 })
9 const directory = await mkdtemp(join(evidence ? resolve(evidence) : tmpdir(), 'drone-incident-access-execution-http-limits-'))
810 let child: ReturnType<typeof Bun.spawn> | undefined
11 let settledExitCode: number | null = null, settledAtMs: number | null = null
12 let watchdogFired = false, watchdogKill = false, cleanupKill = false, completed = false
13 let stdoutWritten = false, stderrWritten = false
14 const began = performance.now()
15 const report = (message: string, error = false) => {
16 try { if (error) console.error(message); else console.log(message) }
17 catch {} // Evidence delivery cannot replace a settled child verdict.
18 }
19 const retain = async (artifact: 'fixture.stdout' | 'fixture.stderr' | 'lifecycle.json', contents: string) => {
20 try { await writeFile(join(directory, artifact), contents, { mode: 0o600, flag: 'wx' }); return true }
21 catch {
22 report(`HTTP_FIXTURE_EVIDENCE_UNAVAILABLE ${JSON.stringify({ scenario, nativeRoutes, artifact })}`, true)
23 return false
24 }
25 }
926 try {
1027 const config = join(directory, 'bunfig.toml'); await writeFile(config, 'preload=[]\n[install]\nauto="disable"\n')
1128 const running = child = Bun.spawn([process.execPath, '--no-install', `--config=${config}`, '--no-env-file', `${import.meta.dir}/../fixtures/public-safety-access/execution-http-limits.ts`, scenario], {
1229 cwd: directory, env: { ...process.env, APP_ENV: 'test', NODE_ENV: 'test', DB_CONNECTION: 'sqlite', DB_DATABASE_PATH: join(directory, 'access.sqlite'), INCIDENT_NATIVE_ROUTES: String(nativeRoutes) }, stdout: 'pipe', stderr: 'pipe',
1330 })
14 const timeout = setTimeout(() => { if (running.exitCode === null) running.kill('SIGKILL') }, 35000)
31 const exited = running.exited.then(code => { settledExitCode = code; settledAtMs = performance.now() - began; return code })
32 const timeout = setTimeout(() => {
33 watchdogFired = true
34 if (settledExitCode !== null) return
35 watchdogKill = true
36 running.kill('SIGKILL')
37 report(JSON.stringify({ oracle: 'execution-http-watchdog', scenario, nativeRoutes, pid: running.pid, timeoutMs: 35000, elapsedMs: performance.now() - began, requestedSignal: 'SIGKILL' }), true)
38 }, 35000)
1539 try {
16 const [code, stdout, stderr] = await Promise.all([running.exited, new Response(running.stdout).text(), new Response(running.stderr).text()])
40 report(JSON.stringify({ oracle: 'execution-http-fixture-start', scenario, nativeRoutes, pid: running.pid, parentBunVersion: Bun.version, childExecutable: process.execPath, timeoutMs: 35000 }))
41 const [code, stdout, stderr] = await Promise.all([exited, new Response(running.stdout).text(), new Response(running.stderr).text()])
1742 // eslint-disable-next-line no-console
18 for (const line of stdout.split('\n')) if (line.startsWith('{"oracle":')) console.log(line)
19 expect(code, `${stdout}\n${stderr}`).toBe(0)
20 expect(stdout).toContain(`PASS native execution HTTP ${scenario} nativeRoutes=${nativeRoutes}`)
43 for (const line of stdout.split('\n')) if (line.startsWith('{"oracle":')) report(line)
44 stdoutWritten = await retain('fixture.stdout', stdout)
45 stderrWritten = await retain('fixture.stderr', stderr)
46 expect(code, JSON.stringify({ scenario, nativeRoutes, settledExitCode, signal: running.signalCode, watchdogFired, watchdogKill, elapsedMs: performance.now() - began })).toBe(0)
47 expect(stdout.includes(`PASS native execution HTTP ${scenario} nativeRoutes=${nativeRoutes}`), 'HTTP fixture completion sentinel is missing; raw output is retained privately').toBe(true)
48 completed = true
49 }
50 finally { clearTimeout(timeout); if (settledExitCode === null) { cleanupKill = true; running.kill('SIGKILL') }; settledExitCode = await exited }
51 }
52 finally {
53 if (child && settledExitCode === null) {
54 if (child.exitCode === null && child.signalCode === null) { cleanupKill = true; child.kill('SIGKILL') }
55 settledExitCode = await child.exited
2156 }
22 finally { if (running.exitCode === null) running.kill('SIGKILL'); await running.exited; clearTimeout(timeout) }
57 const lifecycle = { scenario, nativeRoutes, pid: child?.pid ?? null, settledExitCode, exitProperty: child?.exitCode ?? null, signal: child?.signalCode ?? null, timeoutMs: 35000, watchdogFired, watchdogKill, cleanupKill, settledAtMs, elapsedMs: performance.now() - began, stdoutWritten, stderrWritten, completed }
58 report(JSON.stringify({ oracle: 'execution-http-fixture-exit', ...lifecycle }))
59 const lifecycleWritten = await retain('lifecycle.json', JSON.stringify(lifecycle, null, 2))
60 if (completed && stdoutWritten && stderrWritten && lifecycleWritten) await rm(directory, { recursive: true, force: true })
61 else report(`HTTP_FIXTURE_RETAINED ${directory}`, true)
2362 }
24 finally { if (child?.exitCode === null) { child.kill('SIGKILL'); await child.exited }; await rm(directory, { recursive: true, force: true }) }
2563}, 40000)