also looking at this
test: retain execution lifetime failure observations
#62
10 files
+174
-64
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.
| @@ -116,3 +116,18 @@ EXECUTION_BROWSER_QA=true BROWSE_BROWSER=/path/to/google-chrome bun test tests/u | ||
| 116 | 116 | Native controller and HTTP checks separately cover authority replacement, |
| 117 | 117 | elapsed deadlines, stream capacity, cleanup and durable COMMIT with a withheld |
| 118 | 118 | response. The existing workspace browser scenarios remain required regressions. |
| 119 | ||
| 120 | The native lifetime fixture emits bounded phase observations around setup, | |
| 121 | authority reads, retention waits and cleanup. Its parent records the observed | |
| 122 | exit code and signal separately from whether its own watchdog fired or cleanup | |
| 123 | requested a kill. Elapsed time includes process work and output handling, not | |
| 124 | just a native check. Failed cases retain their private temporary directory, | |
| 125 | stdout, stderr and lifecycle receipt when storage permits. A fixed warning | |
| 126 | reports an unavailable receipt if that write fails. Successful cases remove | |
| 127 | their temporary files as before. | |
| 128 | ||
| 129 | These observations support [the unresolved Mac failure](https://github.com/stacksjs/drone/issues/60); | |
| 130 | they do not establish its cause or repair it. The production authority-check | |
| 131 | limit, actual 60-second retention, 90-second child watchdog and 100-second test | |
| 132 | guard are unchanged. An observed signal or watchdog marker alone does not prove | |
| 133 | an individually joined Worker thread or the cause of an earlier exit. | |
| @@ -3,20 +3,31 @@ import { setupExecutionLifetime } from './execution-lifetime-setup' | ||
| 3 | 3 | |
| 4 | 4 | const mode = Bun.argv[2] |
| 5 | 5 | assert(mode === 'completed' || mode === 'canceled' || mode === 'quarantine') |
| 6 | const h = await setupExecutionLifetime(mode) | |
| 6 | const began = performance.now() | |
| 7 | let observations = 0 | |
| 8 | async function observe<T>(phase: string, work: () => Promise<T>): Promise<T> { | |
| 9 | const emit = (outcome: 'began' | 'settled' | 'rejected') => { | |
| 10 | assert(observations < 128 && phase.length <= 64) | |
| 11 | console.log(JSON.stringify({ oracle: 'lifetime-phase', mode, ordinal: observations++, phase, outcome, elapsedMs: performance.now() - began })) | |
| 12 | } | |
| 13 | emit('began') | |
| 14 | try { const result = await work(); emit('settled'); return result } | |
| 15 | catch (error) { emit('rejected'); throw error } | |
| 16 | } | |
| 17 | const h = await observe('setup', () => setupExecutionLifetime(mode)) | |
| 7 | 18 | let attachment: Awaited<ReturnType<typeof h.core.attachIncidentExecution>> | undefined |
| 8 | 19 | let expiredClose: string | null = null |
| 9 | 20 | try { |
| 10 | const run = await h.start() | |
| 21 | const run = await observe('start', h.start) | |
| 11 | 22 | const ack = h.captureFinished(run.slot, mode === 'quarantine') |
| 12 | await h.sourceZero() | |
| 23 | await observe('source-zero', h.sourceZero) | |
| 13 | 24 | if (mode === 'completed') { |
| 14 | 25 | let last = 0 |
| 15 | attachment = await h.f.as(h.f.senderToken, async () => h.core.attachIncidentExecution(h.core.captureExecutionContext(h.key), run.locator, value => { | |
| 26 | attachment = await observe('attach', () => h.f.as(h.f.senderToken, async () => h.core.attachIncidentExecution(h.core.captureExecutionContext(h.key), run.locator, value => { | |
| 16 | 27 | if (!value.latestEvent || value.latestEvent.sequence === last) return |
| 17 | 28 | assert.equal(value.latestEvent.sequence, ++last) |
| 18 | })) | |
| 19 | await attachment.activate() | |
| 29 | }))) | |
| 30 | await observe('activate', () => attachment!.activate()) | |
| 20 | 31 | await h.wait(() => run.slot.phase === 'completed', 'The real eight-second producer must complete', 20000) |
| 21 | 32 | assert(ack.event) |
| 22 | 33 | assert.equal(ack.event.data.outcome, 'completed') |
| @@ -31,7 +42,7 @@ try { | ||
| 31 | 42 | assert.equal(Atomics.load(run.slot.control, h.executionWords.credit), 0) |
| 32 | 43 | assert.equal(Atomics.load(run.slot.control, h.executionWords.returned), 0) |
| 33 | 44 | const stoppingAt = performance.now() |
| 34 | const stopping = await h.core.closeIncidentExecution(h.context, run.locator) | |
| 45 | const stopping = await observe('close', () => h.core.closeIncidentExecution(h.context, run.locator)) | |
| 35 | 46 | assert.equal(stopping.phase, 'stopping') |
| 36 | 47 | await h.wait(() => Boolean(ack.event), 'Capture a genuine finished ACK from the canceled actual Worker') |
| 37 | 48 | assert.equal(ack.event!.data.outcome, 'canceled') |
| @@ -55,16 +66,16 @@ try { | ||
| 55 | 66 | const expiry = run.slot.metadataDeadline |
| 56 | 67 | const observedAt = Date.now(), observedMonotonic = performance.now() |
| 57 | 68 | assert(expiry > observedAt + 50000, 'The actual unshortened terminal TTL must still be mostly ahead') |
| 58 | await h.sourceZero() | |
| 69 | await observe('source-zero', h.sourceZero) | |
| 59 | 70 | console.log(JSON.stringify({ oracle: 'actual-retention-begins', mode, configuredMs: h.limits.retainedMs, remainingMs: expiry - observedAt, producer: run.slot.producer })) |
| 60 | 71 | // Scalar time/slot observation only, not repeated native authority polling. |
| 61 | await h.untilWall(expiry - 1000) | |
| 72 | await observe('wait-before-expiry', () => h.untilWall(expiry - 1000)) | |
| 62 | 73 | assert.equal(h.executionOwner().slot, run.slot, 'Reservation remains during the actual retained lifetime') |
| 63 | const retained = await h.core.readIncidentExecution(h.context, { scope: h.scope }) | |
| 74 | const retained = await observe('retained-read', () => h.core.readIncidentExecution(h.context, { scope: h.scope })) | |
| 64 | 75 | assert.equal(retained?.execution, run.view.execution) |
| 65 | 76 | assert.equal(retained.producer, mode === 'quarantine' ? 'unconfirmed' : 'finished') |
| 66 | 77 | assert.equal(run.slot.metadataDeadline, expiry, 'Reads do not renew retention') |
| 67 | await h.untilWall(expiry + 100) | |
| 78 | await observe('wait-after-expiry', () => h.untilWall(expiry + 100)) | |
| 68 | 79 | if (mode === 'quarantine') { |
| 69 | 80 | assert.equal(h.executionOwner().slot, run.slot, 'Actual TTL cannot free an unconfirmed reservation') |
| 70 | 81 | try { assert.equal((await h.core.closeIncidentExecution(h.context, run.locator)).producer, 'unconfirmed'); expiredClose = 'unconfirmed-view' } |
| @@ -84,20 +95,20 @@ try { | ||
| 84 | 95 | await h.wait(() => h.executionOwner().slot === null, 'The real retention timer must dispose the confirmed slot') |
| 85 | 96 | h.assertCleared(run.slot) |
| 86 | 97 | assert.equal(run.slot.worker, null) |
| 87 | assert.equal(await h.core.readIncidentExecution(h.context, { scope: h.scope }), null) | |
| 98 | assert.equal(await observe('expired-read', () => h.core.readIncidentExecution(h.context, { scope: h.scope })), null) | |
| 88 | 99 | if (mode === 'completed') { |
| 89 | const next = await h.start() | |
| 100 | const next = await observe('next-start', h.start) | |
| 90 | 101 | assert.notEqual(next.view.execution, run.view.execution) |
| 91 | 102 | assert.equal(next.view.phase, 'waiting-for-consumer') |
| 92 | 103 | await h.wait(() => Atomics.load(next.slot.control, h.executionWords.emitted) === 1, 'A new explicit start constructs a new real producer') |
| 93 | await h.core.closeIncidentExecution(h.context, next.locator) | |
| 104 | await observe('next-close', () => h.core.closeIncidentExecution(h.context, next.locator)) | |
| 94 | 105 | await h.wait(() => next.slot.producer === 'finished', 'New explicit producer cooperatively finishes') |
| 95 | await h.core.closeIncidentExecution(h.context, next.locator) | |
| 106 | await observe('next-release', () => h.core.closeIncidentExecution(h.context, next.locator)) | |
| 96 | 107 | assert.equal(h.executionOwner().slot, null) |
| 97 | 108 | } |
| 98 | 109 | } |
| 99 | await h.sourceZero() | |
| 110 | await observe('source-zero', h.sourceZero) | |
| 100 | 111 | console.log(JSON.stringify({ oracle: 'actual-retention-ended', mode, elapsedSinceObservationMs: performance.now() - observedMonotonic, expiryPassedMs: Date.now() - expiry, slotRetained: h.executionOwner().slot === run.slot, producer: run.slot.producer, sourceCount: 0, expiredClose, lateAckControlled: mode === 'quarantine', actualIndividualThreadJoinQualified: false })) |
| 101 | 112 | console.log(`PASS native execution lifetime ${mode}`) |
| 102 | 113 | } |
| 103 | finally { attachment?.release(); await h.close() } | |
| 114 | finally { attachment?.release(); await observe('cleanup', h.close) } | |
| @@ -6,18 +6,36 @@ import { join } from 'node:path' | ||
| 6 | 6 | for (const mode of ['completed', 'canceled', 'quarantine']) test(`native execution lifetime ${mode}`, async () => { |
| 7 | 7 | const root = await mkdtemp(join(tmpdir(), 'drone-incident-access-execution-lifetime-')) |
| 8 | 8 | let child: ReturnType<typeof Bun.spawn> | undefined |
| 9 | const began = performance.now() | |
| 10 | let deadlineFired = false, cleanupKill = false, completed = false | |
| 9 | 11 | try { |
| 10 | 12 | const config = join(root, 'bunfig.toml'); await writeFile(config, 'preload=[]\n[install]\nauto="disable"\n') |
| 11 | 13 | const running = child = Bun.spawn([process.execPath, '--no-install', `--config=${config}`, '--no-env-file', `${import.meta.dir}/../fixtures/public-safety-access/execution-lifetime.ts`, mode], { cwd: root, env: { APP_ENV: 'test', APP_DEBUG: 'false', NODE_ENV: 'test', DB_CONNECTION: 'sqlite', DB_DATABASE_PATH: join(root, 'access.sqlite') }, stdin: 'ignore', stdout: 'pipe', stderr: 'pipe' }) |
| 12 | const timeout = setTimeout(() => { if (running.exitCode === null) running.kill('SIGKILL') }, 90000) | |
| 14 | const timeout = setTimeout(() => { | |
| 15 | if (running.exitCode !== null) return | |
| 16 | deadlineFired = true | |
| 17 | running.kill('SIGKILL') | |
| 18 | console.error('LIFETIME_FIXTURE_DEADLINE', JSON.stringify({ mode, pid: running.pid, timeoutMs: 90000, elapsedMs: performance.now() - began, requestedSignal: 'SIGKILL' })) | |
| 19 | }, 90000) | |
| 13 | 20 | try { |
| 14 | 21 | const [code, stdout, stderr] = await Promise.all([running.exited, new Response(running.stdout).text(), new Response(running.stderr).text()]) |
| 22 | await writeFile(join(root, 'fixture.stdout'), stdout, { mode: 0o600 }) | |
| 23 | await writeFile(join(root, 'fixture.stderr'), stderr, { mode: 0o600 }) | |
| 15 | 24 | // eslint-disable-next-line no-console |
| 16 | 25 | for (const line of stdout.split('\n')) if (line.startsWith('{"oracle":')) console.log(line) |
| 17 | 26 | expect(code, `${stdout}\n${stderr}`).toBe(0) |
| 18 | 27 | expect(stdout).toContain(`PASS native execution lifetime ${mode}`) |
| 28 | completed = true | |
| 19 | 29 | } |
| 20 | finally { if (running.exitCode === null) running.kill('SIGKILL'); await running.exited; clearTimeout(timeout) } | |
| 30 | finally { clearTimeout(timeout); if (running.exitCode === null) { cleanupKill = true; running.kill('SIGKILL') }; await running.exited } | |
| 31 | } | |
| 32 | finally { | |
| 33 | if (child?.exitCode === null) { cleanupKill = true; child.kill('SIGKILL'); await child.exited } | |
| 34 | const lifecycle = { mode, pid: child?.pid ?? null, exitCode: child?.exitCode ?? null, signal: child?.signalCode ?? null, timeoutMs: 90000, deadlineFired, cleanupKill, elapsedMs: performance.now() - began, completed } | |
| 35 | console.log(JSON.stringify({ oracle: 'lifetime-fixture-exit', ...lifecycle })) | |
| 36 | try { await writeFile(join(root, 'lifecycle.json'), JSON.stringify(lifecycle, null, 2), { mode: 0o600 }) } | |
| 37 | catch { console.error('LIFETIME_FIXTURE_EVIDENCE_UNAVAILABLE', JSON.stringify({ mode })) } | |
| 38 | if (completed) await rm(root, { recursive: true, force: true }) | |
| 39 | else console.error('LIFETIME_FIXTURE_RETAINED', root) | |
| 21 | 40 | } |
| 22 | finally { if (child?.exitCode === null) { child.kill('SIGKILL'); await child.exited }; await rm(root, { recursive: true, force: true }) } | |
| 23 | 41 | }, 100000) |