diff --git a/lib/shared/autorouter-diagnostics.ts b/lib/shared/autorouter-diagnostics.ts index 9a043cd44..937c95045 100644 --- a/lib/shared/autorouter-diagnostics.ts +++ b/lib/shared/autorouter-diagnostics.ts @@ -53,6 +53,7 @@ type CircuitJsonLookup = { } type AutoroutingEventPayload = { + isolatedSubcircuitPath?: string[] subcircuit_id?: string subcircuitId?: string componentDisplayName?: string @@ -87,6 +88,10 @@ type AutoroutingEventPayload = { } type ActivePhase = { + key: string + subcircuitKey: string + isolatedSubcircuitPath: string[] + artifactDirectory: string subcircuitId: string componentDisplayName: string phaseName?: string @@ -180,10 +185,13 @@ export class AutorouterDiagnostics { Omit private phaseOrdinalBySubcircuit = new Map() private traceCountBySubcircuit = new Map() - private activePhase: ActivePhase | null = null + private activePhases = new Map() + private primarySubcircuitId?: string + private isolatedCompletedPhaseTraces = new Map() private completedPhaseTraces: AutorouterTrace[] = [] private hasWrittenPlacementSnapshot = false private targetPhaseReached = false + private targetPhaseReachedBySubcircuit = new Set() private summary: Array> = [] private rootCircuit: any @@ -230,17 +238,19 @@ export class AutorouterDiagnostics { checkTimeout() { this.checkLongRunning() - if (!this.options.timeoutMs || !this.activePhase) return + if (!this.options.timeoutMs) return - const elapsedMs = performance.now() - this.activePhase.startedAt - if (elapsedMs < this.options.timeoutMs) return + for (const activePhase of this.activePhases.values()) { + const elapsedMs = performance.now() - activePhase.startedAt + if (elapsedMs < this.options.timeoutMs) continue - const artifactPath = this.writeTimeoutArtifact(this.activePhase, elapsedMs) - const phaseLabel = this.getPhaseLabel(this.activePhase) - const message = `Autorouter timeout after ${this.formatElapsed(elapsedMs)} in ${phaseLabel}. Set a different timeout with \`--autorouter-timeout \` (for example, \`--autorouter-timeout 2m\`).` - this.log(kleur.red(message)) + const artifactPath = this.writeTimeoutArtifact(activePhase, elapsedMs) + const phaseLabel = this.getPhaseLabel(activePhase) + const message = `Autorouter timeout after ${this.formatElapsed(elapsedMs)} in ${phaseLabel}. Set a different timeout with \`--autorouter-timeout \` (for example, \`--autorouter-timeout 2m\`).` + this.log(kleur.red(message)) - throw new AutorouterPhaseTimeoutError(message, artifactPath) + throw new AutorouterPhaseTimeoutError(message, artifactPath) + } } finalize(circuitJson?: CircuitJson) { @@ -263,14 +273,16 @@ export class AutorouterDiagnostics { } private handleStart(event: AutoroutingEventPayload) { - if (this.targetPhaseReached) return - const simpleRouteJson = event.simpleRouteJson const subcircuitId = event.subcircuit_id ?? event.subcircuitId ?? "unknown-subcircuit" - const previousOrdinal = this.phaseOrdinalBySubcircuit.get(subcircuitId) ?? 0 + const isolatedSubcircuitPath = event.isolatedSubcircuitPath ?? [] + const subcircuitKey = JSON.stringify([isolatedSubcircuitPath, subcircuitId]) + if (this.targetPhaseReachedBySubcircuit.has(subcircuitKey)) return + const previousOrdinal = + this.phaseOrdinalBySubcircuit.get(subcircuitKey) ?? 0 const phaseOrdinal = event.phaseOrdinal ?? previousOrdinal + 1 - this.phaseOrdinalBySubcircuit.set(subcircuitId, phaseOrdinal) + this.phaseOrdinalBySubcircuit.set(subcircuitKey, phaseOrdinal) const routingPhaseIndex = event.routingPhaseIndex ?? phaseOrdinal - 1 const connectionCount = event.connectionCount ?? simpleRouteJson?.connections?.length ?? 0 @@ -278,10 +290,24 @@ export class AutorouterDiagnostics { event.obstacleCount ?? simpleRouteJson?.obstacles?.length ?? 0 const previousTraceCount = event.previousTraceCount ?? - this.traceCountBySubcircuit.get(subcircuitId) ?? + this.traceCountBySubcircuit.get(subcircuitKey) ?? 0 - this.activePhase = { + const key = JSON.stringify([ + subcircuitKey, + routingPhaseIndex, + phaseOrdinal, + event.phaseName, + event.phaseStageIndex, + ]) + const activePhase: ActivePhase = { + key, + subcircuitKey, + isolatedSubcircuitPath, + artifactDirectory: this.getArtifactDirectory( + subcircuitId, + isolatedSubcircuitPath, + ), subcircuitId, componentDisplayName: event.componentDisplayName ?? "subcircuit", phaseName: event.phaseName, @@ -309,7 +335,13 @@ export class AutorouterDiagnostics { longRunningLoggingStarted: false, } - if (this.options.enabled && !this.hasWrittenPlacementSnapshot) { + this.activePhases.set(key, activePhase) + + if ( + this.options.enabled && + isolatedSubcircuitPath.length === 0 && + !this.hasWrittenPlacementSnapshot + ) { const placementCircuitJson = this.getCurrentCircuitJson().filter( (element) => !this.isRouteElement(element), ) as AnyCircuitElement[] @@ -320,32 +352,33 @@ export class AutorouterDiagnostics { } if (this.options.enabled) { - this.logPhaseStart(this.activePhase) + this.logPhaseStart(activePhase) } if (this.shouldDumpInput(routingPhaseIndex)) { this.writeJson( - this.getPhaseFileName(this.activePhase, "input.simple-route.json"), + this.getPhaseFileName(activePhase, "input.simple-route.json"), simpleRouteJson ?? {}, ) } } private handleProgress(event: AutoroutingEventPayload) { - if (!this.activePhase) return + const activePhase = this.matchActivePhase(event) + if (!activePhase) return const now = performance.now() - this.activePhase.lastProgress = event - if (!this.shouldLogPhaseDetails(this.activePhase)) return + activePhase.lastProgress = event + if (!this.shouldLogPhaseDetails(activePhase)) return if ( - this.activePhase.lastProgressLogAt > 0 && - now - this.activePhase.lastProgressLogAt < PROGRESS_LOG_INTERVAL_MS + activePhase.lastProgressLogAt > 0 && + now - activePhase.lastProgressLogAt < PROGRESS_LOG_INTERVAL_MS ) { return } - this.activePhase.lastProgressLogAt = now + activePhase.lastProgressLogAt = now - this.logProgress(this.activePhase, event, now) + this.logProgress(activePhase, event, now) } private handleEnd(event: AutoroutingEventPayload) { @@ -361,10 +394,17 @@ export class AutorouterDiagnostics { activePhase.previousTraceCount + outputTraceCount this.traceCountBySubcircuit.set( - activePhase.subcircuitId, + activePhase.subcircuitKey, cumulativeTraceCount, ) - this.completedPhaseTraces.push(...(outputSrj?.traces ?? [])) + if (activePhase.isolatedSubcircuitPath.length > 0) { + const scopeKey = JSON.stringify(activePhase.isolatedSubcircuitPath) + const traces = this.isolatedCompletedPhaseTraces.get(scopeKey) ?? [] + traces.push(...(outputSrj?.traces ?? [])) + this.isolatedCompletedPhaseTraces.set(scopeKey, traces) + } else { + this.completedPhaseTraces.push(...(outputSrj?.traces ?? [])) + } this.summary.push({ subcircuit_id: activePhase.subcircuitId, componentDisplayName: activePhase.componentDisplayName, @@ -408,20 +448,25 @@ export class AutorouterDiagnostics { ) } - if (this.options.enabled) { + if ( + this.options.enabled && + activePhase.isolatedSubcircuitPath.length === 0 + ) { this.writePngSnapshot( - `phase-${activePhase.routingPhaseIndex}-routed.png`, + path.join( + activePhase.artifactDirectory, + `phase-${activePhase.routingPhaseIndex}-routed.png`, + ), this.getCircuitJsonWithCompletedPhaseTraces(), ) } if (this.isFinalTargetPhaseStage(activePhase)) { this.targetPhaseReached = true + this.targetPhaseReachedBySubcircuit.add(activePhase.subcircuitKey) } - if (this.activePhase === activePhase) { - this.activePhase = null - } + this.activePhases.delete(activePhase.key) } private handleError(event: AutoroutingEventPayload) { @@ -454,7 +499,7 @@ export class AutorouterDiagnostics { this.logPhaseStart(activePhase, "failed") } this.log( - ` ${this.getPhaseLabel(activePhase)} error after ${this.formatElapsed(elapsedMs)}: ${this.formatUserFacingText(error.message)}`, + ` ${this.getPhaseLabel(activePhase)} error after ${this.formatElapsed(elapsedMs)}: ${this.formatUserFacingText(error.message, activePhase.isolatedSubcircuitPath.length > 0)}`, ) } @@ -483,11 +528,10 @@ export class AutorouterDiagnostics { if (this.isFinalTargetPhaseStage(activePhase)) { this.targetPhaseReached = true + this.targetPhaseReachedBySubcircuit.add(activePhase.subcircuitKey) } - if (this.activePhase === activePhase) { - this.activePhase = null - } + this.activePhases.delete(activePhase.key) } private writeTimeoutArtifact(activePhase: ActivePhase, elapsedMs: number) { @@ -500,11 +544,20 @@ export class AutorouterDiagnostics { "previous-output.traces.json", ) const timeoutFile = this.getPhaseFileName(activePhase, "timeout.json") - const boardFile = "board.source-and-pcb.circuit.json" + const boardFile = + activePhase.isolatedSubcircuitPath.length === 0 + ? "board.source-and-pcb.circuit.json" + : undefined + const previousTraces = + activePhase.isolatedSubcircuitPath.length > 0 + ? (this.isolatedCompletedPhaseTraces.get( + JSON.stringify(activePhase.isolatedSubcircuitPath), + ) ?? []) + : this.completedPhaseTraces this.writeJson(inputFile, activePhase.simpleRouteJson ?? {}) - this.writeJson(previousTracesFile, this.completedPhaseTraces) - this.writeJson(boardFile, this.getCurrentCircuitJson()) + this.writeJson(previousTracesFile, previousTraces) + if (boardFile) this.writeJson(boardFile, this.getCurrentCircuitJson()) return this.writeJson(timeoutFile, { type: "autorouter_phase_timeout", @@ -531,10 +584,11 @@ export class AutorouterDiagnostics { } private checkLongRunning() { - if (!this.activePhase) return - const elapsedMs = performance.now() - this.activePhase.startedAt - if (!this.didCrossLongRunningThreshold(this.activePhase, elapsedMs)) return - this.startLongRunningLogging(this.activePhase, elapsedMs) + for (const activePhase of this.activePhases.values()) { + const elapsedMs = performance.now() - activePhase.startedAt + if (!this.didCrossLongRunningThreshold(activePhase, elapsedMs)) continue + this.startLongRunningLogging(activePhase, elapsedMs) + } } private didCrossLongRunningThreshold( @@ -571,10 +625,13 @@ export class AutorouterDiagnostics { private logPhaseStart(activePhase: ActivePhase, reason?: string) { const reasonText = reason ? ` ${reason}` : "" this.log( - `Autorouting ${this.formatUserFacingText(activePhase.componentDisplayName)} ${this.getPhaseLabel(activePhase)}${reasonText} start: connections=${activePhase.connectionCount}, obstacles=${activePhase.obstacleCount}, previous_traces=${activePhase.previousTraceCount}${activePhase.routerDescription ? `, ${activePhase.routerDescription}` : ""}`, + `Autorouting ${this.formatUserFacingText(activePhase.componentDisplayName, activePhase.isolatedSubcircuitPath.length > 0)} ${this.getPhaseLabel(activePhase)}${reasonText} start: connections=${activePhase.connectionCount}, obstacles=${activePhase.obstacleCount}, previous_traces=${activePhase.previousTraceCount}${activePhase.routerDescription ? `, ${activePhase.routerDescription}` : ""}`, ) - const connectionNames = this.getConnectionNames(activePhase.simpleRouteJson) + const connectionNames = this.getConnectionNames( + activePhase.simpleRouteJson, + activePhase.isolatedSubcircuitPath.length > 0, + ) if (connectionNames.length > 0) { this.log(` connections: ${connectionNames.join(", ")}`) } @@ -628,13 +685,39 @@ export class AutorouterDiagnostics { ) } - private matchActivePhase(event: AutoroutingEventPayload) { - if (!this.activePhase) return null + private matchActivePhase(event: AutoroutingEventPayload): ActivePhase | null { + const scopeKey = JSON.stringify(event.isolatedSubcircuitPath ?? []) const subcircuitId = event.subcircuit_id ?? event.subcircuitId - if (subcircuitId && subcircuitId !== this.activePhase.subcircuitId) { - return null - } - return this.activePhase + const matches = [...this.activePhases.values()].filter((activePhase) => { + if (JSON.stringify(activePhase.isolatedSubcircuitPath) !== scopeKey) { + return false + } + if (subcircuitId && subcircuitId !== activePhase.subcircuitId) + return false + if ( + event.routingPhaseIndex != null && + event.routingPhaseIndex !== activePhase.routingPhaseIndex + ) + return false + if ( + event.phaseOrdinal !== undefined && + event.phaseOrdinal !== activePhase.phaseOrdinal + ) + return false + if ( + event.phaseName !== undefined && + event.phaseName !== activePhase.phaseName + ) + return false + if ( + event.phaseStageIndex !== undefined && + event.phaseStageIndex !== activePhase.phaseStageIndex + ) + return false + return true + }) + // Legacy events can omit phase metadata, but must still identify one phase. + return matches.length === 1 ? matches[0] : null } private shouldDumpInput(routingPhaseIndex: number) { @@ -661,8 +744,8 @@ export class AutorouterDiagnostics { private writeJson(fileName: string, value: unknown) { const debugDir = path.resolve(this.options.debugDir ?? DEFAULT_DEBUG_DIR) - fs.mkdirSync(debugDir, { recursive: true }) const filePath = path.join(debugDir, fileName) + fs.mkdirSync(path.dirname(filePath), { recursive: true }) fs.writeFileSync(filePath, JSON.stringify(value, null, 2)) this.logArtifact(filePath) return filePath @@ -677,8 +760,8 @@ export class AutorouterDiagnostics { const pcbSvg = convertCircuitJsonToPcbSvg(circuitJson, options) const png = convertSvgToPngBuffer(pcbSvg) const debugDir = path.resolve(this.options.debugDir ?? DEFAULT_DEBUG_DIR) - fs.mkdirSync(debugDir, { recursive: true }) const filePath = path.join(debugDir, fileName) + fs.mkdirSync(path.dirname(filePath), { recursive: true }) fs.writeFileSync(filePath, png) this.logArtifact(filePath) } catch (error) { @@ -752,12 +835,37 @@ export class AutorouterDiagnostics { return element.type === "pcb_trace" || element.type === "pcb_via" } + private getArtifactDirectory(subcircuitId: string, isolatedPath: string[]) { + const encodeSegment = (value: string) => + encodeURIComponent(value).replaceAll(".", "%2E") + if (isolatedPath.length > 0) { + return path.join( + "isolated", + ...isolatedPath.map(encodeSegment), + encodeSegment(subcircuitId), + ) + } + this.primarySubcircuitId ??= subcircuitId + return subcircuitId === this.primarySubcircuitId + ? "" + : path.join("subcircuits", encodeSegment(subcircuitId)) + } + private getPhaseFileName(activePhase: ActivePhase, suffix: string) { const phaseNumber = activePhase.routingPhaseIndex - return `phase-${phaseNumber}.${suffix}` + return path.join( + activePhase.artifactDirectory, + `phase-${phaseNumber}.${suffix}`, + ) } private getPhaseLabel(activePhase: ActivePhase) { + const scopeLabel = + activePhase.isolatedSubcircuitPath.length > 0 + ? ` [isolated ${activePhase.isolatedSubcircuitPath.join("/")}]` + : activePhase.artifactDirectory + ? ` [${activePhase.componentDisplayName}: ${activePhase.subcircuitId}]` + : "" const phaseName = activePhase.phaseName ? ` "${activePhase.phaseName}"` : "" const stageLabel = activePhase.phaseStageIndex !== undefined && @@ -766,9 +874,9 @@ export class AutorouterDiagnostics { ? ` stage ${activePhase.phaseStageIndex + 1}/${activePhase.phaseStageCount}` : "" if (activePhase.phaseCount) { - return `phase ${activePhase.phaseOrdinal}/${activePhase.phaseCount}${phaseName}${stageLabel}` + return `phase ${activePhase.phaseOrdinal}/${activePhase.phaseCount}${phaseName}${stageLabel}${scopeLabel}` } - return `phase ${activePhase.phaseOrdinal}${phaseName}${stageLabel}` + return `phase ${activePhase.phaseOrdinal}${phaseName}${stageLabel}${scopeLabel}` } private isFinalTargetPhaseStage(activePhase: ActivePhase) { @@ -820,6 +928,9 @@ export class AutorouterDiagnostics { private getExecutionMetadata(activePhase: ActivePhase) { return { + ...(activePhase.isolatedSubcircuitPath.length > 0 + ? { isolatedSubcircuitPath: activePhase.isolatedSubcircuitPath } + : {}), autorouterName: activePhase.autorouterName, autorouterVersion: activePhase.autorouterVersion, solverName: activePhase.solverName, @@ -830,8 +941,13 @@ export class AutorouterDiagnostics { } } - private getConnectionNames(simpleRouteJson?: SimpleRouteJson) { - const circuitJsonLookup = this.createCircuitJsonLookup() + private getConnectionNames( + simpleRouteJson?: SimpleRouteJson, + isolated = false, + ) { + const circuitJsonLookup: CircuitJsonLookup = isolated + ? { circuitJson: [], elementById: new Map() } + : this.createCircuitJsonLookup() return [ ...new Set( @@ -878,7 +994,9 @@ export class AutorouterDiagnostics { return null } - private formatUserFacingText(value: string) { + private formatUserFacingText(value: string, isolated = false) { + if (isolated) + return value.replace(CIRCUIT_JSON_ID_PATTERN, "internal element") const circuitJsonLookup = this.createCircuitJsonLookup() let formattedValue = value diff --git a/lib/shared/generate-circuit-json.tsx b/lib/shared/generate-circuit-json.tsx index 0879c2dad..0fb991617 100644 --- a/lib/shared/generate-circuit-json.tsx +++ b/lib/shared/generate-circuit-json.tsx @@ -170,24 +170,30 @@ export async function generateCircuitJson({ runner.add() - runner.render() - const loggedAsyncEffectNames = new Set() - while (!runner.isDoneRendering()) { - for (const asyncEffect of runner.getRunningAsyncEffects()) { - const asyncEffectName = asyncEffect.effectName - if (!asyncEffectName || loggedAsyncEffectNames.has(asyncEffectName)) { - continue + try { + runner.render() + + while (!runner.isDoneRendering()) { + for (const asyncEffect of runner.getRunningAsyncEffects()) { + const asyncEffectName = asyncEffect.effectName + if (!asyncEffectName || loggedAsyncEffectNames.has(asyncEffectName)) { + continue + } + + loggedAsyncEffectNames.add(asyncEffectName) + onAsyncEffectStatus?.(asyncEffectName) } - loggedAsyncEffectNames.add(asyncEffectName) - onAsyncEffectStatus?.(asyncEffectName) + autorouterDiagnostics.checkTimeout() + await new Promise((resolve) => setTimeout(resolve, 100)) + runner.render() } - - autorouterDiagnostics.checkTimeout() - await new Promise((resolve) => setTimeout(resolve, 100)) - runner.render() + } catch (error) { + // User projects can use older tscircuit versions without cancellation. + runner.cancelRendering?.(error) + throw error } runner.emit("renderComplete") diff --git a/lib/shared/thread-worker-pool.ts b/lib/shared/thread-worker-pool.ts index 6f633b83a..528e8e877 100644 --- a/lib/shared/thread-worker-pool.ts +++ b/lib/shared/thread-worker-pool.ts @@ -49,6 +49,7 @@ export class ThreadWorkerPool { private stopped = false private stopReason: Error | null = null private heartbeatIntervalId: NodeJS.Timeout | null = null + private terminationPromise: Promise | null = null constructor( options: ThreadWorkerPoolOptions< @@ -202,6 +203,8 @@ export class ThreadWorkerPool { } private replaceWorker(threadWorker: ThreadWorker): void { + if (this.stopped) return + this.clearWorkerTimeout(threadWorker) void threadWorker.worker.terminate().catch(() => undefined) @@ -229,7 +232,6 @@ export class ThreadWorkerPool { threadWorker.currentStatus = null threadWorker.busy = false action(job) - this.processQueue() } private attachWorkerHandlers( @@ -238,7 +240,7 @@ export class ThreadWorkerPool { const worker = threadWorker.worker worker.on("message", (message: TWorkerOutput) => { - if (threadWorker.worker !== worker) { + if (this.stopped || threadWorker.worker !== worker) { return } @@ -263,10 +265,11 @@ export class ThreadWorkerPool { job.resolve(this.options.getResult(message)) }) + this.processQueue() }) worker.on("error", (error) => { - if (threadWorker.worker !== worker) { + if (this.stopped || threadWorker.worker !== worker) { return } @@ -283,18 +286,16 @@ export class ThreadWorkerPool { }) worker.on("exit", (code) => { - if (threadWorker.worker !== worker) { + if (this.stopped || threadWorker.worker !== worker) { return } - if (code !== 0) { - this.finishJob(threadWorker, (job) => { - job.reject(new Error(`Worker exited with code ${code}`)) - }) + this.finishJob(threadWorker, (job) => { + job.reject(new Error(`Worker exited with code ${code}`)) + }) - this.replaceWorker(threadWorker) - this.processQueue() - } + this.replaceWorker(threadWorker) + this.processQueue() }) } @@ -330,6 +331,10 @@ export class ThreadWorkerPool { await this.initWorkers() + if (this.stopped) { + throw this.stopReason ?? new Error("Worker pool stopped") + } + return new Promise((resolve, reject) => { this.jobQueue.push({ job, resolve, reject }) this.processQueue() @@ -337,7 +342,10 @@ export class ThreadWorkerPool { } async stop(reason: Error): Promise { - if (this.stopped) return + if (this.stopped) { + await this.terminationPromise + return + } this.stopped = true this.stopHeartbeat() @@ -346,17 +354,25 @@ export class ThreadWorkerPool { queuedJob.reject(reason) } this.jobQueue = [] - } + const workers = this.workers + this.workers = [] + this.initialized = false - async terminate(): Promise { - this.stopHeartbeat() - await Promise.all( - this.workers.map((worker) => { + this.terminationPromise = Promise.all( + workers.map((worker) => { this.clearWorkerTimeout(worker) + worker.currentJob?.reject(reason) + worker.currentJob = null + worker.currentJobStartedAt = null + worker.currentStatus = null + worker.busy = false return worker.worker.terminate() }), - ) - this.workers = [] - this.initialized = false + ).then(() => undefined) + await this.terminationPromise + } + + async terminate(): Promise { + await this.stop(new Error("Worker pool terminated")) } } diff --git a/tests/fixtures/get-thread-worker-pool-test-fixture.ts b/tests/fixtures/get-thread-worker-pool-test-fixture.ts new file mode 100644 index 000000000..641664bd8 --- /dev/null +++ b/tests/fixtures/get-thread-worker-pool-test-fixture.ts @@ -0,0 +1,74 @@ +import fs from "node:fs" +import os from "node:os" +import path from "node:path" +import { ThreadWorkerPool } from "lib/shared/thread-worker-pool" + +type TestJob = { + id: string + outcome: "hang" | "fatal" | "success" | "error" | "exit" | "clean_exit" +} +type TestMessage = + | { type: "progress"; id: string } + | { type: "complete"; id: string; fatal: boolean } + +export const getThreadWorkerPoolTestFixture = (concurrency = 1) => { + const directory = fs.mkdtempSync(path.join(os.tmpdir(), "worker-pool-")) + const workerPath = path.join(directory, "worker.cjs") + fs.writeFileSync( + workerPath, + `const { parentPort } = require("node:worker_threads") +parentPort.on("message", (job) => { + parentPort.postMessage({ type: "progress", id: job.id }) + if (job.outcome === "error") throw new Error("Worker routing failed") + if (job.outcome === "exit") return process.exit(1) + if (job.outcome === "clean_exit") return process.exit(0) + if (job.outcome === "hang") { + setInterval(() => { + parentPort.postMessage({ type: "progress", id: job.id }) + }, 1000) + return + } + parentPort.postMessage({ + type: "complete", + id: job.id, + fatal: job.outcome === "fatal", + }) +})`, + ) + + let resolveStarted: () => void = () => {} + const started = new Promise((resolve) => { + resolveStarted = resolve + }) + const logs: string[] = [] + const cancellationError = new Error("Cancelled after fatal result") + const pool = new ThreadWorkerPool({ + concurrency, + workerEntrypointPath: workerPath, + createMessage: (job) => job, + isLogMessage: (message) => message.type === "progress", + getLogLines: (message) => [message.id], + isCompletionMessage: (message) => message.type === "complete", + getResult: (message) => message.id, + shouldStopOnMessage: (message) => + message.type === "complete" && message.fatal, + cancellationError, + jobTimeoutMs: 0, + heartbeatIntervalMs: 0, + onLog: (lines) => { + logs.push(...lines) + resolveStarted() + }, + }) + + return { + pool, + started, + logs, + cancellationError, + cleanup: async () => { + await pool.terminate() + fs.rmSync(directory, { recursive: true, force: true }) + }, + } +} diff --git a/tests/shared/autorouter-diagnostics-concurrent-isolated-phases.test.ts b/tests/shared/autorouter-diagnostics-concurrent-isolated-phases.test.ts new file mode 100644 index 000000000..65a8ab1a9 --- /dev/null +++ b/tests/shared/autorouter-diagnostics-concurrent-isolated-phases.test.ts @@ -0,0 +1,104 @@ +import { expect, test } from "bun:test" +import { EventEmitter } from "node:events" +import fs from "node:fs" +import os from "node:os" +import path from "node:path" +import { + AutorouterDiagnostics, + AutorouterPhaseTimeoutError, +} from "lib/shared/autorouter-diagnostics" + +test("completing one isolated sibling preserves the other sibling's progress and timeout", async () => { + const debugDir = fs.mkdtempSync(path.join(os.tmpdir(), "routing-scopes-")) + let parentDbReads = 0 + const root = Object.assign(new EventEmitter(), { + db: { + toArray: () => { + parentDbReads++ + return [] + }, + }, + }) + const diagnostics = new AutorouterDiagnostics({ + timeoutMs: 1, + dumpSrj: "all", + debugDir, + log: () => {}, + }) + diagnostics.attachToRootCircuit(root) + const shared = { subcircuit_id: "subcircuit_0", routingPhaseIndex: 0 } + const first = { ...shared, isolatedSubcircuitPath: ["outer", "first"] } + const second = { ...shared, isolatedSubcircuitPath: ["outer", "second"] } + + try { + root.emit("autorouting:start", { + ...first, + simpleRouteJson: { connections: [{ name: "first" }] }, + }) + root.emit("autorouting:start", { + ...second, + simpleRouteJson: { connections: [{ name: "second" }] }, + }) + root.emit("autorouting:progress", { ...first, progress: 0.25, steps: 12 }) + root.emit("autorouting:progress", { ...second, progress: 0.75, steps: 99 }) + root.emit("autorouting:end", { + ...second, + simpleRouteJson: { + traces: [{ type: "pcb_trace", pcb_trace_id: "pcb_trace_0", route: [] }], + }, + }) + root.emit("autorouting:progress", { ...second, progress: 1, steps: 100 }) + + await new Promise((resolve) => setTimeout(resolve, 5)) + let timeout: unknown + try { + diagnostics.checkTimeout() + } catch (error) { + timeout = error + } + expect(timeout).toBeInstanceOf(AutorouterPhaseTimeoutError) + const artifactPath = (timeout as AutorouterPhaseTimeoutError) + .debugArtifactPath! + const artifact = JSON.parse(fs.readFileSync(artifactPath, "utf8")) + expect(artifact.isolatedSubcircuitPath).toEqual( + first.isolatedSubcircuitPath, + ) + expect(artifact.phaseOrdinal).toBe(1) + expect(artifact.lastProgress).toMatchObject({ progress: 0.25, steps: 12 }) + expect(artifact.files.boardCircuitJson).toBeUndefined() + expect( + JSON.parse( + fs.readFileSync( + path.join(debugDir, artifact.files.previousOutputTraces), + "utf8", + ), + ), + ).toEqual([]) + + diagnostics.finalize([]) + const summary = JSON.parse( + fs.readFileSync(path.join(debugDir, "board.meta.json"), "utf8"), + ) + expect(summary.phases).toHaveLength(1) + expect(summary.phases[0]).toMatchObject({ + isolatedSubcircuitPath: second.isolatedSubcircuitPath, + phaseOrdinal: 1, + outputTraceCount: 1, + }) + expect( + fs.existsSync( + path.join( + debugDir, + "isolated", + "outer", + "second", + "subcircuit_0", + "phase-0.input.simple-route.json", + ), + ), + ).toBe(true) + expect(parentDbReads).toBe(0) + } finally { + fs.rmSync(debugDir, { recursive: true, force: true }) + } +}) diff --git a/tests/shared/autorouter-diagnostics-concurrent-progress.test.ts b/tests/shared/autorouter-diagnostics-concurrent-progress.test.ts new file mode 100644 index 000000000..23431670d --- /dev/null +++ b/tests/shared/autorouter-diagnostics-concurrent-progress.test.ts @@ -0,0 +1,36 @@ +import { expect, test } from "bun:test" +import { EventEmitter } from "node:events" +import { AutorouterDiagnostics } from "lib/shared/autorouter-diagnostics" + +test("long-running diagnostics report each active scope's own progress", async () => { + const root = new EventEmitter() + const logs: string[] = [] + const diagnostics = new AutorouterDiagnostics({ + longRunningLogThresholdMs: 1, + log: (message) => logs.push(message), + }) + diagnostics.attachToRootCircuit(root) + const first = { subcircuit_id: "board", isolatedSubcircuitPath: ["first"] } + const second = { subcircuit_id: "board", isolatedSubcircuitPath: ["second"] } + root.emit("autorouting:start", first) + root.emit("autorouting:start", second) + root.emit("autorouting:progress", { ...first, progress: 0.25 }) + root.emit("autorouting:progress", { ...second, progress: 0.75 }) + + await new Promise((resolve) => setTimeout(resolve, 5)) + diagnostics.checkTimeout() + + expect( + logs.some((line) => + line.includes("[isolated first] progress: progress=25%"), + ), + ).toBe(true) + expect( + logs.some((line) => + line.includes("[isolated second] progress: progress=75%"), + ), + ).toBe(true) + expect(logs.filter((line) => line.includes("has been running"))).toHaveLength( + 2, + ) +}) diff --git a/tests/shared/autorouter-diagnostics-isolated-geometry.test.ts b/tests/shared/autorouter-diagnostics-isolated-geometry.test.ts new file mode 100644 index 000000000..7820e0c5c --- /dev/null +++ b/tests/shared/autorouter-diagnostics-isolated-geometry.test.ts @@ -0,0 +1,70 @@ +import { expect, test } from "bun:test" +import { EventEmitter } from "node:events" +import fs from "node:fs" +import os from "node:os" +import path from "node:path" +import { AutorouterDiagnostics } from "lib/shared/autorouter-diagnostics" + +test("isolated phases do not consume parent placement snapshots or mix child traces into them", () => { + const debugDir = fs.mkdtempSync(path.join(os.tmpdir(), "routing-geometry-")) + let parentDbReads = 0 + const root = Object.assign(new EventEmitter(), { + db: { + toArray: () => { + parentDbReads++ + return [ + { + type: "pcb_board", + pcb_board_id: "board", + center: { x: 0, y: 0 }, + width: 10, + height: 10, + thickness: 1.4, + num_layers: 2, + material: "fr4", + }, + ] + }, + }, + }) + const diagnostics = new AutorouterDiagnostics({ + enabled: true, + dumpSrj: "all", + debugDir, + log: () => {}, + }) + diagnostics.attachToRootCircuit(root) + const isolated = { subcircuit_id: "board", isolatedSubcircuitPath: ["child"] } + + try { + root.emit("autorouting:start", isolated) + root.emit("autorouting:end", { + ...isolated, + simpleRouteJson: { + traces: [{ type: "pcb_trace", pcb_trace_id: "pcb_trace_0", route: [] }], + }, + }) + expect(parentDbReads).toBe(0) + expect(fs.existsSync(path.join(debugDir, "placement-unrouted.png"))).toBe( + false, + ) + expect(fs.existsSync(path.join(debugDir, "phase-0-routed.png"))).toBe(false) + + root.emit("autorouting:start", { subcircuit_id: "board" }) + expect(fs.existsSync(path.join(debugDir, "placement-unrouted.png"))).toBe( + true, + ) + root.emit("autorouting:end", { + subcircuit_id: "board", + simpleRouteJson: { traces: [] }, + }) + expect(fs.existsSync(path.join(debugDir, "phase-0-routed.png"))).toBe(true) + expect( + (diagnostics as any) + .getCircuitJsonWithCompletedPhaseTraces() + .filter((element: { type: string }) => element.type === "pcb_trace"), + ).toEqual([]) + } finally { + fs.rmSync(debugDir, { recursive: true, force: true }) + } +}) diff --git a/tests/shared/autorouter-diagnostics-isolated-phase-target.test.ts b/tests/shared/autorouter-diagnostics-isolated-phase-target.test.ts new file mode 100644 index 000000000..87c85d772 --- /dev/null +++ b/tests/shared/autorouter-diagnostics-isolated-phase-target.test.ts @@ -0,0 +1,83 @@ +import { expect, test } from "bun:test" +import { EventEmitter } from "node:events" +import fs from "node:fs" +import os from "node:os" +import path from "node:path" +import { + AutorouterDiagnostics, + AutorouterPhaseTimeoutError, +} from "lib/shared/autorouter-diagnostics" + +test("reaching the target phase in one scope does not disable a sibling's later phases", async () => { + const debugDir = fs.mkdtempSync(path.join(os.tmpdir(), "routing-target-")) + const root = new EventEmitter() + const logs: string[] = [] + const diagnostics = new AutorouterDiagnostics({ + phaseName: "target", + timeoutMs: 1, + debugDir, + log: (message) => logs.push(message), + }) + diagnostics.attachToRootCircuit(root) + const first = { + subcircuit_id: "board", + isolatedSubcircuitPath: ["first"], + phaseName: "target", + routingPhaseIndex: 0, + } + const second = { subcircuit_id: "board", isolatedSubcircuitPath: ["second"] } + + try { + root.emit("autorouting:start", first) + root.emit("autorouting:end", first) + root.emit("autorouting:start", { + ...second, + phaseName: "prepare", + routingPhaseIndex: 0, + }) + root.emit("autorouting:end", { + ...second, + phaseName: "prepare", + routingPhaseIndex: 0, + }) + root.emit("autorouting:start", { + ...second, + phaseName: "target", + routingPhaseIndex: 1, + }) + root.emit("autorouting:progress", { + ...second, + phaseName: "target", + routingPhaseIndex: 1, + progress: 0.25, + }) + await new Promise((resolve) => setTimeout(resolve, 5)) + + let timeout: unknown + try { + diagnostics.checkTimeout() + } catch (error) { + timeout = error + } + expect(timeout).toBeInstanceOf(AutorouterPhaseTimeoutError) + expect((timeout as Error).message).toContain("[isolated second]") + expect( + logs.some((line) => + line.includes("[isolated second] progress: progress=25%"), + ), + ).toBe(true) + const artifact = JSON.parse( + fs.readFileSync( + (timeout as AutorouterPhaseTimeoutError).debugArtifactPath!, + "utf8", + ), + ) + expect(artifact).toMatchObject({ + isolatedSubcircuitPath: ["second"], + routingPhaseIndex: 1, + phaseOrdinal: 2, + }) + } finally { + fs.rmSync(debugDir, { recursive: true, force: true }) + } +}) diff --git a/tests/shared/autorouter-diagnostics-stale-phase-events.test.ts b/tests/shared/autorouter-diagnostics-stale-phase-events.test.ts new file mode 100644 index 000000000..b69943cdc --- /dev/null +++ b/tests/shared/autorouter-diagnostics-stale-phase-events.test.ts @@ -0,0 +1,53 @@ +import { expect, test } from "bun:test" +import { EventEmitter } from "node:events" +import fs from "node:fs" +import os from "node:os" +import path from "node:path" +import { + AutorouterDiagnostics, + AutorouterPhaseTimeoutError, +} from "lib/shared/autorouter-diagnostics" + +test("late progress and completion from an earlier phase cannot alter its successor", async () => { + const debugDir = fs.mkdtempSync(path.join(os.tmpdir(), "routing-stale-")) + const root = new EventEmitter() + const diagnostics = new AutorouterDiagnostics({ + timeoutMs: 1, + debugDir, + log: () => {}, + }) + diagnostics.attachToRootCircuit(root) + const shared = { subcircuit_id: "board", isolatedSubcircuitPath: ["child"] } + const first = { ...shared, routingPhaseIndex: 0, phaseStageIndex: 0 } + const second = { ...shared, routingPhaseIndex: 1, phaseStageIndex: 1 } + + try { + root.emit("autorouting:start", first) + root.emit("autorouting:end", first) + root.emit("autorouting:start", second) + root.emit("autorouting:progress", { ...second, progress: 0.5 }) + root.emit("autorouting:progress", { ...first, progress: 1 }) + root.emit("autorouting:end", first) + root.emit("autorouting:error", { ...first, error: "late error" }) + + await new Promise((resolve) => setTimeout(resolve, 5)) + let timeout: unknown + try { + diagnostics.checkTimeout() + } catch (error) { + timeout = error + } + expect(timeout).toBeInstanceOf(AutorouterPhaseTimeoutError) + const artifact = JSON.parse( + fs.readFileSync( + (timeout as AutorouterPhaseTimeoutError).debugArtifactPath!, + "utf8", + ), + ) + expect(artifact.routingPhaseIndex).toBe(1) + expect(artifact.phaseOrdinal).toBe(2) + expect(artifact.lastProgress.progress).toBe(0.5) + } finally { + fs.rmSync(debugDir, { recursive: true, force: true }) + } +}) diff --git a/tests/shared/generate-circuit-json-timeout-cancellation.test.ts b/tests/shared/generate-circuit-json-timeout-cancellation.test.ts new file mode 100644 index 000000000..872812f8f --- /dev/null +++ b/tests/shared/generate-circuit-json-timeout-cancellation.test.ts @@ -0,0 +1,65 @@ +import { expect, test } from "bun:test" +import fs from "node:fs" +import os from "node:os" +import path from "node:path" +import { pathToFileURL } from "node:url" +import { AutorouterPhaseTimeoutError } from "lib/shared/autorouter-diagnostics" +import { generateCircuitJson } from "lib/shared/generate-circuit-json" + +test("circuit generation cancels the active renderer when routing times out", async () => { + const directory = fs.mkdtempSync(path.join(os.tmpdir(), "routing-timeout-")) + const moduleDirectory = path.join(directory, "node_modules", "tscircuit") + fs.mkdirSync(moduleDirectory, { recursive: true }) + fs.writeFileSync( + path.join(moduleDirectory, "package.json"), + JSON.stringify({ name: "tscircuit", type: "module", main: "index.js" }), + ) + const modulePath = path.join(moduleDirectory, "index.js") + fs.writeFileSync( + modulePath, + `import { EventEmitter } from "node:events" +export const state = { ticks: 0, interval: undefined, cancellationReason: undefined } +export class RootCircuit extends EventEmitter { + add() {} + render() { + if (state.interval !== undefined) return + state.interval = setInterval(() => state.ticks++, 1) + this.emit("autorouting:start", { subcircuit_id: "board" }) + } + isDoneRendering() { return false } + getRunningAsyncEffects() { return [{ effectName: "autorouting" }] } + getCircuitJson() { return [] } + cancelRendering(reason) { + state.cancellationReason = reason + clearInterval(state.interval) + state.interval = undefined + } +}`, + ) + const circuitPath = path.join(directory, "index.circuit.tsx") + fs.writeFileSync(circuitPath, "export default () => null") + const { state } = await import(pathToFileURL(modulePath).href) + const effects: string[] = [] + + try { + const error = await generateCircuitJson({ + filePath: circuitPath, + projectDir: directory, + onAsyncEffectStatus: (name) => effects.push(name), + autorouterDiagnostics: { + timeoutMs: 10, + debugDir: path.join(directory, "debug"), + log: () => {}, + }, + }).catch((error) => error) + + expect(error).toBeInstanceOf(AutorouterPhaseTimeoutError) + expect(state.cancellationReason).toBe(error) + expect(state.interval).toBeUndefined() + expect(state.ticks).toBeGreaterThan(0) + expect(effects).toEqual(["autorouting"]) + } finally { + clearInterval(state.interval) + fs.rmSync(directory, { recursive: true, force: true }) + } +}) diff --git a/tests/shared/thread-worker-pool-clean-exit-recovery.test.ts b/tests/shared/thread-worker-pool-clean-exit-recovery.test.ts new file mode 100644 index 000000000..75c38bcc5 --- /dev/null +++ b/tests/shared/thread-worker-pool-clean-exit-recovery.test.ts @@ -0,0 +1,21 @@ +import { expect, test } from "bun:test" +import { getThreadWorkerPoolTestFixture } from "tests/fixtures/get-thread-worker-pool-test-fixture" + +test("a clean worker exit without a result rejects the job and recovers the queue", async () => { + const { pool, cleanup } = getThreadWorkerPoolTestFixture() + const failed = pool.queueJob({ id: "failed", outcome: "clean_exit" }) + const next = pool.queueJob({ id: "after-exit", outcome: "success" }) + + const settled = Promise.allSettled([failed, next]) + + try { + const [failedResult, nextResult] = await settled + expect(failedResult.status).toBe("rejected") + expect(failedResult).toMatchObject({ + reason: { message: "Worker exited with code 0" }, + }) + expect(nextResult).toEqual({ status: "fulfilled", value: "after-exit" }) + } finally { + await cleanup() + } +}) diff --git a/tests/shared/thread-worker-pool-error-recovery.test.ts b/tests/shared/thread-worker-pool-error-recovery.test.ts new file mode 100644 index 000000000..2e8cbaf58 --- /dev/null +++ b/tests/shared/thread-worker-pool-error-recovery.test.ts @@ -0,0 +1,23 @@ +import { expect, test } from "bun:test" +import { getThreadWorkerPoolTestFixture } from "tests/fixtures/get-thread-worker-pool-test-fixture" + +test("worker errors replace the worker before dispatching the next queued job", async () => { + const { pool, cleanup } = getThreadWorkerPoolTestFixture() + const failed = pool.queueJob({ id: "failed", outcome: "error" }) + const next = pool.queueJob({ id: "after-error", outcome: "success" }) + const last = pool.queueJob({ id: "after-success", outcome: "success" }) + + const settled = Promise.allSettled([failed, next, last]) + + try { + const [failedResult, nextResult, lastResult] = await settled + expect(failedResult.status).toBe("rejected") + expect(failedResult).toMatchObject({ + reason: { message: "Worker routing failed" }, + }) + expect(nextResult).toEqual({ status: "fulfilled", value: "after-error" }) + expect(lastResult).toEqual({ status: "fulfilled", value: "after-success" }) + } finally { + await cleanup() + } +}) diff --git a/tests/shared/thread-worker-pool-exit-recovery.test.ts b/tests/shared/thread-worker-pool-exit-recovery.test.ts new file mode 100644 index 000000000..6ad7b1e0a --- /dev/null +++ b/tests/shared/thread-worker-pool-exit-recovery.test.ts @@ -0,0 +1,21 @@ +import { expect, test } from "bun:test" +import { getThreadWorkerPoolTestFixture } from "tests/fixtures/get-thread-worker-pool-test-fixture" + +test("worker exits replace the worker before dispatching the next queued job", async () => { + const { pool, cleanup } = getThreadWorkerPoolTestFixture() + const failed = pool.queueJob({ id: "failed", outcome: "exit" }) + const next = pool.queueJob({ id: "after-exit", outcome: "success" }) + + const settled = Promise.allSettled([failed, next]) + + try { + const [failedResult, nextResult] = await settled + expect(failedResult.status).toBe("rejected") + expect(failedResult).toMatchObject({ + reason: { message: "Worker exited with code 1" }, + }) + expect(nextResult).toEqual({ status: "fulfilled", value: "after-exit" }) + } finally { + await cleanup() + } +}) diff --git a/tests/shared/thread-worker-pool-fatal-cancellation.test.ts b/tests/shared/thread-worker-pool-fatal-cancellation.test.ts new file mode 100644 index 000000000..995688ee1 --- /dev/null +++ b/tests/shared/thread-worker-pool-fatal-cancellation.test.ts @@ -0,0 +1,26 @@ +import { expect, test } from "bun:test" +import { getThreadWorkerPoolTestFixture } from "tests/fixtures/get-thread-worker-pool-test-fixture" + +test("fatal results cancel other running jobs without waiting for their timeout", async () => { + const { pool, started, cancellationError, cleanup } = + getThreadWorkerPoolTestFixture(2) + const active = pool.queueJob({ id: "active", outcome: "hang" }) + const activeSettled = Promise.allSettled([active]) + + try { + await started + const fatal = pool.queueJob({ id: "fatal", outcome: "fatal" }) + const queued = pool.queueJob({ id: "queued", outcome: "success" }) + const queuedSettled = Promise.allSettled([queued]) + + expect(await fatal).toBe("fatal") + expect(await activeSettled).toEqual([ + { status: "rejected", reason: cancellationError }, + ]) + expect(await queuedSettled).toEqual([ + { status: "rejected", reason: cancellationError }, + ]) + } finally { + await cleanup() + } +}) diff --git a/tests/shared/thread-worker-pool-stop-during-initialization.test.ts b/tests/shared/thread-worker-pool-stop-during-initialization.test.ts new file mode 100644 index 000000000..51a103c9e --- /dev/null +++ b/tests/shared/thread-worker-pool-stop-during-initialization.test.ts @@ -0,0 +1,17 @@ +import { expect, test } from "bun:test" +import { getThreadWorkerPoolTestFixture } from "tests/fixtures/get-thread-worker-pool-test-fixture" + +test("stop rejects jobs that are waiting for worker initialization", async () => { + const { pool, logs, cleanup } = getThreadWorkerPoolTestFixture() + const reason = new Error("Stopped before dispatch") + const queued = pool.queueJob({ id: "pending", outcome: "success" }) + const settled = Promise.allSettled([queued]) + + try { + await pool.stop(reason) + expect(await settled).toEqual([{ status: "rejected", reason }]) + expect(logs).toEqual([]) + } finally { + await cleanup() + } +}) diff --git a/tests/shared/thread-worker-pool-stop.test.ts b/tests/shared/thread-worker-pool-stop.test.ts new file mode 100644 index 000000000..a7c7dd1f9 --- /dev/null +++ b/tests/shared/thread-worker-pool-stop.test.ts @@ -0,0 +1,26 @@ +import { expect, test } from "bun:test" +import { getThreadWorkerPoolTestFixture } from "tests/fixtures/get-thread-worker-pool-test-fixture" + +test("stop cancels active and queued jobs and terminates a busy worker", async () => { + const { pool, started, logs, cleanup } = getThreadWorkerPoolTestFixture() + const reason = new Error("Routing cancelled") + const active = pool.queueJob({ id: "active", outcome: "hang" }) + const queued = pool.queueJob({ id: "queued", outcome: "success" }) + const settled = Promise.allSettled([active, queued]) + + try { + await started + await Promise.all([pool.stop(reason), pool.stop(reason)]) + + expect(await settled).toEqual([ + { status: "rejected", reason }, + { status: "rejected", reason }, + ]) + expect(logs).toEqual(["active"]) + await expect( + pool.queueJob({ id: "after-stop", outcome: "success" }), + ).rejects.toBe(reason) + } finally { + await cleanup() + } +})