[Bug]: Models from plugin providers vanish after restart until the 10-minute catalog cache expires #255

Summary

After a bot restart, models contributed by a plugin provider (here: opencode-cmd-provider) disappear from the favorites list and from the provider/model picker, and stay missing for up to 10 minutes. The bot reads the provider/model catalog a couple of seconds after the managed OpenCode server reports ready — before the server has finished registering all providers — then treats that partial snapshot as authoritative and caches it (MODEL_CATALOG_CACHE_TTL_MS = 10 * 60 * 1000). Stored favorites that are not in the snapshot are filtered out of the list the user sees.

The ready handler does try to wait for the server to warm up, but the wait condition is wrong: it polls until the catalog is non-empty (bounded by a hardcoded 3 s timeout, 500 ms interval) and then accepts whatever that snapshot contains. A fully empty catalog is rejected correctly (favorites kept), while a catalog that is non-empty yet incomplete — built-in providers registered, plugin provider still missing — is accepted as authoritative. That leaves a narrow window (roughly 2–4 s after the server becomes ready) in which the bot can poison its catalog for 10 minutes.

The ready wait is hardcoded and not configurable — there is no environment variable for it.

Environment

• opencode version: 2.0.18 (CLI, managed server, and bundled @opencode/client are all 2.0.18)
• OS: Linux 6.8.0-139-generic (x86_64), Ubuntu 24.04
• Node.js: v24.21.0
• opencode-telegram-bot: 0.26.0 (installed globally via npm, run as opencode-bot.service)
• Shell: /usr/bin/bash
• Install/channel: release (systemd service opencode-bot, OPENCODE_AUTO_RESTART_ENABLED=true, server on 127.0.0.1:49374)
• Active plugins: opencode-cmd-provider 2.1.9 (contributes the commandcode provider with 82 models)

Reproduction

1. Configure a plugin provider that contributes models — here opencode-cmd-provider (provider commandcode, 82 models). It is the only provider whose models come from a plugin; built-in providers (opencode, opencode, cline-pass) register earlier.

2. Put a model from that provider into the OpenCode model state favorites, in ~/.local/state/opencode/model.json:

   {"recent":[],"favorite":[{"providerID":"commandcode","modelID":"deepseek/deepseek-v4.1-flash"},{"providerID":"opencode-go","modelID":"deepseek-v4.1-flash"}],"variant":{}}

3. Run the bot with OPENCODE_AUTO_RESTART_ENABLED=true so the bot starts (and restarts) the managed server itself.

4. Restart the bot — systemctl restart opencode-bot.service — which also restarts the managed OpenCode server.

5. Watch the log. The server becomes ready, then the bot reads the catalog while the server is still warming up:

   01:26:56.654  [ModelManager] OpenCode server is not running; skipping model catalog refresh
   01:26:57.595  [OpenCodeAutoRestart] OpenCode server recovered: pid=790061, port=49374
   01:26:57.596  [OpenCodeReady] OpenCode server is ready: reason=auto_restart_startup
   01:26:59.109  [ModelManager] Model catalog is empty, treating it as unavailable: providers=0
   

   On an earlier restart the same sequence captured the bad case, where the snapshot was non-empty but incomplete:

   01:00:59.415  [OpenCodeAutoRestart] OpenCode server recovered: pid=787340, port=49374
   01:00:59.417  [OpenCodeReady] OpenCode server is ready: reason=auto_restart_startup
   01:01:00.915  [ModelManager] Model catalog is empty, treating it as unavailable: providers=0
   01:01:02.195  [ModelManager] Stored model commandcode/deepseek/deepseek-v4.1-flash is unavailable,
                 falling back to opencode/big-pickle
   

6. Open the model menu in Telegram. The env-default model is present, the plugin provider's model and provider are missing:

   01:23:18.031  [ModelManager] Filtered unavailable models from OpenCode state: favoritesRemoved=1, recentRemoved=0
   01:23:21.890  [ModelManager] Filtered unavailable models from OpenCode state: favoritesRemoved=1, recentRemoved=0
   01:24:03.369  [ModelManager] Filtered unavailable models from OpenCode state: favoritesRemoved=1, recentRemoved=0
   

7. Keep the bot running without further restarts for ~10 minutes. The catalog is re-read after the TTL expires and the missing models reappear.

Frequency: deterministic if the restart timing is reproduced; intermittent in practice, because it depends on whether the first catalog read lands in the warm-up window. Restarting the bot again before the 10-minute TTL expires re-arms the race and makes it look permanent.

Expected Behavior

