Skip to content

Flaky: GetConfigAsync at the server working directory times out (60 s) on Windows CI #333

Open

Description

@Blind-Striker

ProjectConfigurationIsolationLiveTests.GetConfigAsync_Should_Load_Nothing_From_Above_The_Server_Working_Directory timed out after its 60 s [Timeout] on Windows CI, on both net10.0 and net11.0 in the same run (PR #327 head a91e99f, run 38778882547, job "Build & Test (Windows)"). Every other test passed (+2493/x1 per TFM). The PR changes only a static grep test, so the failure is not caused by its diff.

What the test does. It creates a client with the location set to the pinned server's working directory (the CLI package inside the upstream checkout) and calls Config.GetConfigAsync. The request was still in flight when the timeout fired: the stack shows Pipeline.ExecuteCoreAsync waiting on the socket, and then the cancelled read (IOException: Unable to read data from the transport connection).

Hypothesis to check, not yet a finding. This is the first request to that location in the run. On upstream, the first request to a location starts its activation, which loads plugins. model.list/model.default cap that wait at 5 s and answer 503 (#311). config.get may wait on the same activation without that cap, and on a cold Windows runner the activation may take longer than 60 s. A long wait on both TFMs at once fits a server-side cause rather than a client-side one.

Earlier occurrences. None found in the last 15 failed CI runs.

Next. Find out where the time goes: the server log for that location, and whether config.get awaits location activation at the pin. Fix at the root; no timeout widening and no retry (testing-style). This flake gets a record before #327's Windows job is rerun.

Activity

  1. Blind-Striker commented on Oct 15, 2026

    @Blind-Striker
    CollaboratorAuthor

    Findings so far (Platform; no fix yet)

    The failure. Windows CI, run 38778882547 (attempt 1), GetConfigAsync_Should_Load_Nothing_From_Above_The_Server_Working_Directory:

    TFM Start Duration
    net11.0 17:46:15.7Z 63.6 s
    net10.0 17:46:21.4Z 60.3 s
    • The two runs were in two separate test hosts with two separate owned servers, and their hangs overlapped.
    • The bound is the test's own [Timeout(60_000)].
    • The server diagnostics show the client blocked reading the response (IOException/SocketException, I/O aborted when the timeout cancelled), so the request was sent and never answered.
    • The re-run (attempt 2) passed the same test in 0.21 s and 0.16 s.

    What the timestamps rule out:

    • Fixture start-up counted into the test's timeout. In both hosts the same server had answered the plugin tests milliseconds earlier (ListPluginsAsync… at 17:46:21.43 and 17:46:15.62).
    • A machine-wide stall. No other test in either host was slow in that minute. The tests right after the timeout ran normally on the same servers: GetInfoAsync in 28–128 ms, GetLocationAsync_And_ListProjectsAsync in about 0.3 s.

    Mechanism, from upstream at the pin. config.get itself waits on nothing: config.entries() returns the configs captured when the location was built. It does not wait for plugins; only the model routes and generate.text do. #311's mechanism is therefore not this one, and #311's harness fix does not cover it.

    What the request does wait for is the first build of its location. This test is the first request to …\external\opencode\packages\cli, the server's own working directory and a real git checkout. Every location service is built before any handler runs (core/src/location-services.ts, instance.ts).

    Of that build:

    • Awaited: project resolution, which runs git rev-parse --git-dir --git-common-dir --show-toplevel and git remote get-url origin, then, in some cases, git rev-list --max-parents=0 HEAD or git worktree list (core/src/project.ts:354-397, core/src/git.ts:199-232). It is followed by SQLite writes (busy_timeout 5000 ms per statement) and config load. The git calls run through AppProcess.run with no timeout.
    • Forked, not awaited: plugin activation (and any install), MCP, the file watcher (its subscribe has its own 10 s timeout), and VCS.

    Ranked hypotheses:

    1. A git child process on the location-build path stalls. Both servers ran git in the same submodule within six seconds of each other.
    2. The server's event loop is blocked during that build, for example by synchronous SQLite. This is less likely: each server has its own database, and the other tests in the same window were fast.
    3. Native watcher work tying up Bun's worker pool. Speculative.

    Why it cannot be settled from the artifacts. Upstream's own logs, which would show the spawning process lines for git and location services booted … durationMs, go to <runRoot>\data\opencode\log\ and are not uploaded. The fixture keeps only stdout, stderr and the failure metadata, and the server prints its logs to stderr only with OPENCODE_PRINT_LOGS=1.

    Proposed next step (a harness change, for the lead's word). On failure, the pinned fixture copies <runRoot>\data\opencode\log\*.log into the server-diagnostics folder it already uploads, so the next occurrence names the stalled step. A fix waits for that evidence: no retry and no wider bound.

  2. Blind-Striker commented on Oct 15, 2026

    @Blind-Striker
    CollaboratorAuthor

    Evidence capture landed in #345 (abb1139). From now on, a failed pinned-server test on CI uploads the server's own log under server-diagnostics/<assembly>/<id>/server-logs/. That is the newest megabyte of each *.log in the server's data root, at most the eight newest files, and nothing else from that root. The next occurrence of this timeout will therefore show the spawning process lines for git and whether location services booted … durationMs=… was reached for …\packages\cli. That settles the ranked hypotheses above. This issue stays open, waiting for that evidence; no fix until then.

  3. Blind-Striker commented on Oct 15, 2026

    @Blind-Striker
    CollaboratorAuthor

    Possibly related: #346. A session DELETE in a live test's cleanup got no complete response within 15 s on Windows CI, at 341a63ed, before the capture landed. If the captured server log of the next occurrence of either shows the same stall, they're one root cause.

  4. added this to the 1.0 milestone on Oct 18, 2026
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

No one assigned

    Labels

    bugSomething isn't working

    Type

    No type

    Projects

    No projects

      Relationships

      None yet

      Development

      No branches or pull requests

      Issue actions