feat(provider): log why a live model catalog kept its fallback

A connection that drops or times out mid-body now counts as unavailable
rather than malformed, so routine network trouble stays at debug while
an empty or malformed catalog warns.

Author: bwachman

src/provider/bounded-model-catalog.ts

@@ -1,8 +1,12 @@
+import { getLogger } from "@intx/log";
+import { LOG_NAMESPACE_ROOT } from "../branding.js";
 import {
   endpointErrorMessage,
   type ModelsEndpointDiscoveryState,
 } from "./models-endpoint.js";
 
+const catalogLogger = getLogger([LOG_NAMESPACE_ROOT, "provider", "catalog"]);
+
 export type CatalogDiscoveryState = ModelsEndpointDiscoveryState;
 
 function declaredCatalogBytes(response: Response): number | undefined {
@@ -18,20 +22,24 @@ async function readBoundedCatalogText(
   args: { readonly maxBytes: number; readonly oversizeMessage: string },
 ): Promise<
   | { readonly ok: true; readonly text: string }
-  | { readonly ok: false; readonly message: string }
+  | {
+      readonly ok: false;
+      readonly message: string;
+      readonly transport: boolean;
+    }
 > {
   const declared = declaredCatalogBytes(response);
   if (declared !== undefined && declared > args.maxBytes) {
     await response.body?.cancel().catch(() => undefined);
-    return { ok: false, message: args.oversizeMessage };
+    return { ok: false, message: args.oversizeMessage, transport: false };
   }
 
   try {
     const body = response.body;
     if (body === null) {
       const text = await response.text();
       if (new TextEncoder().encode(text).byteLength > args.maxBytes) {
-        return { ok: false, message: args.oversizeMessage };
+        return { ok: false, message: args.oversizeMessage, transport: false };
       }
       return { ok: true, text };
     }
@@ -46,7 +54,7 @@ async function readBoundedCatalogText(
       total += value.byteLength;
       if (total > args.maxBytes) {
         await reader.cancel().catch(() => undefined);
-        return { ok: false, message: args.oversizeMessage };
+        return { ok: false, message: args.oversizeMessage, transport: false };
       }
       chunks.push(value);
     }
@@ -59,7 +67,11 @@ async function readBoundedCatalogText(
     }
     return { ok: true, text: new TextDecoder().decode(buffer) };
   } catch (error) {
-    return { ok: false, message: endpointErrorMessage(error) };
+    return {
+      ok: false,
+      message: endpointErrorMessage(error),
+      transport: true,
+    };
   }
 }
 
@@ -104,11 +116,13 @@ export function createBoundedModelCatalog<
     return `${catalogLabel} catalog exceeds ${String(maxModels)} models`;
   }
 
-  async function readCatalogJson(
-    response: Response,
-  ): Promise<
+  async function readCatalogJson(response: Response): Promise<
     | { readonly ok: true; readonly value: unknown }
