puter/paseo
1
0
Fork 0
mirror of https://github.com/getpaseo/paseo.git synced 2026-07-29 12:01:31 +00:00
Code Issues Packages Projects Releases Wiki Activity
Files
24526a3b2327362cfe2ffcd2f36bdb2034d9a05b
paseo/docs/diagnostics/opencode-provider-snapshot-timeout-2026-05-27.md
Mohamed Boudra 5a56835db3 Add startup diagnostics reports
2026-05-27 20:59:06 +07:00

15 KiB
Raw Blame History

OpenCode Provider Snapshot Startup Timeout Diagnosis - 2026-05-27

Answer

The startup timeout is real OpenCode provider snapshot work, not an agent resume path.

In the dev-style copied-home reproduction, the OpenCode snapshot misses the 30s budget because several expensive things stack:

  1. Paseo starts from a copied PASEO_HOME containing 4,851 agent records.
  2. Clients ask for provider snapshots for three cwd scopes at almost the same time:
    • /Users/moboudra
    • /Users/moboudra/dev/paseo
    • /Users/moboudra/dev/blankpage/editor
  3. Each OpenCode snapshot runs two OpenCode SDK calls:
    • GET /provider?directory=... through client.provider.list()
    • GET /agent?directory=... through client.app.agents()
  4. One cold opencode serve process is shared by the three cwd scopes. It took 8.562s to become ready.
  5. After OpenCode was listening, Paseo issued six OpenCode HTTP calls concurrently.
  6. The OpenCode /provider responses are large: about 3,549,620 decompressed bytes per cwd.
  7. During the same window, the daemon was still doing heavy startup workspace git work. In the exact 18:14:19-18:14:43 window, the daemon log has 292 git spawn/close events.
  8. The /provider calls eventually succeeded, but too late: they completed about 32.2s-32.5s after the snapshot fetch started, while the snapshot timeout is 30s.

So the root cause is:

Cold OpenCode server startup + three concurrent cwd snapshots + large OpenCode /provider responses + daemon startup git contention causes client.provider.list() to complete after Paseo's 30s snapshot budget.

More precise wording: the contention is machine-level process/CPU/filesystem contention created by daemon startup work, especially git work. It is not proven to be an OpenCode internal lock or a Paseo-only event-loop issue. A daemon-free repro with only OpenCode plus an external git storm slowed the same six OpenCode calls from about 1s to about 30s total.

Manual settings refresh works because it runs after startup contention is gone and uses force: true, which creates fresh OpenCode runtime/server state. The same OpenCode provider refreshes then complete in about 1.7s-2.2s.

The daemon does not auto-retry error snapshots. A failed provider snapshot is cached as status: "error" until an explicit refresh resets it to loading.

Follow-up: Normal Copied-Home Startup Check

I later reran a normal dev-daemon startup against a fresh copy of the same Paseo home metadata and drove the app startup request path:

fetchWorkspaces
fetchAgents
getProvidersSnapshot(home scope)
getProvidersSnapshot(first workspace scope)

That run did not reproduce the 30s OpenCode timeout.

home scope:
  OpenCode ready at ~8s
  availability: 1.6s
  fetch total: 5.2s

first workspace scope:
  OpenCode ready at ~26s
  availability: 2.0s
  fetch total: 15.4s

The slowest OpenCode operation in that successful run was the workspace-scoped /provider response body read: 13.6s. The daemon log had no Timed out refreshing OpenCode entry and no OpenCode provider snapshot failure.

This means the timeout is reproducible under the heavier multi-scope startup contention captured below, but it is not guaranteed on every copied-home dev startup.

Reproduction Used

The user's correction was right: the useful reproduction is not a random isolated home. It must match dev.sh worktree behavior.

Relevant scripts:

  • scripts/dev.sh
  • scripts/dev-daemon.sh
  • scripts/dev-home.sh

dev-home.sh only seeds this metadata into the dev home:

agents/**/*.json
projects/**/*.json
config.json

It does not copy chat, loops, schedules, sockets, pid files, logs, or worktree contents.

I ran a separate daemon, not the main daemon:

PASEO_HOME=/var/folders/xl/kkk9drfd3ms_t8x7rmy4z6900000gn/T/paseo-devseed.Wms6pi
PASEO_LISTEN=127.0.0.1:51116
PASEO_LOG_LEVEL=trace

Startup facts:

18:13:39.552 Agent storage initialized: 712ms
18:13:39.559 Workspace registries bootstrapped: 719ms
18:13:39.961 Agent registry loaded: 4851 records
18:13:39.972 Server listening: http://127.0.0.1:51116

The probe then connected four client sessions and requested:

  • workspaces
  • active agents
  • provider snapshots for home, paseo, and blankpage/editor

Client-visible result:

18:14:30.263 /Users/moboudra/dev/blankpage/editor opencode error:
  OpenCode app.agents timed out after 10s

