🐛 Harden the SVG worker pool and lazy-load the logger

Follow up on the review of the SVG sanitization commit.

The logger is now lazy: createLogger only builds its child on the first
log call, so importing a module inside an SVG worker no longer spawns
the main logger's transport threads (which the previous comment
wrongly claimed).

The pool stops respawning a slot after five consecutive spawn failures
and degrades to 503 when no worker is left, instead of spinning in a
spawn->fail->respawn loop. A malformed worker message is validated and
treated as a worker failure, and runInSvgPool rejects when the pool is
disabled.

Tests: the real worker entry point is exercised end to end (via tsx),
and the pool covers the spawn cap, malformed messages and the disabled
pool. The remote root check is case-insensitive, and the SVG size hint
uses the project's str/ffmt.

AI-assisted-by: deepseek-v4.1-flash

.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

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 "<svg")
+        (when-not (re-find #"(?i)^<svg" cleaned)
           (ex/raise :type :internal
                     :code :invalid-sanitized-svg
                     :hint "media-processor returned a non-SVG response"))

backend/src/app/rpc/commands/media.clj

@@ -25,6 +25,7 @@
    [app.storage :as sto]
    [app.storage.tmp :as tmp]
    [app.util.services :as sv]
+   [cuerdas.core :as str]
    [datoteka.io :as io])
   (:import
    java.io.OutputStream))
@@ -137,7 +138,9 @@
                   (when (> 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)

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<string | symbol, unknown>)[prop];
+      return typeof value === "function" ? value.bind(child) : value;
+    },
+  });
 }

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");
     }

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<string> {
   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<string>((resolve, reject) => {
     current.queue.push({ svg, resolve, reject, timer: null });
     dispatch();
@@ -106,11 +120,10 @@ export async function shutdownSvgPool(): Promise<void> {
     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" });
+}

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();
+  });
+});

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("<svg/>");
+    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("<svg/>");
+    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("<svg/>"));
+    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("<svg/>"));
+    expect(err.statusCode).toBe(503);
+    expect(err.errorBody.code).toBe("svg-pool-disabled");
+  });
 });
 
 describe("svg pool: timeout", () => {

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<WorkerReply> {
+  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(
+      `<svg xmlns="http://www.w3.org/2000/svg"><script>alert("x")</script><rect/></svg>`
+    );
+    expect(reply.ok).toBe(true);
+    expect(reply.clean).toMatch(/^<svg[\s/>]/i);
+    expect(reply.clean).not.toMatch(/<script/i);
+  });
+
+  it("reports invalid input as a validation error", async () => {
+    const reply = await runRealWorker("this is not an svg");
+    expect(reply.ok).toBe(false);
+    expect(reply.statusCode).toBe(400);
+    expect(reply.body?.code).toBe("invalid-svg-file");
+  });
+});