Hacktoberfest 2026: the issues maintainers tagged for October, open and beginner-friendly. Browse Hacktoberfest issues

API server: creating an Executable hangs 30-45 s (504) while the log storage restarts its parent resource watcher for Executables

Open
  • Is something wrong?
#286 6 comments 0 reactions 1 assignee View on GitHub

Maintainers usually reply within 1 day

@danegsta is already working on this.

Since Oct 12, 2026.

  • #292 by @danegsta — open

Assessment

Difficulty
4/5
Estimated time
3-5 days
Newbie friendliness
45/100
Issue type
Bug
Clarity
Mostly clear
Activity status
Active
Tech stack
go
Domain
api, backend

Research direction

Start in api/v1/log_storage.go, especially the 30-second watcher restart loop, ls.mutex, and stopWatcher. Reproduce or inspect the macOS timing from the attached start-apiserver logs, then determine what Stop waits for and whether a blocked watcher can stall an unrelated Executable create. Done means the blocking behavior is explained and covered by an appropriate regression check.

Written by the indexing model from the issue text.

Description

Summary

On GitHub-hosted macOS runners, creating an Executable via the API server hangs until the server's own request timeout (HTTP 504 Timeout: request did not complete within requested timeout - context deadline exceeded). In both occurrences, the log storage's periodic restart of its parent resource watcher for Executable (log_storage.go, every 30 s) was stuck at "Stopping old parent resource watcher…" for the whole time, and only completed when the client (Aspire AppHost) disconnected. We could not reproduce it on Windows, where the same restart completes in the same millisecond.

I don't know the root cause. I'm reporting what the logs show in case it is a known problem or the maintainers can tell what Stop waits for.

Environment
  • DCP 0.26.4 (commit 182c961ce6b2f6b23e785d2963a500d1ed65291d, built 2026-09-24), shipped with Aspire 13.6.0 (Aspire.Hosting.Orchestration.osx-x64)
  • GitHub-hosted macos-15-intel runner (public runners; no nested virtualization), Docker 29.8.2 in a Lima 2.2.0 VM (QEMU software emulation, 2 CPUs, 6 GB) as the container runtime. Everything is very slow there: image pulls take 3+ minutes, MySQL initialization 2-3 more.
  • Client: Aspire AppHost started from DistributedApplicationTestingBuilder (integration tests), DCP_DIAGNOSTICS_LOG_LEVEL=debug
  • Not tested with DCP 0.26.5 (Aspire release/13.6 moved to it in microsoft/aspire#20636, which changes concurrency of same-kind mutations; possibly relevant)
What happens

The Aspire AppHost has a MySQL container, three project services (each waits for its own database in that container) and a web frontend project that waits for the three services, so the frontend's Executable is created some time after the services' executables. The AppHost requests log streams for every executable it observes.

Run A Run B
Services' executables started 11:23:07 12:57:37
First log stream requested for them ~11:23:07 12:57:37
Log storage logs Restarting parent resource watcher… (Kind=Executable) 11:23:37.889 (+30 s) 12:58:07.381 (+30 s)
…Stopping old parent resource watcher… 11:23:37.889 12:58:07.382
Frontend Executable create request sent ~11:23:49 12:58:18
Create fails 11:24:09.9 (client timed out after 20 s; server logged Timeout or abort while handling at 11:24:09.908) 12:58:52.8 (HTTP 504 from the API server, about 34 s after the request)
…Old parent resource watcher stopped 11:24:10.865 (33 s later) 12:58:53.616 (46 s later)
…Creating new parent resource watcher… 11:24:10.866 12:58:53.618

In both runs the "stopped" line appears within about a second of the AppHost tearing down its connections (the Context was canceled, closing log stream / Log streaming for resource completed messages, and in run B the API server switching to CleaningResources at 12:58:53.025). So, for as long as the AppHost kept its connections open, the Stop did not return, and the Executable create was stuck behind it. The controller log has no entry at all for the frontend executable during that window, so the create never got past the API server.

Relevant excerpt (run B, start-apiserver log):

12:58:07.381Z  Restarting parent resource watcher...    Kind=usvc-dev.developer.microsoft.com/v1, Kind=Executable
12:58:07.382Z  Stopping old parent resource watcher...  Kind=usvc-dev.developer.microsoft.com/v1, Kind=Executable
               ... nothing for Kind=Executable ...
12:58:53.616Z  Old parent resource watcher stopped      Kind=usvc-dev.developer.microsoft.com/v1, Kind=Executable

During the same period the restarts for Kind=Container complete immediately (14 times in run B, each Stopping / stopped in the same millisecond).

Where I think it is

api/v1/log_storage.go: the restart loop (watcherRestartInterval = 30 * time.Second) takes ls.mutex, then calls stopWatcher(ls.watcher) before creating the new watcher, and its comment says the stop has to come first to avoid a deadlock between delivering a watch event and creating a new watcher (watch set lock in shared vs. exclusive mode). If Stop waits for the watch set lock while some event delivery is blocked (for example on a slow or non-reading watch/log-stream consumer), the exclusive lock request would also block new shared acquisitions, which could explain why an unrelated Executable create stalls. That is a guess based on reading the code, not something I verified.

Why only macOS CI (probably)

On Windows, with the same AppHost shape, the restart completes in the same millisecond and the frontend is created 6 s later without problems (15:17:26.456 Restarting/Stopping/stopped right after the log streams started at 15:16:56, 30 s earlier). On the GitHub macOS runners the services take 30+ s to become healthy and the machine is heavily loaded, so the frontend create lands inside the window. Of the four macOS runs of this AppHost where the watcher problem in microsoft/aspire#20609 was worked around (so that executables were observed at all), two failed this way and two passed. In both passing runs the frontend was created 8-12 s after the services, before the first restart. In a later CI run, five other AppHosts of the same shape (PostgreSQL, RabbitMQ, Valkey, a service-discovery sample and MySQL again) all created their last project 6-12 s after the first ones, and in all of them the 30 s restart of the Executable watcher completed in the same millisecond. So the failures correlate with the last project being created more than 30 s after the first executable, which happens when the services take longer to become healthy on a loaded runner.

Expected behavior

Stop of the old parent watcher should not block unrelated API operations (creates) on the same kind, or at least not for tens of seconds.

Questions
  • Is this known, and is it possibly addressed by DCP 0.26.5?
  • What does Stop wait for here, and is there a log level or diagnostic switch that would show it?
  • Is a 30 s restart of the parent watcher still needed (the comment says it mitigates missed events)?
Related
  • microsoft/aspire#20609 (Aspire's own watches dying after 60 s; the reason these DCP logs became visible, because executables are only observed now)

I attached the relevant excerpt of the start-apiserver log from run B (dcp-apiserver-excerpt-run-b.log). The complete DCP diagnostic logs (start-apiserver and run-controllers, DCP_DIAGNOSTICS_LOG_LEVEL=debug) for both runs can be provided if useful.

dcp-apiserver-excerpt-run-b.log

Dominant language
Go
Stars
191
Forks
26
Avg merge
22h 49m
Merged PRs (30d)
23

Getting set up

Open in Codespaces

Starts the project's dev container in your browser, under your own GitHub account.

First steps

  1. Read the whole issue, then the project's contributing guide.
  2. Comment on the issue to say you are picking it up — it saves two people doing the same work.
  3. Fork the repository and make your change on a branch.
  4. Open a pull request that references the issue number.

More from microsoft/dcp

All issues in microsoft/dcp

Similar issues

More Go issues

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.