fix(ai): explain answers cut off by the token limit, and log AI and import runs (#16)

* fix(ai): leave room for a full answer and explain a cut-off one

max_tokens 300 cut answers off once the reason filled its 300-character
limit, and the run showed JSON.parse's position instead of the cause.
Raise it to 1024 and turn a parse failure into a readable error, naming
the token limit when the provider reports finish_reason length.

* feat(backend): add a shared logger with levels and greppable fields

One line per event with a level, a scope and key=value fields, or one
JSON object per line with LOG_FORMAT=json. LOG_LEVEL drops lines below
it. Errors log their message, status and code, plus the stack at error
level, and bearer tokens are redacted. Nothing outside it changes yet.

* feat(ai,import): log categorization and import runs through the logger

A bulk AI run kept only its last error in memory, so which models failed
and why was lost. Each provider answer it can't use now logs the model,
finish_reason, completion and reasoning tokens and the end of the answer;
each model's outcome and the run's start and totals are logged too.

Collection, Thingiverse, Printables, profile and zip imports dropped a
failed model without a trace; they now log it with its reason, plus the
job's start and totals. The links runner's console lines move to the
logger.

* fix(ai): read an answer wrapped in markdown or prose

Xiaomi MiMo ignores response_format and sent the object in bold,
`**{...}**`, which failed as not valid JSON although the answer was
complete. When the whole text doesn't parse, try the outermost braces.

backend/.env.example

@@ -8,6 +8,10 @@ CORS_ORIGINS=
 AUTH_SECRET=replace-with-random-secret
 AUTH_TOKEN_TTL=43200
 FLARESOLVERR_URL=
+# Backend logs: debug, info, warn or error (default info). LOG_FORMAT=json writes one JSON object
+# per line for a log collector; anything else writes plain text.
+LOG_LEVEL=info
+LOG_FORMAT=text
 # Optional: leave SMTP_HOST blank to skip email verification on registration entirely (new
 # accounts are verified and signed in immediately). Once set, these only seed the admin-editable
 # Connections > SMTP settings on first boot -- later changes are saved via that page, not here.

backend/src/logger.ts

@@ -0,0 +1,128 @@
+/**
+ * Process logs: one line per event, with a level, a scope saying which part of the backend wrote it,
+ * and fields an admin can grep (`print=… outcome=…`). Not the audit log in services/auditLog.ts,
+ * which stores what users did in the database.
+ *
+ *   const log = createLogger("import");
+ *   log.info("job done", { job: jobId, imported: 3 });
+ *   // 2026-10-13T16:36:56.808Z INFO  [import] job done job=cm… imported=3
+ *
+ * LOG_LEVEL (debug | info | warn | error, default info) drops lines below it. LOG_FORMAT=json writes
+ * one JSON object per line instead, for a collector that parses them.
+ */
+
+export type LogLevel = "debug" | "info" | "warn" | "error";
+export type LogFields = Record<string, unknown>;
+
+const LEVELS: Record<LogLevel, number> = { debug: 10, info: 20, warn: 30, error: 40 };
+
+// Read on every line rather than once, so a test or an operator changing the env sees it right away.
+function minimumLevel(): number {
+  const name = process.env.LOG_LEVEL?.trim().toLowerCase();
+  return name && name in LEVELS ? LEVELS[name as LogLevel] : LEVELS.info;
+}
+
+function jsonFormat(): boolean {
+  return process.env.LOG_FORMAT?.trim().toLowerCase() === "json";
+}
+
+/** A token pasted into a URL or carried in an error message shouldn't reach the logs. */
+function redact(text: string): string {
+  return text.replace(/Bearer\s+[^\s"',]+/gi, "Bearer [redacted]");
+}
+
+function errorFields(error: Error, withStack: boolean): LogFields {
+  const out: LogFields = { message: error.message };
+  // Subclasses that don't set `name` (HttpError) still say which class they are.
+  const name = error.name && error.name !== "Error" ? error.name : error.constructor?.name;
+  if (name && name !== "Error") out.name = name;
+  const extra = error as Error & { status?: unknown; code?: unknown };
+  if (extra.status !== undefined) out.status = extra.status;
+  if (extra.code !== undefined) out.code = extra.code;
+  if (withStack && error.stack) out.stack = error.stack;
+  return out;
+}
+
+function textValue(value: unknown): string {
+  if (value instanceof Error) return textValue(value.message);
+  if (value === null || value === undefined) return String(value);
+  if (typeof value === "string") return value === "" || /[\s"=]/.test(value) ? JSON.stringify(value) : value;
+  if (typeof value === "number" || typeof value === "boolean" || typeof value === "bigint") return String(value);
+  try {
+    return JSON.stringify(value) ?? String(value);
+  } catch {
+    // A circular object still says what it was instead of losing the whole line.
+    return "[unserializable]";
+  }
+}
+
+function jsonSafe(value: unknown, withStack: boolean): unknown {
+  if (value instanceof Error) return errorFields(value, withStack);
+  if (typeof value === "bigint") return value.toString();
+  return value;
+}
+
+export class Logger {
+  constructor(
+    readonly scope: string,
+    private readonly bound: LogFields = {},
+  ) {}
+
+  /** A logger that adds the same fields to every line, such as the job it works on. */
+  child(fields: LogFields): Logger {
+    return new Logger(this.scope, { ...this.bound, ...fields });
+  }
+
+  debug(message: string, fields?: LogFields): void {
+    this.write("debug", message, fields);
+  }
+
+  info(message: string, fields?: LogFields): void {
+    this.write("info", message, fields);
+  }
+
+  warn(message: string, fields?: LogFields): void {
+    this.write("warn", message, fields);
+  }
+
+  error(message: string, fields?: LogFields): void {
+    this.write("error", message, fields);
+  }
+
+  private write(level: LogLevel, message: string, fields?: LogFields): void {
+    if (LEVELS[level] < minimumLevel()) return;
+    const all = { ...this.bound, ...fields };
+    // An unexpected failure needs its stack to be found; a warning is usually an expected one.
+    const withStack = level === "error";
+    const time = new Date().toISOString();
+    let line: string;
+    if (jsonFormat()) {
+      const record: LogFields = { time, level, scope: this.scope, message };
+      for (const [key, value] of Object.entries(all)) {
+        if (value !== undefined && !(key in record)) record[key] = jsonSafe(value, withStack);
+      }
+      try {
+        line = JSON.stringify(record);
+      } catch {
+        line = JSON.stringify({ time, level, scope: this.scope, message, fields: "[unserializable]" });
+      }
+    } else {
+      const parts = [time, level.toUpperCase().padEnd(5), `[${this.scope}]`, message];
+      let stack: string | undefined;
+      for (const [key, value] of Object.entries(all)) {
+        if (value === undefined) continue;
+        parts.push(`${key}=${textValue(value)}`);
+        if (withStack && value instanceof Error && value.stack && !stack) stack = value.stack;
+      }
+      line = parts.join(" ") + (stack ? `\n${stack}` : "");
+    }
+    line = redact(line);
+    if (level === "error") console.error(line);
+    else if (level === "warn") console.warn(line);
+    else console.log(line);
+  }
+}
+
+export function createLogger(scope: string, fields?: LogFields): Logger {
+  return new Logger(scope, fields);
+}

backend/src/services/aiCategorizationService.ts

@@ -4,6 +4,7 @@ import sharp from "sharp";
 import { z } from "zod";
 import { prisma } from "../db";
 import { HttpError } from "../utils/fileUtils";
+import { createLogger } from "../logger";
 import { previewImagePath } from "./previewImageService";
 import { createLog } from "./auditLog";
 import { setPrintCategory } from "./printCategoryService";
@@ -18,6 +19,8 @@ const suggestionSchema = z.object({
 });
 
 type Suggestion = z.infer<typeof suggestionSchema>;
+
+const log = createLogger("ai-categorize");
 type Candidate = { id: string; path: string };
 type ProviderResult = { categoryId: string | null; confidence: number; reason: string };
 export type CategorizationOutcome = "applied" | "suggested" | "no_match" | "unchanged";
@@ -119,6 +122,26 @@ function readableNetworkError(error: unknown, settings: AiCategorizationSettings
   return error;
 }
 
+/**
+ * Providers that ignore response_format (Xiaomi MiMo) wrap the object in prose or markdown, e.g.
+ * `**{...}**`; the outermost braces are tried when the whole text doesn't parse. undefined when
+ * neither does.
+ */
+function parseAnswerJson(text: string): unknown {
+  try {
+    return JSON.parse(text);
+  } catch {
+    const start = text.indexOf("{");
+    const end = text.lastIndexOf("}");
+    if (start === -1 || end <= start) return undefined;
+    try {
+      return JSON.parse(text.slice(start, end + 1));
+    } catch {
+      return undefined;
+    }
+  }
+}
+
 async function requestProvider(
   print: Print,
   candidates: Candidate[],
@@ -164,8 +187,10 @@ async function requestProvider(
     required: ["reason", "category", "confidence"],
   };
 
+  const requestLog = log.child({ print: print.id, model: settings.model });
   for (let attempt = 0; attempt < attempts; attempt++) {
     const last = attempt === attempts - 1;
+    const started = Date.now();
     const controller = new AbortController();
     const timeout = setTimeout(() => controller.abort(), settings.timeoutMs);
     try {
@@ -179,7 +204,9 @@ async function requestProvider(
         body: JSON.stringify({
           model: settings.model,
           temperature: 0,
-          max_tokens: 300,
+          // A 300-character reason plus the JSON around it needs room; 300 tokens cut answers off before the
+          // closing brace, and reasoning models spend part of the budget before answering.
+          max_tokens: 1024,
           response_format: { type: "json_schema", json_schema: { name: "categorization", strict: true, schema } },
           messages: [{ role: "user", content }],
         }),
@@ -195,16 +222,48 @@ async function requestProvider(
             : attempt === 0
               ? 1000
               : 3000;
+        requestLog.warn("provider request failed, retrying", {
+          status: response.status,
+          attempt: attempt + 1,
+          attempts,
+          delay_ms: delay,
+        });
         await retryDelay(delay);
         continue;
       }
-      const body = (await response.json()) as { choices?: { message?: { content?: unknown } }[] };
+      const body = (await response.json()) as {
+        choices?: { message?: { content?: unknown }; finish_reason?: unknown }[];
+        usage?: { completion_tokens?: unknown; completion_tokens_details?: { reasoning_tokens?: unknown } };
+      };
       const raw = body.choices?.[0]?.message?.content;
-      if (typeof raw !== "string") throw new Error("AI provider returned no classification");
+      // What an admin needs to tell a cut-off answer (a reasoning model spending the token budget) from a bad one.
+      const answer = {
+        ms: Date.now() - started,
+        finish_reason: body.choices?.[0]?.finish_reason,
+        completion_tokens: body.usage?.completion_tokens,
+        reasoning_tokens: body.usage?.completion_tokens_details?.reasoning_tokens,
+        answer_chars: typeof raw === "string" ? raw.length : undefined,
+      };
+      const unusable = (message: string) => {
+        requestLog.warn("provider answer unusable", {
+          problem: message,
+          ...answer,
+          answer_end: typeof raw === "string" ? raw.slice(-120) : undefined,
+        });
+        return new Error(message);
+      };
+      if (typeof raw !== "string") throw unusable("AI provider returned no classification");
       const unfenced = raw
         .trim()
         .replace(/^```(?:json)?\s*/i, "")
         .replace(/\s*```$/, "");
+      const json = parseAnswerJson(unfenced);
+      if (json === undefined) {
+        // JSON.parse only says where it stopped, which tells an admin nothing about the provider.
+        if (body.choices?.[0]?.finish_reason === "length")
+          throw unusable("AI provider cut the answer off at its token limit");
+        throw unusable("AI provider returned an answer that is not valid JSON");
+      }
       const parsed = z
         .object({
           // Providers without a grammar sometimes quote the number.
@@ -212,14 +271,15 @@ async function requestProvider(
           confidence: z.number().finite(),
           reason: z.string(),
         })
-        .safeParse(JSON.parse(unfenced));
-      if (!parsed.success) throw new Error("AI provider returned invalid classification");
+        .safeParse(json);
+      if (!parsed.success) throw unusable("AI provider returned invalid classification");
       // Providers that ignore the schema's range (Ollama) can answer a whole percentage such as 85.
       const { confidence: stated } = parsed.data;
       const confidence = Number.isInteger(stated) && stated > 1 && stated <= 100 ? stated / 100 : stated;
-      if (confidence < 0 || confidence > 1) throw new Error("AI provider returned invalid classification");
+      if (confidence < 0 || confidence > 1) throw unusable("AI provider returned invalid classification");
       const chosen = parsed.data.category === null ? null : candidates[parsed.data.category - 1];
-      if (chosen === undefined) throw new Error("AI provider returned a category outside the candidate list");
+      if (chosen === undefined) throw unusable("AI provider returned a category outside the candidate list");
+      requestLog.debug("provider answered", { ...answer, category: parsed.data.category, confidence });
       return {
         categoryId: chosen?.id ?? null,
         confidence,
@@ -228,6 +288,11 @@ async function requestProvider(
     } catch (error) {
       const retryable = error instanceof TypeError || (error instanceof Error && error.name === "AbortError");
       if (!retryable || last) throw noSecretError(readableNetworkError(error, settings));
+      requestLog.warn("provider unreachable, retrying", {
+        error: noSecretError(readableNetworkError(error, settings)),
+        attempt: attempt + 1,
+        attempts,
+      });
       await retryDelay(attempt === 0 ? 1000 : 3000);
     } finally {
       clearTimeout(timeout);
@@ -249,10 +314,37 @@ async function clearSuggestion(
   await prisma.print.updateMany({ where, data: { aiSuggestion: Prisma.DbNull } });
 }
 
+/** Errors a caller expects on some models (a manual category, a folder, a model deleted meanwhile). */
+function isExpectedSkip(error: unknown): boolean {
+  return (
+    error instanceof HttpError &&
+    (error.status === 404 || (error.status === 409 && (error.code === "manual_category" || error.code === "folder")))
+  );
+}
+
+/** `source` only labels the log line: an import, a bulk run, or a request for one model. */
 export async function categorizePrint(
   userId: string,
   printId: string,
-  options: { force?: boolean } = {},
+  options: { force?: boolean; source?: "import" | "run" | "request" } = {},
+): Promise<CategorizationOutcome> {
+  const fields = { print: printId, source: options.source ?? "request" };
+  const started = Date.now();
+  try {
+    const outcome = await categorizeOne(userId, printId, options);
+    log.info("model categorized", { ...fields, outcome, ms: Date.now() - started });
+    return outcome;
+  } catch (error) {
+    if (isExpectedSkip(error)) log.info("model skipped", { ...fields, reason: (error as Error).message });
+    else log.warn("model categorization failed", { ...fields, error: noSecretError(error), ms: Date.now() - started });
+    throw error;
+  }
+}
+
+async function categorizeOne(
+  userId: string,
+  printId: string,
+  options: { force?: boolean },
 ): Promise<CategorizationOutcome> {
   const settings = await getAiCategorizationSettings();
   if (!aiCategorizationEnabled(settings)) throw new HttpError(503, "AI categorization is disabled", "ai_disabled");
@@ -312,12 +404,14 @@ export async function categorizePrint(
 
 /** Import creation deliberately never waits on a provider. */
 export function enqueueAiCategorization(userId: string, printId: string): void {
-  void getAiCategorizationSettings()
-    .then((settings) => {
+  void getAiCategorizationSettings().then(
+    (settings) => {
       if (!aiCategorizationEnabled(settings) || !settings.onImport) return;
-      return categorizePrint(userId, printId);
-    })
-    .catch((error) => console.warn("[ai-categorize]", printId, noSecretError(error).message));
+      // categorizePrint logs its own outcome and failure.
+      return categorizePrint(userId, printId, { source: "import" }).catch(() => undefined);
+    },
+    (error) => log.warn("could not read the AI settings for an imported model", { print: printId, error }),
+  );
 }
 
 export async function acceptAiSuggestion(userId: string, printId: string): Promise<void> {
@@ -430,14 +524,34 @@ export function startAiCategorizationRun(
     lastError: null,
   };
   runs.set(userId, run);
+  log.info("run started", {
+    user: userId,
+    include_ai: scope.includeAi,
+    include_rule: scope.includeRule,
+    include_legacy: scope.includeLegacy,
+  });
   void runAiCategorization(userId, run, scope)
     .catch((error) => {
       run.failed++;
       run.lastError = noSecretError(error).message;
+      log.error("run crashed", { user: userId, error: noSecretError(error) });
     })
     .finally(() => {
       run.running = false;
       run.finishedAt = new Date().toISOString();
+      const summary = {
+        user: userId,
+        total: run.total,
+        done: run.done,
+        applied: run.applied,
+        suggested: run.suggested,
+        no_match: run.noMatch,
+        failed: run.failed,
+        cancelled: run.cancelled,
+        last_error: run.lastError ?? undefined,
+      };
+      if (run.failed) log.warn("run finished with failures", summary);
+      else log.info("run finished", summary);
       void createLog({ userId, action: "ai_categorization_run", details: { ...run } });
     });
   return run;
@@ -463,12 +577,13 @@ async function runAiCategorization(
     );
   });
   run.total = selected.length;
+  log.info("run selected models", { user: userId, total: run.total, library: prints.length });
   let consecutiveProviderFailures = 0;
   for (const print of selected) {
     if (run.cancelled) break;
     let stop = false;
     try {
-      const outcome = await categorizePrint(userId, print.id);
+      const outcome = await categorizePrint(userId, print.id, { source: "run" });
       consecutiveProviderFailures = 0;
       if (outcome === "applied") run.applied++;
       else if (outcome === "suggested") run.suggested++;
@@ -482,12 +597,14 @@ async function runAiCategorization(
         consecutiveProviderFailures = 0;
       } else if (error instanceof HttpError && error.status === 503 && error.code === "ai_disabled") {
         run.lastError = noSecretError(error).message;
+        log.warn("run stopped: AI categorization was turned off", { user: userId, done: run.done });
         stop = true;
       } else {
         run.failed++;
         consecutiveProviderFailures++;
         if (consecutiveProviderFailures >= 5) {
           run.lastError = "AI provider is failing repeatedly; run stopped after 5 consecutive failures";
+          log.warn("run stopped after 5 consecutive failures", { user: userId, done: run.done + 1 });
           stop = true;
         } else {
           run.lastError = noSecretError(error).message;
@@ -502,6 +619,8 @@ async function runAiCategorization(
 export function cancelAiCategorizationRun(userId: string): AiCategorizationRun | null {
   const run = runs.get(userId);
   if (!run) return null;
+  if (run.running && !run.cancelled)
+    log.info("run cancel requested", { user: userId, done: run.done, total: run.total });
   run.cancelled = true;
   return run;
 }

backend/src/services/importJobRunner.ts

@@ -36,6 +36,10 @@ import { CLOUDFLARE_BLOCKED_CODE } from "./flaresolverr";
 import { HttpError } from "../utils/fileUtils";
 import { prisma } from "../db";
 import type { ImportJob } from "@prisma/client";
+import { createLogger } from "../logger";
+
+const log = createLogger("import");
+const syncLog = createLogger("sync");
 
 // Sequential on purpose: parallel bursts of api.bambulab.com calls trip MakerWorld's CAPTCHA.
 const COLLECTION_IMPORT_CONCURRENCY = 1;
@@ -80,7 +84,7 @@ function asStopReason(reason: ImportFailureReason): StopReason | null {
 
 async function markJobFailed(jobId: string, err: unknown): Promise<void> {
   const message = err instanceof Error ? err.message : "Import failed";
-  console.error(`Import job ${jobId} failed:`, err);
+  log.error("job failed", { job: jobId, error: err });
   await updateJob(jobId, { status: "ERROR", errorMessage: message }).catch(() => undefined);
 }
 
@@ -125,6 +129,7 @@ async function importProfileUrlsSequentially(
       } catch (err) {
         totals.failed++;
         totals.stopReason = asStopReason(classifyImportFailure(err));
+        log.warn("profile import failed", { url: profileUrl, reason: classifyImportFailure(err), error: err });
       }
     }
     totals.processed++;
@@ -153,6 +158,7 @@ export async function runMakerworldProfilesImportJob(
     const title =
       typeof design.title === "string" && design.title.trim() ? decodeHtmlEntities(design.title.trim()) : null;
     await updateJob(jobId, { total: profileIds.length, sourceLabel: title });
+    log.info("makerworld profiles job started", { job: jobId, url: body.url, profiles: profileIds.length });
 
     const totals = await importProfileUrlsSequentially(
       userId,
@@ -168,6 +174,13 @@ export async function runMakerworldProfilesImportJob(
     );
     const { imported, alreadyInLibrary, failed, stopReason } = totals;
     const printId = totals.printId;
+    log.info("makerworld profiles job done", {
+      job: jobId,
+      imported,
+      already_in_library: alreadyInLibrary,
+      failed,
+      stop_reason: stopReason ?? undefined,
+    });
 
     await updateJob(jobId, {
       status: "DONE",
@@ -230,6 +243,7 @@ export async function runCollectionImportJob(
     let authFailed = 0;
     const failed: string[] = [];
     const successPrintIds: string[] = [];
+    log.info("makerworld collection job started", { job: jobId, url: body.url, models: body.design_ids.length });
 
     await mapWithConcurrency(body.design_ids, COLLECTION_IMPORT_CONCURRENCY, async (designId) => {
       const modelUrl = `https://makerworld.com/en/models/${designId}`;
@@ -253,6 +267,7 @@ export async function runCollectionImportJob(
       } catch (err) {
         failed.push(designId);
         const reason = classifyImportFailure(err);
+        log.warn("model import failed", { job: jobId, url: modelUrl, reason, error: err });
         if (reason === "unavailable") unavailable++;
         else if (reason === "rateLimited") rateLimited++;
         else if (reason === "downloadLimit") downloadLimited++;
@@ -291,6 +306,13 @@ export async function runCollectionImportJob(
       }
     }
 
+    log.info("collection job done", {
+      job: jobId,
+      collection: collectionTitle,
+      imported,
+      already_in_library: alreadyInLibrary,
+      failed: failed.length,
+    });
     await updateJob(jobId, {
       status: "DONE",
       sourceLabel: collectionTitle,
@@ -374,6 +396,7 @@ async function runThingiverseThingsImportJob(
     let authFailed = 0;
     const failed: string[] = [];
     const successPrintIds: string[] = [];
+    log.info("thingiverse job started", { job: jobId, url: body.url, models: body.thing_ids.length });
 
     await mapWithConcurrency(body.thing_ids, COLLECTION_IMPORT_CONCURRENCY, async (thingId, index) => {
       const thingUrl = `https://www.thingiverse.com/thing:${thingId}`;
@@ -391,6 +414,7 @@ async function runThingiverseThingsImportJob(
       } catch (err) {
         failed.push(thingId);
         const reason = classifyImportFailure(err);
+        log.warn("model import failed", { job: jobId, url: thingUrl, reason, error: err });
         if (reason === "unavailable") unavailable++;
         else if (reason === "rateLimited") rateLimited++;
         else if (reason === "auth") authFailed++;
@@ -412,6 +436,13 @@ async function runThingiverseThingsImportJob(
       resultCollectionId = collection.id;
     }
 
+    log.info("collection job done", {
+      job: jobId,
+      collection: collectionTitle,
+      imported,
+      already_in_library: alreadyInLibrary,
+      failed: failed.length,
+    });
     await updateJob(jobId, {
       status: "DONE",
       sourceLabel: collectionTitle,
@@ -502,6 +533,7 @@ export async function runPrintablesCollectionImportJob(
     let rateLimited = 0;
     const failed: string[] = [];
     const successPrintIds: string[] = [];
+    log.info("printables collection job started", { job: jobId, url: body.url, models: body.model_ids.length });
 
     await mapWithConcurrency(body.model_ids, COLLECTION_IMPORT_CONCURRENCY, async (modelId, index) => {
       const modelUrl = `https://www.printables.com/model/${modelId}`;
@@ -519,6 +551,7 @@ export async function runPrintablesCollectionImportJob(
       } catch (err) {
         failed.push(modelId);
         const reason = classifyImportFailure(err);
+        log.warn("model import failed", { job: jobId, url: modelUrl, reason, error: err });
         if (reason === "unavailable") unavailable++;
         else if (reason === "rateLimited") rateLimited++;
       } finally {
@@ -542,6 +575,13 @@ export async function runPrintablesCollectionImportJob(
       resultCollectionId = collection.id;
     }
 
+    log.info("collection job done", {
+      job: jobId,
+      collection: collectionTitle,
+      imported,
+      already_in_library: alreadyInLibrary,
+      failed: failed.length,
+    });
     await updateJob(jobId, {
       status: "DONE",
       sourceLabel: collectionTitle,
@@ -592,6 +632,7 @@ export async function runZipImportJob(jobId: string, userId: string, body: ZipIm
     if (path.extname(filename).toLowerCase() !== ".zip") throw new HttpError(415, "Imported file is not a zip");
 
     await updateJob(jobId, { sourceLabel: filename, total: body.entries.length });
+    log.info("zip job started", { job: jobId, file: filename, entries: body.entries.length });
 
     const author = await upsertAuthorFromImport(meta.author);
     const { prints, failed } = await extractZipEntriesToPrints(
@@ -613,6 +654,7 @@ export async function runZipImportJob(jobId: string, userId: string, body: ZipIm
       },
     );
 
+    log.info("zip job done", { job: jobId, file: filename, imported: prints.length, failed: failed.length });
     await updateJob(jobId, {
       status: "DONE",
       processed: body.entries.length,
@@ -732,7 +774,7 @@ async function importOneLink(
  *  cooloff or a cookie update. */
 export function runLinksImportJob(jobId: string, userId: string, body: LinksImportJobBody): Promise<void> {
   if (liveRunners.has(jobId)) {
-    console.warn(`[import] job ${jobId}: a runner is already working on it, not starting another`);
+    log.warn("a runner is already working on this job, not starting another", { job: jobId });
     return Promise.resolve();
   }
   const run = runLinks(jobId, userId, body).finally(() => {
@@ -748,7 +790,7 @@ async function runLinks(jobId: string, userId: string, body: LinksImportJobBody)
     if (!job) throw new HttpError(404, "Import job not found");
     const items = (await listJobItems(jobId)).filter((item) => item.status === "PENDING");
     const total = await countJobItems(jobId, { in: ["PENDING", "RUNNING", "DONE", "FAILED"] });
-    console.log(`[import] job ${jobId}: running ${items.length} of ${total} links`);
+    log.info("links job running", { job: jobId, pending: items.length, total });
 
     let imported = 0;
     let alreadyInLibrary = 0;
@@ -769,7 +811,7 @@ async function runLinks(jobId: string, userId: string, body: LinksImportJobBody)
       if (index > 0 && body.itemDelayMs) await sleep(body.itemDelayMs);
       // Pausing only flips the status; the link that's importing finishes and the rest wait.
       if ((await getJobStatus(jobId)) === "PAUSED") {
-        console.log(`[import] job ${jobId}: paused, ${processed} of ${total} links processed`);
+        log.info("links job paused", { job: jobId, processed, total });
         return;
       }
       const options = parseQueuedLinkOptions(item.payload);
@@ -831,15 +873,19 @@ async function runLinks(jobId: string, userId: string, body: LinksImportJobBody)
           if (!isTransientImportFailure(err) || attempts >= LINKS_MAX_ATTEMPTS) {
             settled = true;
           } else {
-            console.warn(
-              `[import] job ${jobId}: ${item.url} failed (${itemError}), retrying (attempt ${attempts + 1} of ${LINKS_MAX_ATTEMPTS})`,
-            );
+            log.warn("link failed, retrying", {
+              job: jobId,
+              url: item.url,
+              error: itemError,
+              attempt: attempts + 1,
+              attempts: LINKS_MAX_ATTEMPTS,
+            });
             await sleep(LINKS_RETRY_DELAY_MS * attempts);
           }
         }
       }
-      if (itemError) console.error(`[import] job ${jobId}: ${item.url} failed: ${itemError}`);
-      else console.log(`[import] job ${jobId}: ${item.url} imported`);
+      if (itemError) log.warn("link failed", { job: jobId, url: item.url, error: itemError, attempts });
+      else log.info("link imported", { job: jobId, url: item.url });
       if (stopReason && !stopUrl) stopUrl = item.url;
       // The connection failed, not the models: the rest go back to unseen, for the next sync to find
       // again once it works. A link that got some of its profiles in is done.
@@ -879,9 +925,12 @@ async function runLinks(jobId: string, userId: string, body: LinksImportJobBody)
 
     const totalImported = job.imported + imported;
     const failedCount = await countJobItems(jobId, "FAILED");
-    console.log(
-      `[import] job ${jobId}: done, ${totalImported} imported, ${job.alreadyInLibrary + alreadyInLibrary} already in library, ${failedCount} failed`,
-    );
+    log.info("links job done", {
+      job: jobId,
+      imported: totalImported,
+      already_in_library: job.alreadyInLibrary + alreadyInLibrary,
+      failed: failedCount,
+    });
     await updateJob(jobId, {
       status: "DONE",
       processed,
@@ -987,7 +1036,7 @@ async function pauseSyncJob(job: ImportJob, reason: StopReason, newPrintIds: str
     processed: (await countJobItems(job.id, "DONE")) + (await countJobItems(job.id, "FAILED")),
     failedCount: await countJobItems(job.id, "FAILED"),
   });
-  console.warn(`[sync] job ${job.id}: paused, ${stopText}; ${waiting} links waiting`);
+  syncLog.warn("job paused", { job: job.id, reason: stopText, waiting });
   const owner = await prisma.user.findUnique({ where: { id: job.userId }, select: { role: true } });
   const isAdmin = owner?.role === "ADMIN";
   const name = sync?.collection.name ?? job.sourceLabel ?? "a synced collection";
@@ -1012,7 +1061,9 @@ async function pauseSyncJob(job: ImportJob, reason: StopReason, newPrintIds: str
 
 /** Scheduled MakerWorld syncs then wait for a new cookie instead of meeting the same refusal. */
 async function noteMakerworldRejected(userId: string): Promise<void> {
-  await markMakerworldCookieRejected(userId).catch((err) => console.error("[import] couldn't mark cookie:", err));
+  await markMakerworldCookieRejected(userId).catch((err) =>
+    log.error("couldn't mark the MakerWorld cookie rejected", { user: userId, error: err }),
+  );
 }
 
 type SyncDeferral = { count: number; reason: "auth" | "blocked" };
@@ -1052,7 +1103,7 @@ async function deferSyncRest(job: ImportJob, currentItemId: string | null, reaso
     }
     return items;
   });
-  console.warn(`[sync] job ${job.id}: ${handedBack.length} links handed back to the sync (${reason})`);
+  syncLog.warn("links handed back to the sync", { job: job.id, links: handedBack.length, reason });
   return handedBack.length;
 }
 
@@ -1111,6 +1162,6 @@ async function fileIntoCollection(userId: string, collectionId: string, printId:
     const collection = await prisma.collection.findFirst({ where: { id: collectionId, userId } });
     if (collection) await addPrintsToCollection(collection.id, [printId]);
   } catch (err) {
-    console.warn(`[import] couldn't add ${printId} to collection ${collectionId}:`, err);
+    log.warn("couldn't add the model to its collection", { print: printId, collection: collectionId, error: err });
   }
 }

backend/tests/aiCategorization.test.ts

@@ -1,5 +1,5 @@
 import http from "node:http";
-import { afterAll, afterEach, beforeAll, describe, expect, it } from "vitest";
+import { afterAll, afterEach, beforeAll, describe, expect, it, vi } from "vitest";
 import request from "supertest";
 import { createApp } from "../src/app";
 import { prisma } from "../src/db";
@@ -25,7 +25,14 @@ let providerMaxInFlight = 0;
 type ProviderAnswer = { category_id: string | null; confidence: number; reason: string };
 type ProviderReply =
   | ProviderAnswer
-  | { status: number; headers?: Record<string, string>; content?: ProviderAnswer | string; never?: boolean };
+  | {
+      status: number;
+      headers?: Record<string, string>;
+      content?: ProviderAnswer | string;
+      finishReason?: string;
+      usage?: Record<string, unknown>;
+      never?: boolean;
+    };
 type ProviderHandler = (body: Record<string, unknown>) => ProviderReply | Promise<ProviderReply>;
 
 type User = { id: string; token: string };
@@ -91,7 +98,9 @@ async function startProvider(handler: ProviderHandler) {
           typeof content === "string"
             ? await toProviderText(body, content)
             : JSON.stringify(await toProviderJson(body, content));
-        res.end(JSON.stringify({ choices: [{ message: { content: text } }] }));
+        const finishReason = isAnswer(reply) ? "stop" : (reply.finishReason ?? "stop");
+        const usage = isAnswer(reply) ? undefined : reply.usage;
+        res.end(JSON.stringify({ choices: [{ message: { content: text }, finish_reason: finishReason }], usage }));
       } catch (error) {
         res.writeHead(500, { "content-type": "application/json" });
         res.end(JSON.stringify({ error: error instanceof Error ? error.message : "provider failed" }));
@@ -404,6 +413,144 @@ describe("AI categorization", () => {
     }
   });
 
+  it("explains an answer cut off by the token limit instead of a JSON parse position", async () => {
+    const target = await category("Cut off target");
+    // A reason filled to its 300-character limit, cut before the closing brace: what a small max_tokens produced.
+    const cut = `{"reason":"${"r".repeat(300)}","category_id":"${target.id}"`;
+    const replies: ProviderReply[] = [
+      {
+        status: 200,
+        content: cut,
+        finishReason: "length",
+        usage: { completion_tokens: 1024, completion_tokens_details: { reasoning_tokens: 900 } },
+      },
+      { status: 200, content: cut },
+      { status: 200, content: '{"category_id":null,"confidence":1,"reason":"fine"}', finishReason: "length" },
+    ];
+    let maxTokens: unknown;
+    const baseUrl = await startProvider((body) => {
+      maxTokens = body.max_tokens;
+      return replies.shift()!;
+    });
+    await enable(baseUrl);
+    const warnings: string[] = [];
+    vi.spyOn(console, "warn").mockImplementation((line: unknown) => void warnings.push(String(line)));
+
+    const cutPrint = await print();
+    const limited = await request(app).post(`/api/print/${cutPrint.id}/recategorize`).set(auth()).send({});
+    vi.restoreAllMocks();
+    expect(limited.status).toBe(502);
+    expect(limited.body.error).toBe("AI provider failed: AI provider cut the answer off at its token limit");
+    // The log says why, for which model, and how the token budget went: the run status only keeps the last error.
+    const answerLine = warnings.find((line) => line.includes("provider answer unusable"));
+    expect(answerLine).toContain(`print=${cutPrint.id}`);
+    expect(answerLine).toContain("finish_reason=length");
+    expect(answerLine).toContain("completion_tokens=1024");
+    expect(answerLine).toContain("reasoning_tokens=900");
+    expect(answerLine).toContain("answer_chars=");
+    expect(answerLine).toContain(`answer_end=`);
+    const failureLine = warnings.find((line) => line.includes("model categorization failed"));
+    expect(failureLine).toContain(`print=${cutPrint.id}`);
+    expect(failureLine).toContain("source=request");
+    // Leaves room for a full-length reason and the JSON around it.
+    expect(maxTokens).toBeGreaterThanOrEqual(1024);
+
+    // A provider that doesn't report finish_reason still gets a readable error.
+    const unreported = await request(app)
+      .post(`/api/print/${(await print()).id}/recategorize`)
+      .set(auth())
+      .send({});
+    expect(unreported.status).toBe(502);
+    expect(unreported.body.error).toBe("AI provider failed: AI provider returned an answer that is not valid JSON");
+    expect(unreported.body.error).not.toContain("position");
+
+    // A complete answer that still reports the limit is used: a cut-off object never parses.
+    const completeAtLimit = await request(app)
+      .post(`/api/print/${(await print()).id}/recategorize`)
+      .set(auth())
+      .send({});
+    expect(completeAtLimit.status).toBe(200);
+    expect(completeAtLimit.body.outcome).toBe("no_match");
+    expect(providerRequests).toBe(3);
+  });
+
+  it("reads an answer wrapped in markdown or prose by a provider that ignores response_format", async () => {
+    const target = await category("Wrapped target");
+    const answer = `{"reason":"fits","category_id":"${target.id}","confidence":0.9}`;
+    const replies: ProviderReply[] = [
+      // What Xiaomi MiMo sent back: the object in bold.
+      { status: 200, content: `**${answer}**` },
+      { status: 200, content: `Here is my answer:\n${answer}\nHope this helps.` },
+      // Braces in prose around something that still isn't JSON: a clear failure, not a crash.
+      { status: 200, content: "I think {it is a tool} but {not sure}" },
+    ];
+    const baseUrl = await startProvider(() => replies.shift()!);
+    await enable(baseUrl);
+
+    for (const wrapped of ["bold", "prose"]) {
+      const response = await request(app)
+        .post(`/api/print/${(await print()).id}/recategorize`)
+        .set(auth())
+        .send({});
+      // The label rides along so a failure says which wrapping broke.
+      expect({ wrapped, status: response.status }).toEqual({ wrapped, status: 200 });
+      expect({ wrapped, ...response.body }).toMatchObject({
+        wrapped,
+        outcome: "suggested",
+        print: { ai_suggestion: { category_id: target.id } },
+      });
+    }
+
+    const notJson = await request(app)
+      .post(`/api/print/${(await print()).id}/recategorize`)
+      .set(auth())
+      .send({});
+    expect(notJson.status).toBe(502);
+    expect(notJson.body.error).toBe("AI provider failed: AI provider returned an answer that is not valid JSON");
+  });
+
+  it("logs a run's start, each failed model and the totals", async () => {
+    const runner = await newUser();
+    await categoryFor(runner.id, "Run log target");
+    const failing = await printFor(runner.id);
+    const fine = await printFor(runner.id);
+    const baseUrl = await startProvider(async (body) =>
+      promptText(body).includes(failing.name)
+        ? { status: 200, content: "not json" }
+        : { category_id: null, confidence: 1, reason: "none" },
+    );
+    await enable(baseUrl);
+    const lines: string[] = [];
+    for (const stream of ["log", "warn", "error"] as const) {
+      vi.spyOn(console, stream).mockImplementation((line: unknown) => void lines.push(String(line)));
+    }
+    try {
+      const started = await request(app)
+        .post("/api/ai-categorization/run")
+        .set(auth(runner.token))
+        .send({ include_ai: false, include_rule: false, include_legacy: false });
+      expect(started.status).toBe(202);
+      await waitForRun(runner.token);
+      await waitFor(() => lines.some((line) => line.includes("run finished")), "run finish was not logged");
+    } finally {
+      vi.restoreAllMocks();
+    }
+    expect(lines.find((line) => line.includes("run started"))).toContain(`user=${runner.id}`);
+    expect(lines.find((line) => line.includes("run selected models"))).toContain("total=2");
+    const failedLine = lines.find((line) => line.includes("model categorization failed"));
+    expect(failedLine).toContain(`print=${failing.id}`);
+    expect(failedLine).toContain("source=run");
+    expect(failedLine).toContain("not valid JSON");
+    expect(lines.find((line) => line.includes(`print=${fine.id}`) && line.includes("model categorized"))).toContain(
+      "outcome=no_match",
+    );
+    const finished = lines.find((line) => line.includes("run finished"))!;
+    expect(finished).toMatch(/WARN .*run finished with failures/);
+    expect(finished).toContain("total=2");
+    expect(finished).toContain("failed=1");
+    expect(finished).toContain("no_match=1");
+  });
+
   it("tells the provider a model's current category", async () => {
     const current = await category("Current hint");
     const prompts: string[] = [];

backend/tests/importJobRunner.test.ts

@@ -124,6 +124,50 @@ describe("runCollectionImportJob", () => {
     );
   });
 
+  it("logs the job's start, each failed model with why, and the totals", async () => {
+    vi.mocked(importPrintFromUrl).mockImplementation(async (_userId: string, url: string) => {
+      if (url.endsWith("/41")) throw new HttpError(404, "Not found");
+      if (url.endsWith("/42")) throw new HttpError(429, "MakerWorld is challenging this account with a CAPTCHA");
+      return {
+        print: { id: "print-40" } as never,
+        plates: [],
+        author: null,
+        previewImages: [],
+        alreadyImported: false,
+      };
+    });
+    const job = await createJob(userId, "COLLECTION", {
+      sourceUrl: "https://makerworld.com/en/models/does-not-matter",
+      provider: "makerworld",
+      total: 3,
+    });
+    const lines: string[] = [];
+    for (const stream of ["log", "warn", "error"] as const) {
+      vi.spyOn(console, stream).mockImplementation((line: unknown) => void lines.push(String(line)));
+    }
+    try {
+      await runCollectionImportJob(job.id, userId, {
+        url: "https://makerworld.com/en/models/does-not-matter",
+        design_ids: ["40", "41", "42"],
+        tags: [],
+      });
+    } finally {
+      vi.mocked(console.log).mockRestore();
+      vi.mocked(console.warn).mockRestore();
+      vi.mocked(console.error).mockRestore();
+    }
+
+    const ofJob = lines.filter((line) => line.includes(`job=${job.id}`));
+    expect(ofJob[0]).toMatch(/INFO  \[import\] makerworld collection job started .*models=3/);
+    const failures = ofJob.filter((line) => line.includes("model import failed"));
+    expect(failures).toHaveLength(2);
+    expect(failures[0]).toMatch(
+      /WARN .*url=https:\/\/makerworld\.com\/en\/models\/41 reason=unavailable error="Not found"/,
+    );
+    expect(failures[1]).toContain("reason=rateLimited");
+    expect(ofJob.at(-1)).toMatch(/collection job done .*imported=1 already_in_library=0 failed=2/);
+  });
+
   it("still marks the job DONE even if every model in the batch is unavailable", async () => {
     const mockedImport = vi.mocked(importPrintFromUrl);
     mockedImport.mockImplementation(async () => {

backend/tests/logger.test.ts

@@ -0,0 +1,124 @@
+import { afterEach, beforeEach, describe, expect, it, vi } from "vitest";
+import { createLogger } from "../src/logger";
+import { HttpError } from "../src/utils/fileUtils";
+
+let lines: { stream: "log" | "warn" | "error"; text: string }[];
+const saved = { level: process.env.LOG_LEVEL, format: process.env.LOG_FORMAT };
+
+beforeEach(() => {
+  lines = [];
+  for (const stream of ["log", "warn", "error"] as const) {
+    vi.spyOn(console, stream).mockImplementation((text: unknown) => {
+      lines.push({ stream, text: String(text) });
+    });
+  }
+  delete process.env.LOG_LEVEL;
+  delete process.env.LOG_FORMAT;
+});
+
+afterEach(() => {
+  vi.restoreAllMocks();
+  for (const [key, value] of [
+    ["LOG_LEVEL", saved.level],
+    ["LOG_FORMAT", saved.format],
+  ] as const) {
+    if (value === undefined) delete process.env[key];
+    else process.env[key] = value;
+  }
+});
+
+describe("logger", () => {
+  it("writes a level, the scope, the message and greppable fields", () => {
+    createLogger("import").info("job done", { job: "cm1", imported: 3, url: "https://x.test/a b", empty: "" });
+    expect(lines).toHaveLength(1);
+    expect(lines[0].stream).toBe("log");
+    expect(lines[0].text).toMatch(
+      /^\d{4}-\d\d-\d\dT[\d:.]+Z INFO  \[import\] job done job=cm1 imported=3 url="https:\/\/x\.test\/a b" empty=""$/,
+    );
+  });
+
+  it("sends warnings and errors to stderr and leaves out undefined fields", () => {
+    const log = createLogger("ai");
+    log.warn("slow", { attempt: 2, skipped: undefined });
+    log.error("broke");
+    expect(lines.map((line) => line.stream)).toEqual(["warn", "error"]);
+    expect(lines[0].text).not.toContain("skipped");
+  });
+
+  it("drops lines below LOG_LEVEL and falls back to info on a value it doesn't know", () => {
+    const log = createLogger("x");
+    log.debug("hidden by default");
+    process.env.LOG_LEVEL = "DEBUG";
+    log.debug("shown");
+    process.env.LOG_LEVEL = "warn";
+    log.info("hidden");
+    log.warn("kept");
+    process.env.LOG_LEVEL = "verbose";
+    log.debug("hidden again");
+    log.info("info again");
+    expect(lines.map((line) => line.text.split("] ")[1])).toEqual(["shown", "kept", "info again"]);
+  });
+
+  it("logs an error's message, status and code, and the stack only at error level", () => {
+    const log = createLogger("x");
+    const error = new HttpError(429, "slow down", "rate_limited");
+    log.warn("item failed", { error });
+    expect(lines[0].text).toContain('error="slow down"');
+    expect(lines[0].text).not.toContain("\n");
+
+    log.error("job failed", { error: new Error("disk full") });
+    expect(lines[1].text).toContain('error="disk full"');
+    expect(lines[1].text).toContain("\nError: disk full\n    at ");
+
+    process.env.LOG_FORMAT = "json";
+    log.warn("item failed", { error });
+    expect(JSON.parse(lines[2].text).error).toEqual({
+      message: "slow down",
+      name: "HttpError",
+      status: 429,
+      code: "rate_limited",
+    });
+  });
+
+  it("writes one parseable JSON object per line with LOG_FORMAT=json", () => {
+    process.env.LOG_FORMAT = "json";
+    // A field can't overwrite what the line itself says.
+    createLogger("sync", { job: "j1" }).info('he said "hi"\nthen left', { level: "fake", count: 2n });
+    const record = JSON.parse(lines[0].text);
+    expect(record).toMatchObject({
+      level: "info",
+      scope: "sync",
+      message: 'he said "hi"\nthen left',
+      job: "j1",
+      count: "2",
+    });
+    expect(lines[0].text).not.toContain("\n");
+  });
+
+  it("still writes the line when a field can't be serialized", () => {
+    const circular: Record<string, unknown> = { name: "loop" };
+    circular.self = circular;
+    const log = createLogger("x");
+    log.info("text", { circular });
+    expect(lines[0].text).toContain("circular=[unserializable]");
+    process.env.LOG_FORMAT = "json";
+    log.info("json", { circular });
+    expect(JSON.parse(lines[1].text)).toMatchObject({ message: "json", fields: "[unserializable]" });
+  });
+
+  it("adds a child's fields to every line, letting a call's own fields win", () => {
+    const job = createLogger("import").child({ job: "j1", provider: "makerworld" });
+    job.info("start", { provider: "printables" });
+    expect(lines[0].text).toContain("job=j1 provider=printables");
+  });
+
+  it("redacts bearer tokens wherever they appear", () => {
+    const log = createLogger("ai");
+    log.warn("request failed Bearer sk-secret1", { error: new Error("header was Bearer sk-secret2, rejected") });
+    process.env.LOG_FORMAT = "json";
+    log.warn("again", { header: "Bearer sk-secret3" });
+    const all = lines.map((line) => line.text).join("\n");
+    expect(all).not.toMatch(/sk-secret/);
+    expect(all).toContain("Bearer [redacted]");
+  });
+});