18:14:41.687 /Users/moboudra/dev/paseo opencode error:
  Timed out refreshing OpenCode after 30000ms

18:14:41.688 /Users/moboudra opencode error:
  Timed out refreshing OpenCode after 30000ms

Exact OpenCode Timeline

OpenCode snapshot requests began at 18:14:10.

Availability checks:

18:14:10.780 opencode availability start for /Users/moboudra
18:14:10.787 opencode availability start for /Users/moboudra/dev/paseo
18:14:10.800 opencode availability start for /Users/moboudra/dev/blankpage/editor

18:14:11.363 paseo availability complete: 576ms
18:14:11.376 home availability complete: 597ms
18:14:11.391 blankpage availability complete: 591ms

OpenCode server acquisition:

18:14:11.364 OpenCode server spawn start: opencode serve --port 56376
18:14:19.926 OpenCode server listening after 8562ms

Six SDK calls were then issued:

18:14:19.931 GET /provider directory=/Users/moboudra/dev/paseo
18:14:19.931 GET /agent    directory=/Users/moboudra/dev/paseo
18:14:19.931 GET /provider directory=/Users/moboudra
18:14:19.931 GET /agent    directory=/Users/moboudra
18:14:19.931 GET /provider directory=/Users/moboudra/dev/blankpage/editor
18:14:19.936 GET /agent    directory=/Users/moboudra/dev/blankpage/editor

Why six:

Cwd Why that scope exists Model call Mode call
/Users/moboudra home/settings provider snapshot client.provider.list() -> /provider client.app.agents() -> /agent
/Users/moboudra/dev/paseo workspace-scoped provider snapshot for the Paseo workspace client.provider.list() -> /provider client.app.agents() -> /agent
/Users/moboudra/dev/blankpage/editor workspace/agent cwd snapshot for blankpage/editor client.provider.list() -> /provider client.app.agents() -> /agent

Multiple clients can request the same snapshot scope during startup, but non-forced provider loads are deduped by (cwd, provider). Different cwd scopes are separate loads. Three cwd scopes times two OpenCode SDK calls each is the six OpenCode calls in this repro.

Headers arrived before the 30s timeout:

Call Cwd Headers after request
/provider /Users/moboudra 6.462s
/agent /Users/moboudra 6.681s
/agent /Users/moboudra/dev/paseo 6.681s
/provider /Users/moboudra/dev/paseo 8.192s
/provider /Users/moboudra/dev/blankpage 8.654s
/agent /Users/moboudra/dev/blankpage 8.649s

But body consumption and completion lagged:

18:14:29.380 /agent home complete, total app.agents duration 9450ms
18:14:29.813 /agent paseo complete, total app.agents duration 9883ms
18:14:30.263 /agent blankpage timed out at 10s
18:14:31.332 /agent blankpage body finally finished, after the 10s app.agents timeout

18:14:41.687 paseo snapshot outer 30s timeout fires
18:14:41.688 home snapshot outer 30s timeout fires

18:14:43.593 /provider home completes, provider.list duration 23664ms, total listModels 32218ms
18:14:43.798 /provider blankpage completes, provider.list duration 23868ms, total listModels 32411ms
18:14:43.839 /provider paseo completes, provider.list duration 23911ms, total listModels 32476ms

The useful /provider results arrived about 1.9s-2.2s after the snapshot manager had already marked home and paseo as failed.

Why Settings Refresh Works

After the daemon settled, I ran the same refresh path through the daemon on port 51116, using refreshProvidersSnapshot({ providers: ["opencode"] }).

Results:

home refresh:
  total: 2165ms
  status: ready
  models: 409
  modes: 5

/Users/moboudra/dev/paseo refresh:
  total: 1675ms
  status: ready
  models: 409
  modes: 5

/Users/moboudra/dev/blankpage/editor refresh:
  total: 1794ms
  status: ready
  models: 409
  modes: 5

Trace details for the manual-style refresh:

OpenCode server acquisition: 708ms-1291ms
/agent completion: 433ms-592ms after request start
/provider completion: 524ms-618ms after request start

That proves the startup failure is not bad credentials, not a permanently wedged OpenCode install, and not OpenCode generally taking more than 30s. It is startup timing and contention.

Minimal OpenCode-Only Repros

OpenCode Only, No Daemon, No Artificial Load

I started a fresh opencode serve, waited for stdout listening on, then issued the same six HTTP calls concurrently:

GET /provider?directory=/Users/moboudra
GET /agent?directory=/Users/moboudra
GET /provider?directory=/Users/moboudra/dev/paseo
GET /agent?directory=/Users/moboudra/dev/paseo
GET /provider?directory=/Users/moboudra/dev/blankpage/editor
GET /agent?directory=/Users/moboudra/dev/blankpage/editor

Three runs:

Run opencode serve ready All six calls complete
1 1376ms 1295ms
2 906ms 1050ms
3 939ms 898ms

Slowest individual call in those runs:

/provider /Users/moboudra/dev/paseo: 1270ms total
/agent /Users/moboudra/dev/blankpage/editor: 1251ms total

So six concurrent OpenCode calls alone are not the bug.

OpenCode Only Plus External Git Storm, No Daemon

I then ran the same OpenCode-only six-call test while an external shell spawned repeated git commands across the same real workspaces/worktrees. This did not use the Paseo daemon.

Result:

opencode serve ready: 15479ms
all six OpenCode calls complete: 15176ms after server ready
combined cold-start + calls: about 30655ms

Individual calls under the external git storm:

Call Cwd Total
/provider /Users/moboudra 10684ms
/agent /Users/moboudra 10767ms
/provider /Users/moboudra/dev/paseo 13220ms
/agent /Users/moboudra/dev/paseo 13147ms
/provider /Users/moboudra/dev/blankpage/editor 14675ms
/agent /Users/moboudra/dev/blankpage/editor 15038ms

This is the daemon-free minimal evidence that process/filesystem contention can push the same OpenCode cold-start + six-call workload to the same 30s boundary.

Why It Does Not Retry

ProviderSnapshotManager.getSnapshot() only starts background warmup for:

  • no existing snapshot
  • missing providers
  • entries still in loading with no active load

When refresh fails, refreshProvider() stores:

status: "error"
error: "Timed out refreshing OpenCode after 30000ms"

An error entry is not treated as stale/loading by getSnapshot(), so normal reads keep returning the cached error.

Settings refresh calls refresh_providers_snapshot_request, which routes to:

refreshSettingsSnapshot()
clearCachedProviders()
resetSnapshotToLoading()
refreshProviders(... force: true)

That is why you have to force a manual refresh.

Git Work During The Repro

This is not the final optimization report, but it matters for the timeout because it overlaps exactly with OpenCode response handling.

Total git commands in the dev-style copied-home daemon log:

632 spawned
632 closed

Top cwd counts:

Count Cwd
44 /Users/moboudra/.paseo/worktrees/1luy0po7/merry-ladybug
44 /Users/moboudra/.paseo/worktrees/1luy0po7/hopeful-eel
44 /Users/moboudra/.paseo/worktrees/1luy0po7/fix-compaction-cancel-loading
44 /Users/moboudra/.paseo/worktrees/1luy0po7/fix-archive-worktree-session-history
44 /Users/moboudra/.paseo/worktrees/0vpo9h4b/breezy-toad
36 /Users/moboudra/.paseo/worktrees/steering-policy-refactor-detached
36 /Users/moboudra/.paseo/worktrees/1luy0po7/integration-session-mcp-command-stack
36 /Users/moboudra/.paseo/worktrees/1luy0po7/fix-provider-diagnostic-binary-resolution
36 /Users/moboudra/.paseo/worktrees/1luy0po7/feat-voice-runtime-on-demand
36 /Users/moboudra/.paseo/worktrees/1luy0po7/feat-find-in-pane
36 /Users/moboudra/.paseo/worktrees/1luy0po7/epic-paseo-client-sdk
24 /Users/moboudra/dev/paseo
24 /Users/moboudra/dev/blankpage/editor
24 /Users/moboudra/dev/faro/main
24 /Users/moboudra/dev/konbert/web
24 /Users/moboudra/dev/paseo-cloud

In the exact OpenCode pressure window, 18:14:19 through 18:14:43, there were:

142 git command spawns
150 git command closes

The main repeated command shapes were:

76  git rev-parse --show-toplevel
72  git status --porcelain
72  git show-ref --verify --quiet refs/remotes/origin/main
72  git show-ref --verify --quiet refs/heads/main
16  git config --get branch.main.remote
16  git config --get branch.main.merge
16  git rev-list --count main..origin/main
16  git rev-list --count origin/main..main

Original log.txt Alignment

The original startup showed the same home and paseo outer timeout shape:

16:04:22.466 /Users/moboudra/dev/paseo:
  Timed out refreshing OpenCode after 30000ms

16:04:22.482 /Users/moboudra:
  Timed out refreshing OpenCode after 30000ms

The original logs did not include SDK fetch/header/body timing, so they could only show the wrapper-level timeout. The dev-style copied-home reproduction with instrumentation now shows the missing link: the /provider calls completed just after the 30s snapshot budget.

Files Instrumented For Diagnosis

Temporary trace instrumentation was added to:

  • packages/server/src/server/agent/provider-snapshot-manager.ts
  • packages/server/src/server/agent/providers/opencode-agent.ts
  • packages/server/src/server/agent/providers/opencode/runtime.ts
  • packages/server/src/server/agent/providers/opencode/server-manager.ts

The instrumentation is behavior-neutral and only emits trace logs.