-    | { readonly ok: false; readonly message: string }
+    | {
+        readonly ok: false;
+        readonly message: string;
+        readonly transport: boolean;
+      }
   > {
     const text = await readBoundedCatalogText(response, {
       maxBytes,
@@ -119,7 +133,11 @@ export function createBoundedModelCatalog<
       const value: unknown = JSON.parse(text.text);
       return { ok: true, value };
     } catch (error) {
-      return { ok: false, message: endpointErrorMessage(error) };
+      return {
+        ok: false,
+        message: endpointErrorMessage(error),
+        transport: false,
+      };
     }
   }
 
@@ -151,7 +169,12 @@ export function createBoundedModelCatalog<
 
     const body = await readCatalogJson(response);
     if (!body.ok) {
-      return { status: "malformed", message: body.message };
+      // A connection that drops or times out mid-body never delivered an
+      // answer; only a body that arrived and fails the contract is malformed.
+      return {
+        status: body.transport ? "unavailable" : "malformed",
+        message: body.message,
+      };
     }
     return parse(body.value, {
       maxModels,
@@ -169,10 +192,48 @@ export function createBoundedModelCatalog<
     // stale-but-live beats empty; a cold failure falls back to the seed.
     if (state.status === "models") {
       snapshot = state.models;
+    } else {
+      logFallback(state);
     }
     return selectableModelIds();
   }
 
+  // An unreachable catalog is routine (offline, transient outage), so it
+  // stays at debug. An empty or malformed answer means the endpoint's
+  // contract moved, which only shows up here, so it warns.
+  function logFallback(
+    state: Exclude<CatalogDiscoveryState, { status: "models" }>,
+  ): void {
+    const fallback =
+      snapshot === undefined ? "the built-in list" : "the last live list";
+    // HTTP and size failures already name the catalog; transport and parse
+    // errors do not, so the catalog is named exactly once either way.
+    const reason = (message: string): string =>
+      message.startsWith(catalogLabel)
+        ? message
+        : `${catalogLabel}: ${message}`;
+    switch (state.status) {
+      case "unavailable":
+        catalogLogger.debug(
+          "Model catalog unavailable ({reason}); keeping {fallback}",
+          { reason: reason(state.message), fallback },
+        );
+        return;
+      case "empty":
+        catalogLogger.warn(
+          "Model catalog listed no models ({catalog}); keeping {fallback}",
+          { catalog: catalogLabel, fallback },
+        );
+        return;
+      case "malformed":
+        catalogLogger.warn(
+          "Model catalog response rejected ({reason}); keeping {fallback}",
+          { reason: reason(state.message), fallback },
+        );
+        return;
+    }
+  }
+
   function prefetchModels(): Promise<Seed | DiscoveredModels> {
     if (inflight !== undefined) return inflight;
 

src/provider/model-catalogs.test.ts

@@ -1,4 +1,7 @@
 import { afterEach, beforeEach, describe, expect, test } from "bun:test";
+import { configureSync, getConfig, resetSync } from "@intx/log";
+
+import { defined } from "../../testkit/defined.js";
 
 import { OPENCODE_GO_MODEL_IDS } from "../../packages/opencode-go/src/index.js";
 import { ZEN_MODEL_IDS } from "../../packages/zen/src/index.js";
@@ -92,6 +95,35 @@ afterEach(() => {
   resetZenModelDiscoveryForTests();
 });
 
+// Records the catalog's own log lines; restores the previous log config even
+// when `run` throws so other files keep their sinks.
+async function captureCatalogLogs(
+  catalogLabel: string,
+  run: () => Promise<void>,
+): Promise<{ level: string; text: string }[]> {
+  const records: { level: string; text: string }[] = [];
+  const previous = getConfig();
+  configureSync({
+    reset: true,
+    sinks: {
+      test: (record) => {
+        records.push({
+          level: record.level,
+          text: record.message.map(String).join(""),
+        });
+      },
+    },
+    loggers: [{ category: [], lowestLevel: "debug", sinks: ["test"] }],
+  });
+  try {
+    await run();
+  } finally {
+    if (previous === null) resetSync();
+    else configureSync({ ...previous, reset: true });
+  }
+  return records.filter((r) => r.text.includes(catalogLabel));
+}
+
 function oversizedCatalogResponse(byteLength: number): Response {
   const chunk = new Uint8Array(64 * 1024).fill(0x61);
   let remaining = byteLength;
@@ -324,6 +356,80 @@ for (const harness of harnesses) {
       expect(selectable()).toEqual(seedIds);
     });
 
+    test("logs why a prefetch kept the fallback, warning only when the catalog answered badly", async () => {
+      const records = await captureCatalogLogs(catalogLabel, async () => {
+        globalThis.fetch = (async () =>
+          new Response("no", { status: 503 })) as unknown as typeof fetch;
+        await prefetch();
+        globalThis.fetch = (async () =>
+          Response.json({ data: [] })) as unknown as typeof fetch;
+        await prefetch();
+        globalThis.fetch = (async () =>
+          Response.json({ models: [] })) as unknown as typeof fetch;
+        await prefetch();
+      });
+
+      expect(records.map((r) => r.level)).toEqual([
+        "debug",
+        "warning",
+        "warning",
+      ]);
+      for (const record of records) {
+        expect(record.text).toContain("keeping the built-in list");
+        expect(record.text.split(catalogLabel)).toHaveLength(2);
+      }
+    });
+
+    test("a connection that drops mid-body logs as unavailable, not as a contract change", async () => {
+      const records = await captureCatalogLogs(catalogLabel, async () => {
+        globalThis.fetch = (async () => {
+          let sent = false;
+          const stream = new ReadableStream<Uint8Array>({
+            pull(controller) {
+              if (!sent) {
+                sent = true;
+                controller.enqueue(new TextEncoder().encode('{"data":['));
+                return;
+              }
+              controller.error(new Error("socket connection was closed"));
+            },
+          });
+          return new Response(stream, { status: 200 });
+        }) as unknown as typeof fetch;
+        await prefetch();
+      });
+
+      expect(records.map((r) => r.level)).toEqual(["debug"]);
+      expect(defined(records[0]).text).toContain("unavailable");
+    });
+
+    test("a failed refresh after a live list says it kept the last live list", async () => {
+      globalThis.fetch = (async () =>
+        Response.json({
+          data: [{ id: liveOnlyId }],
+        })) as unknown as typeof fetch;
+      await prefetch();
+
+      const records = await captureCatalogLogs(catalogLabel, async () => {
+        globalThis.fetch = (async () =>
+          Response.json({ data: [] })) as unknown as typeof fetch;
+        await prefetch();
+      });
+
+      expect(records).toHaveLength(1);
+      expect(defined(records[0]).text).toContain("keeping the last live list");
+    });
+
+    test("concurrent callers of one prefetch run produce one fallback record", async () => {
+      const records = await captureCatalogLogs(catalogLabel, async () => {
+        globalThis.fetch = (async () =>
+          Response.json({ data: [] })) as unknown as typeof fetch;
+        await Promise.all([prefetch(), prefetch(), prefetch()]);
+      });
+
+      expect(records).toHaveLength(1);
+    });
+
     test("oversized live catalog does not replace the seed with a truncated prefix", async () => {
       globalThis.fetch = (async () =>
         oversizedCatalogResponse(maxBytes + 1)) as unknown as typeof fetch;