diff --git a/.serena/memories/media-processor/core.md b/.serena/memories/media-processor/core.md index e9b85fc7af..d9a8ad0fad 100644 --- a/.serena/memories/media-processor/core.md +++ b/.serena/memories/media-processor/core.md @@ -97,6 +97,12 @@ media-processor/ pool maps that to a 503 and respawns it. A stuck job is terminated by a timeout and its worker respawned. Worst-case memory is roughly workers × maxOldGenerationSizeMb. +- A worker that fails before it ever answers is respawned at most + `MAX_SPAWN_FAILURES` (5) consecutive times; after that the slot is dropped and + a pool left with no workers is degraded (`svg-pool-degraded`), so a broken + worker cannot spin in a spawn→fail→respawn loop for the life of the process. + The streak resets as soon as a worker answers. A malformed worker message is + treated as a worker failure (`svg-worker-failed`), never trusted. - DOMPurify is given `USE_PROFILES: {svg: true, svgFilters: true}` and `NAMESPACE: "http://www.w3.org/2000/svg"`, so it parses the document as XML/SVG the way a browser parses a standalone `.svg`. Its default allowlist fails closed @@ -119,7 +125,9 @@ media-processor/ the same cap (`:media-svg-max-file-size`, `mem:backend/media-sanitization`) so both modes behave the same; keep the two knobs aligned. - Errors: `400 invalid-svg-file` (not a well-formed SVG), `413 svg-too-large`, - `503 svg-sanitization-failed` / `svg-timeout` / `svg-worker-failed`. + and 503 `svg-sanitization-failed` (internal failure), `svg-timeout`, + `svg-worker-failed` / `svg-worker-exited` (broken worker), `svg-pool-degraded` + (no worker could start) and `svg-pool-stopped` (shutdown). - Tests: `svg.test.ts` (service corpus, route, and the exact multipart the JVM backend builds) and `svg-pool.test.ts` (queue, timeout, failure/respawn with a fake worker). The contract test pins the wire format but does not run the JVM diff --git a/backend/src/app/media/remote.clj b/backend/src/app/media/remote.clj index 66d4431196..e09da2224d 100644 --- a/backend/src/app/media/remote.clj +++ b/backend/src/app/media/remote.clj @@ -230,7 +230,7 @@ ;; misconfigured proxy or a future endpoint change must not let a non-SVG ;; body be stored as `image/svg+xml`. (let [cleaned (str/trim (slurp body :encoding "UTF-8"))] - (when-not (str/starts-with? cleaned " size max-size) (ex/raise :type :restriction :code :svg-too-large - :hint (str "the svg size " size " is greater than the maximum " max-size))) + :hint (str/ffmt "the svg size % is greater than the maximum %" + size + max-size))) (let [sanitized (media/sanitize-svg cfg content) temp-path (tmp/tempfile :prefix "penpot-svg-" :suffix ".svg" :min-age "5m")] (spit (str temp-path) sanitized) diff --git a/media-processor/src/logger.ts b/media-processor/src/logger.ts index aede1219d2..f77f3d091e 100644 --- a/media-processor/src/logger.ts +++ b/media-processor/src/logger.ts @@ -130,6 +130,18 @@ export function logActiveTransports(log: pino.Logger): void { } } -export function createLogger(name: string) { - return logger.child({ name }); +// Returns a lazy proxy: `logger.child({ name })` (and therefore the pino +// instance with its transport threads) is only created on the first log call. +// This keeps importing a module cheap — notably inside a worker thread, where +// an eager `createLogger` would spawn the transport workers of the main +// process logger in every SVG worker. +export function createLogger(name: string): pino.Logger { + let child: pino.Logger | null = null; + return new Proxy({} as pino.Logger, { + get(_, prop) { + child ??= logger.child({ name }); + const value = (child as unknown as Record)[prop]; + return typeof value === "function" ? value.bind(child) : value; + }, + }); } diff --git a/media-processor/src/services/svg.ts b/media-processor/src/services/svg.ts index fd9f7c386d..5506044701 100644 --- a/media-processor/src/services/svg.ts +++ b/media-processor/src/services/svg.ts @@ -84,7 +84,7 @@ export function sanitizeSvgSync(svg: string): string { // is not the user's file being invalid: report it as a service failure and // keep the technical detail out of the hint. Inside a worker this is not // logged: the pool logs it on the main thread when the result comes back, - // so a worker never initializes the (transport-spawning) logger. + // so the worker never touches the logger. if (isMainThread) { logger.error({ err }, "unexpected svg sanitization failure"); } diff --git a/media-processor/src/svg-pool.ts b/media-processor/src/svg-pool.ts index dd383e66ea..0e44d4090e 100644 --- a/media-processor/src/svg-pool.ts +++ b/media-processor/src/svg-pool.ts @@ -5,6 +5,11 @@ import type { AppError } from "./types.js"; const logger = createLogger("svg-pool"); +// A worker that fails before it ever answers (a missing bundle, a broken loader) +// must not respawn forever. After this many consecutive spawn failures the slot +// is dropped; with no workers left the pool is degraded and answers 503. +const MAX_SPAWN_FAILURES = 5; + /** * The slice of `worker_threads.Worker` the pool uses. Keeping it narrow lets * tests inject a fake worker and exercise the queue, the timeout and the @@ -42,11 +47,13 @@ interface PoolState { workers: PooledWorker[]; queue: Job[]; stopped: boolean; + degraded: boolean; } type SvgWorkerResult = { ok: true; clean: string } | { ok: false; statusCode: number; body: AppError }; let state: PoolState | null = null; +let spawnFailures = 0; let createWorker: () => SvgWorker = defaultWorkerFactory; function workerUrl(): URL { @@ -77,7 +84,8 @@ export function configureSvgPool(options: SvgPoolOptions): void { if (state !== null) { throw new Error("svg pool is already configured"); } - state = { options, workers: [], queue: [], stopped: false }; + spawnFailures = 0; + state = { options, workers: [], queue: [], stopped: false, degraded: false }; for (let i = 0; i < options.workers; i++) { state.workers.push(spawnWorker()); } @@ -93,6 +101,12 @@ export function runInSvgPool(svg: string): Promise { if (current === null || current.stopped) { return Promise.reject(stoppedError()); } + if (current.options.workers <= 0) { + return Promise.reject(disabledError()); + } + if (current.degraded) { + return Promise.reject(degradedError()); + } return new Promise((resolve, reject) => { current.queue.push({ svg, resolve, reject, timer: null }); dispatch(); @@ -106,11 +120,10 @@ export async function shutdownSvgPool(): Promise { return; } current.stopped = true; + spawnFailures = 0; state = null; - for (const job of current.queue.splice(0)) { - job.reject(stoppedError()); - } + rejectQueue(current, stoppedError()); const workers = current.workers; current.workers = []; @@ -139,7 +152,7 @@ function spawnWorker(): PooledWorker { function dispatch(): void { const current = state; - if (current === null || current.stopped) { + if (current === null || current.stopped || current.degraded) { return; } while (current.queue.length > 0) { @@ -158,6 +171,15 @@ function dispatch(): void { } function onMessage(pooled: PooledWorker, value: unknown): void { + if (!isWorkerResult(value)) { + logger.error("svg worker sent a malformed message"); + failWorker(pooled, new ProcessingError(503, { type: "internal", code: "svg-worker-failed" }), true); + return; + } + + // A well-formed answer proves the worker loaded, so the spawn streak is over. + spawnFailures = 0; + const job = pooled.job; if (job === null) { return; @@ -165,21 +187,20 @@ function onMessage(pooled: PooledWorker, value: unknown): void { clearJobTimer(job); pooled.job = null; - const result = value as SvgWorkerResult; - if (result.ok) { - job.resolve(result.clean); + if (value.ok) { + job.resolve(value.clean); } else { - if (result.body.code === "svg-sanitization-failed") { + if (value.body.code === "svg-sanitization-failed") { logger.error("svg worker reported an unexpected sanitization failure"); } - job.reject(new ProcessingError(result.statusCode, result.body)); + job.reject(new ProcessingError(value.statusCode, value.body)); } dispatch(); } function onWorkerError(pooled: PooledWorker, err: Error): void { logger.error({ err }, "svg worker error"); - failWorker(pooled, new ProcessingError(503, { type: "internal", code: "svg-worker-failed" })); + failWorker(pooled, new ProcessingError(503, { type: "internal", code: "svg-worker-failed" }), true); } function onWorkerExit(pooled: PooledWorker, code: number): void { @@ -187,11 +208,16 @@ function onWorkerExit(pooled: PooledWorker, code: number): void { return; } logger.error({ code }, "svg worker exited unexpectedly"); - failWorker(pooled, new ProcessingError(503, { type: "internal", code: "svg-worker-exited" })); + failWorker(pooled, new ProcessingError(503, { type: "internal", code: "svg-worker-exited" }), true); } -/** Reject the worker's in-flight job (if any) and replace the worker. */ -function failWorker(pooled: PooledWorker, err: ProcessingError): void { +/** + * Reject the worker's in-flight job (if any) and replace the worker. When the + * failure is a spawn failure and the streak passes `MAX_SPAWN_FAILURES`, the + * slot is dropped instead of respawned; a pool left with no workers is degraded + * and answers 503 for every request. + */ +function failWorker(pooled: PooledWorker, err: ProcessingError, spawnFailure = false): void { if (pooled.terminating) { return; } @@ -207,13 +233,52 @@ function failWorker(pooled: PooledWorker, err: ProcessingError): void { void pooled.worker.terminate().catch(() => 0); const current = state; - if (current !== null && !current.stopped) { - const index = current.workers.indexOf(pooled); - if (index !== -1) { - current.workers[index] = spawnWorker(); - } - dispatch(); + if (current === null || current.stopped) { + return; } + + if (spawnFailure) { + spawnFailures++; + } + + const index = current.workers.indexOf(pooled); + if (spawnFailure && spawnFailures > MAX_SPAWN_FAILURES) { + if (index !== -1) { + current.workers.splice(index, 1); + } + if (current.workers.length === 0) { + current.degraded = true; + logger.error("svg pool degraded: no worker could be started"); + rejectQueue(current, degradedError()); + } + return; + } + + if (index !== -1) { + current.workers[index] = spawnWorker(); + } + dispatch(); +} + +function rejectQueue(current: PoolState, err: ProcessingError): void { + for (const job of current.queue.splice(0)) { + clearJobTimer(job); + job.reject(err); + } +} + +function isWorkerResult(value: unknown): value is SvgWorkerResult { + if (typeof value !== "object" || value === null) { + return false; + } + const result = value as { ok?: unknown; clean?: unknown; statusCode?: unknown; body?: unknown }; + if (result.ok === true) { + return typeof result.clean === "string"; + } + if (result.ok === false) { + return typeof result.statusCode === "number" && typeof result.body === "object" && result.body !== null; + } + return false; } function clearJobTimer(job: Job): void { @@ -226,3 +291,11 @@ function clearJobTimer(job: Job): void { function stoppedError(): ProcessingError { return new ProcessingError(503, { type: "internal", code: "svg-pool-stopped" }); } + +function degradedError(): ProcessingError { + return new ProcessingError(503, { type: "internal", code: "svg-pool-degraded" }); +} + +function disabledError(): ProcessingError { + return new ProcessingError(503, { type: "internal", code: "svg-pool-disabled" }); +} diff --git a/media-processor/test/logger-lazy.test.ts b/media-processor/test/logger-lazy.test.ts new file mode 100644 index 0000000000..2ec24304ec --- /dev/null +++ b/media-processor/test/logger-lazy.test.ts @@ -0,0 +1,29 @@ +import { describe, it, expect, afterEach, vi } from "vitest"; + +describe("createLogger", () => { + const original = process.env.PENPOT_MEDIA_PROCESSOR_LOG_LEVEL; + + afterEach(() => { + if (original === undefined) { + delete process.env.PENPOT_MEDIA_PROCESSOR_LOG_LEVEL; + } else { + process.env.PENPOT_MEDIA_PROCESSOR_LOG_LEVEL = original; + } + vi.resetModules(); + }); + + it("defers logger initialization until the first log call", async () => { + vi.resetModules(); + // An invalid level makes loadConfig throw, which is how we observe whether + // the logger was initialized: it must not be at createLogger time, and must + // be at the first log call. + process.env.PENPOT_MEDIA_PROCESSOR_LOG_LEVEL = "definitely-not-a-level"; + + const { createLogger } = await import("../src/logger.js"); + + const child = createLogger("lazy"); + expect(child).toBeTruthy(); + + expect(() => child.info("boom")).toThrow(); + }); +}); diff --git a/media-processor/test/svg-pool.test.ts b/media-processor/test/svg-pool.test.ts index 6afc52f102..bb4f533978 100644 --- a/media-processor/test/svg-pool.test.ts +++ b/media-processor/test/svg-pool.test.ts @@ -129,6 +129,67 @@ describe("svg pool: worker failure", () => { expect(err.errorBody.code).toBe("svg-worker-exited"); expect(created).toHaveLength(2); }); + + it("rejects a malformed worker message instead of crashing", async () => { + installFakeFactory(); + configureSvgPool({ workers: 1, maxOldGenerationSizeMb: 512, timeout: 1000 }); + + const job = runInSvgPool(""); + created[0].reply(null); + + const err = await rejection(job); + expect(err.statusCode).toBe(503); + expect(err.errorBody.code).toBe("svg-worker-failed"); + expect(created).toHaveLength(2); + }); + + it("rejects a non-object worker message instead of crashing", async () => { + installFakeFactory(); + configureSvgPool({ workers: 1, maxOldGenerationSizeMb: 512, timeout: 1000 }); + + const job = runInSvgPool(""); + created[0].reply(42); + + const err = await rejection(job); + expect(err.statusCode).toBe(503); + expect(err.errorBody.code).toBe("svg-worker-failed"); + }); +}); + +describe("svg pool: spawn failure cap", () => { + it("stops respawning after repeated spawn failures and degrades", async () => { + created = []; + setSvgWorkerFactory(() => { + const worker = new FakeWorker(); + created.push(worker); + // Fail asynchronously, like a worker that cannot load its entry point. + queueMicrotask(() => worker.emit("error", new Error("spawn failed"))); + return worker as unknown as SvgWorker; + }); + configureSvgPool({ workers: 1, maxOldGenerationSizeMb: 512, timeout: 1000 }); + + // Let the spawn -> error -> respawn cascade settle. + for (let i = 0; i < 30; i++) { + await new Promise((resolve) => setTimeout(resolve, 0)); + } + + expect(created.length).toBeLessThanOrEqual(6); + + const err = await rejection(runInSvgPool("")); + expect(err.statusCode).toBe(503); + expect(err.errorBody.code).toBe("svg-pool-degraded"); + }); +}); + +describe("svg pool: disabled", () => { + it("rejects queued work when the pool has no workers", async () => { + installFakeFactory(); + configureSvgPool({ workers: 0, maxOldGenerationSizeMb: 512, timeout: 1000 }); + + const err = await rejection(runInSvgPool("")); + expect(err.statusCode).toBe(503); + expect(err.errorBody.code).toBe("svg-pool-disabled"); + }); }); describe("svg pool: timeout", () => { diff --git a/media-processor/test/svg-worker-real.test.ts b/media-processor/test/svg-worker-real.test.ts new file mode 100644 index 0000000000..19162abfe3 --- /dev/null +++ b/media-processor/test/svg-worker-real.test.ts @@ -0,0 +1,46 @@ +import { describe, it, expect } from "vitest"; +import { Worker } from "node:worker_threads"; + +// Exercises the *real* worker file (not the injectable fake used by +// `svg-pool.test.ts`): the entry point, its imports and the message protocol +// between the pool and the worker. It loads the `.ts` source with the dev +// loader (`tsx`), which is the same worker the service runs under `tsx` and +// whose compiled twin the bundle ships as `dist/svg-worker.js`. +interface WorkerReply { + ok: boolean; + clean?: string; + statusCode?: number; + body?: { code?: string }; +} + +function runRealWorker(svg: string): Promise { + return new Promise((resolve, reject) => { + const worker = new Worker(new URL("../src/svg-worker.ts", import.meta.url), { + execArgv: ["--import", "tsx"], + }); + worker.once("message", (message) => { + void worker.terminate(); + resolve(message as WorkerReply); + }); + worker.once("error", reject); + worker.postMessage(svg); + }); +} + +describe("svg worker (real)", () => { + it("sanitizes a malicious svg", async () => { + const reply = await runRealWorker( + `` + ); + expect(reply.ok).toBe(true); + expect(reply.clean).toMatch(/^]/i); + expect(reply.clean).not.toMatch(/