The model catalog should not be treated as authoritative while the server is still registering providers, and a partial snapshot must not be used to filter stored favorites or be cached for 10 minutes.

Actual Behavior

• A non-empty but incomplete catalog is accepted as the source of truth.

• Stored favorites that are absent from that snapshot are silently removed from the bot's list (favoritesRemoved=1), and the selected model is rewritten to the env default:

  01:01:02.195  [ModelManager] Stored model commandcode/deepseek/deepseek-v4.1-flash is unavailable,
                falling back to opencode/big-pickle
  

• The bad snapshot is cached for 10 * 60 * 1000 ms, so the provider stays invisible for up to 10 minutes.

• Nothing in the ready sequence detects that the provider set was still growing — see Where it happens below.

• The env-default model is still shown, because it is appended to the favorites outside the catalog filter, which makes the symptom look like "only models from the plugin provider are gone":

  // src/app/services/model-selection-service.ts:264
  const favorites = envDefaultModel
    ? dedupeModels([...validatedFavorites, envDefaultModel])
    : validatedFavorites;

Additional Context

Where it happens

The wait that is supposed to cover the warm-up, and why it does not:

// src/opencode/ready-refresh.ts:14-30
// A freshly started server answers health before it lists any model, so wait (bounded)
// for a non-empty catalog before the rest of the ready sequence reads it.
async function refreshModelCatalogUntilAvailable(reason: string): Promise<void> {
  const startedAt = Date.now();

  while (!(await reconcileStoredModelSelection({ forceCatalogRefresh: true }))) {
    if (Date.now() - startedAt >= MODEL_CATALOG_WAIT_TIMEOUT_MS) {
      logger.warn(
        `[OpenCodeReady] Model catalog still unavailable after ${MODEL_CATALOG_WAIT_TIMEOUT_MS}ms: reason=${reason}`,
      );
      return;
    }

    logger.debug(`[OpenCodeReady] Model catalog not available yet, retrying: reason=${reason}`);
    await new Promise((resolve) => setTimeout(resolve, MODEL_CATALOG_POLL_INTERVAL_MS));
  }
}

The loop exits as soon as reconcileStoredModelSelection() reports the catalog as available, and that function only requires a non-empty, non-stale catalog:

// src/app/services/model-selection-service.ts:327-330
const { validModelKeys, isStale } = await readModelCatalog({ force: options?.forceCatalogRefresh });
const catalogAvailable = validModelKeys !== null && !isStale;

There is no check that the provider set has stopped growing, so a snapshot that contains only the built-in providers — while the plugin provider is still registering — ends the wait and wins.

The server side is healthy

The same catalog, read from the same client code a few minutes after the restart, is complete. GET /api/model (v2) returns 141 enabled models:

opencode-go    OpenCode Go     33 models
opencode       OpenCode Zen      8 models
cline-pass     ClinePass       18 models
commandcode    Command Code    82 models

Both favorites from model.json are present in that catalog, commandcode is registered as a provider (GET /api/provider → commandcode | Command Code | aisdk:[email protected]), and a real inference call succeeds:

$ opencode run -m commandcode/deepseek/deepseek-v4.1-flash "…"
> build · deepseek/deepseek-v4.1-flash
Работает.

So the plugin, the credential, the provider registration, and the models are all fine — only the bot's cached view of the catalog is wrong.

Suggested fix

The first point is the actual root cause; the rest is defence in depth.

1. Fix the exit condition of the ready wait (src/opencode/ready-refresh.ts:19-29). The loop must not accept the first non-empty catalog. Stop only when the provider set has stopped growing — for example, read the catalog, wait one poll interval, read again, and accept only when two consecutive reads report the same set of providers (and that set is non-empty), under a bounded timeout. Raising MODEL_CATALOG_WAIT_TIMEOUT_MS alone does not fix it: the loop exits on the first non-empty result no matter how long the timeout is.
2. Do not cache the empty/unavailable result for the full 10-minute TTL — retry on the next access instead.
3. Consider not filtering stored favorites while the catalog is known to be in a warm-up/unstable state (only filter against a catalog that included at least one model from every configured provider, or against the previous good snapshot).

Workaround

• Do not restart the bot immediately after the server; give the server time to register all providers before the first catalog read.
• If models are missing, either wait out the 10-minute TTL, or restart the bot while the server is already warm (the first catalog read is then complete).

Related

Judging by the logs, this is not version-specific: the same race was already present at 00:11 and 00:55 before any of the plugin/bot updates in this session — the restarts are just what makes it visible.