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

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 [release/13.6] Update dependencies from microsoft/dcp 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)?

Time	Event
14:28:51-14:28:56	the three services' executables started
14:29:21.910	log storage: `Stopping old parent resource watcher...` (`Kind=Executable`), +30 s
14:29:33.775	frontend `Executable` create request sent
14:30:07.8	client gets HTTP 504 `Timeout: request did not complete within requested timeout - context deadline exceeded` (about 34 s later)
14:30:08.067	`Old parent resource watcher stopped` (46 s after it started)
14:30:08.100	the controller starts the frontend process, 33 ms later

So the create request that the client had already given up on was processed as soon as the stuck stop returned. It was blocked, not lost.

Likely cause: the per-kind mutation lock in 0.26.4

internal/apiserver/ordered_resource_mutation_handler.go in v0.26.4 (withOrderedResourceMutations) takes one mutex per (apiGroup, resource) for every create/update/patch/delete, and holds it for the whole request, including the notification of watchers (see the comment in the file: "Serialize the complete mutation, including watcher notification, on the same boundary"). If one Executable mutation is stuck while notifying a watcher (for example the log storage watcher whose Stop was blocked at the same time), every other Executable mutation queues behind it, including our create. That matches both what we see (create blocked for 30-45 s, Kind=Container unaffected) and the fact that it is released the moment the stuck stop returns.

That middleware is removed in #279 / #281 (tilt-apiserver v0.19.1), which is in v0.26.5 (tagged 2026-09-30). So I expect 0.26.5 to fix this. We have not been able to run on a build that contains 0.26.5 yet: Aspire 13.6.0 ships DCP 0.26.4, and release/13.6 moved to 0.26.5 only recently (microsoft/aspire#20636).

Not specific to macOS. microsoft/aspire#20691 now has a report of the same pattern (resource creation hanging in CreateClusterCustomObjectWithHttpMessagesAsync and hitting the 20 s client timeout) on GitHub-hosted Windows agents with Aspire 13.6.0, which also ship DCP 0.26.4. That report comes from an automated analysis of their CI logs, so treat the details with some care, but it fits the same cause.

This is my reading of the code, not something I could confirm in a debugger. If it is right, blocked creates should be fixed by #281. That does not answer all the questions above, so I would keep this issue open until that is confirmed:

Why does Stop of the old watcher stall in the first place, and why does it only return once the client disconnects? The mutation lock explains why the create waits, not what the stuck Stop / watcher notification is waiting for. If that part is a separate problem, it may still show up as stalled log streaming even without the lock.
Is there a diagnostic that would show what a watcher Stop is waiting on?
Is the periodic 30 s restart of the log storage watcher still needed?

A correction to my earlier comment, and a way to reproduce a blocked mutation using only the DCP API server, without Aspire.

Correction. I expected 0.26.5 (which removes the per-kind mutation lock) to fix this. It does not: I still see blocked creates/updates with DCP 0.26.5 (tilt-apiserver v0.19.1). The goroutine dumps (/debug/pprof/goroutine?debug=2) of a stalled API server show:

one request blocked in filepathREST.Update (or Create) -> WatchSet.notifyWatchers on a [chan send], i.e. it cannot deliver its event to a watcher;
in some dumps, other requests for the same object waiting in keyedMutex.lock (via WatchSet.lockObjectPublication);
a watch response (WatchServer.HandleHTTP) blocked in http2.(*serverConn).writeDataFromHandler, i.e. waiting for HTTP/2 flow-control window of a client that does not read.

So the stall is not caused by the lock that I suspected. It is a watcher that stops reading: the sender in notifyWatchers blocks without a bound, holding the per-object publication lock.

Reproduction with only the API server. Start any Aspire AppHost (it starts DCP) and take server and token from aspire-dcp*/kubeconfig in the temp directory. This script opens a watch on a kind and never reads its response, then keeps patching one object of that kind:

# PowerShell 7. Server and Token: the "server:" and "token:" values in the kubeconfig of a running AppHost (aspire-dcp*/kubeconfig in the temp directory).
param($Server, $Token, $Kind = 'containers')

Add-Type -TypeDefinition 'public static class AcceptAll { public static bool Always(object s, System.Security.Cryptography.X509Certificates.X509Certificate c, System.Security.Cryptography.X509Certificates.X509Chain h, System.Net.Security.SslPolicyErrors e) { return true; } }'
$accept = [Delegate]::CreateDelegate([Net.Security.RemoteCertificateValidationCallback], [AcceptAll].GetMethod('Always'))

function New-Client([TimeSpan] $Timeout) {
    $handler = [Net.Http.SocketsHttpHandler]::new()
    $handler.SslOptions.RemoteCertificateValidationCallback = $accept
    $client = [Net.Http.HttpClient]::new($handler)
    $client.Timeout = $Timeout
    $client.DefaultRequestVersion = [Version]'2.0'
    $client.DefaultVersionPolicy = 'RequestVersionExact'
    $client.DefaultRequestHeaders.Authorization = [Net.Http.Headers.AuthenticationHeaderValue]::new('Bearer', $Token)
    return $client
}

$api = "$Server/apis/usvc-dev.developer.microsoft.com/v1"
$client = New-Client ([TimeSpan]::FromSeconds(15))
$name = ($client.GetStringAsync("$api/$Kind").GetAwaiter().GetResult() | ConvertFrom-Json).items[0].metadata.name

# 1. Open a watch on the kind and never read its response body.
$watchClient = New-Client ([Threading.Timeout]::InfiniteTimeSpan)
$watch = $watchClient.GetAsync("$api/${Kind}?watch=true", 'ResponseHeadersRead').GetAwaiter().GetResult()
"watch opened: HTTP $([int] $watch.StatusCode), body is not read"

# 2. Keep patching one object (each patch produces a MODIFIED event of about 4 KB for the watch).
for ($n = 1; $n -le 100; $n++) {
    $body = [Net.Http.StringContent]::new("{`"metadata`":{`"annotations`":{`"test`":`"$n-$('x' * 4000)`"}}}", [Text.Encoding]::UTF8, 'application/merge-patch+json')
    $stopwatch = [Diagnostics.Stopwatch]::StartNew()
    try {
        $response = $client.PatchAsync("$api/$Kind/$name", $body).GetAwaiter().GetResult()
        "patch $n -> HTTP $([int] $response.StatusCode) in $($stopwatch.ElapsedMilliseconds) ms"
    }
    catch {
        "patch $n -> no response after $($stopwatch.ElapsedMilliseconds) ms"
        break
    }
}

# 3. Close the watch. The server accepts patches again immediately.
$watch.Dispose()
Start-Sleep 3
$body = [Net.Http.StringContent]::new('{"metadata":{"annotations":{"test":"after"}}}', [Text.Encoding]::UTF8, 'application/merge-patch+json')
"patch after closing the watch -> HTTP $([int] $client.PatchAsync("$api/$Kind/$name", $body).GetAwaiter().GetResult().StatusCode)"

Output on Windows with DCP 0.26.5 (-Kind containers; -Kind executables behaves the same, blocking at the 5th patch):

watch opened: HTTP 200, body is not read
patch 1 -> HTTP 200 in 8 ms
...
patch 8 -> HTTP 200 in 1 ms
patch 9 -> no response after 15019 ms
patch after closing the watch -> HTTP 200

While patch 9 hangs, a goroutine dump shows the blocked notifyWatchers send and the write-blocked watch, plus a second request waiting on the same object's lock. Requests for a different kind keep working (GET of another kind answers in 1 ms), and as soon as the unread watch is closed, patching works again. That matches what I saw in CI, where a blocked create was processed right after a client disconnected.

I only tested patching the same object that is being watched; I did not test other objects of the same kind.

What I do not know.

Which client's watch stops reading in the Aspire runs. In the CI runs (GitHub-hosted macOS; the first executables are created more than about 5 minutes after DCP starts, i.e. after the AppHost's 5-minute watch restart), all four failing attempts show the blocked notifyWatchers together with a write-blocked watch in the dumps, while the six passing attempts show neither and created their executables earlier. But a small AppHost that I made to take 5:45 minutes to start did not reproduce it, so I cannot say that a long startup alone is enough. Whether the unread watch belongs to the AppHost, to a DCP controller or to something else is unconfirmed; I cannot tell that from the stacks.
Whether this is intended. A single watcher that stops reading blocking mutations of its kind without any limit looks risky to me, but I do not know the design intent of the filepath storage in tilt-apiserver. If the answer is that watchers must always read, then the fix is on the client side, and the repro above is still useful to confirm that.

My assumption is that this is a side effect/regression from the fix in tilt-apiserver. The fix specifically adds synchronization to watch events to ensure that they can't be emitted out of order, but that means that an event must be delivered before the next can be sent.

Previously there was no guarantee one event had been added before then next was sent, which means the reason this worked before was probably down to accumulating goroutines all waiting to write an event to an 8 item buffered channel that the events are read from. Adding in synchronization means the ninth unsent event blocks subsequent processing once the channel is full.

I'll take a look this weekend to see how close to the mark I am and what could be done in tilt to work around the problem without resorting back to risking out-of-order event delivery. Ideally watchers should read, but they probably shouldn't deadlock the server if they don't.

I pretty much confirmed this is a pre-existing bug in tilt-apiserver that was previously less common simply because goroutines were allowed to accumulate. The synchronization effectively prevents that. I'll put together a PR for a proper slow consumer policy that can queue updates and force disconnect a watcher that falls too far behind.

Thanks, that matches what I measured. In my repro the 9th patch on containers is the first one that hangs, which fits an 8-slot channel that is no longer drained.

One data point on which watcher stops reading in the Aspire runs, since that is what triggers this. I have goroutine dumps (/debug/pprof/goroutine?debug=2, every 10 s) of four stalled runs on DCP 0.26.5, and of healthy runs of the same tests. In all four stalled runs:

exactly one watch response is blocked in http2.(*serverConn).writeDataFromHandler, and one Update/Create is blocked in WatchSet.notifyWatchers [chan send];
the sockets to the API server have empty Recv-Q/Send-Q for the whole stall, so the client process is alive and the stall is HTTP/2 flow control, not TCP;
the blocked watch is on the connection with 7 or 8 watches. The API server sees three client connections. In healthy runs they carry 17 watches (the DCP controllers), 5 (the AppHost, one for each kind it watches) and 1. lsof shows the AppHost process has exactly one connection to the API server. So in the stalled runs the AppHost's connection carried 2 or 3 more watches than the 5 it opens. That attribution is inferred from the watch counts per connection, not from a process ID per goroutine.

The extra watches show up after the AppHost's periodic 5-minute watch restart: apiserver_longrunning_requests for executables and containerexecs is one higher than before the restart. Healthy runs here never reach that point, because they finish within about three minutes.

So I do not see DCP's own watchers (as in #292) as the stalled consumer in these runs; it is on the Aspire side, and I do not know yet why those watches are not read or closed. A small AppHost with a resource that takes 5:45 minutes to become healthy did not reproduce it, so something else is needed on top of that.

For the fix in tilt-dev/tilt-apiserver#117: evicting a watcher whose queue is full should be survivable for the AppHost, because it restarts a watch whose stream ends.

Bart Koelman (@bart-vmware)

Bart Koelman (@bart-vmware) I based the tilt-apiserver fix on how the official Kubernetes watcher implementation deals with slow connections, so there's at least some prior art.

I'm working on a PR for the slow watchers in the AppHost; there's a bug in the C# KibernetesClient library that's contributing, so I'm having to implement our own watcher registration to ensure the connection is closed completely when we release a watcher.

Keep DCP watches draining and close abandoned connections (#20972)

A correction to my earlier comment here, based on newer data. I wrote that the extra watches on the AppHost's connection appear after its periodic 5-minute watch restart. That is not what I see. They appear in steps of 60 seconds from the start of the watches, while a kind has no objects. In one failing run (DCP 0.26.5, Aspire 13.6.1), measured from the start of the watches, the AppHost's connection carried 5 watches, then 7 at about 65 s, 9 at about 125 s and 10 at about 185 s, and the extra ones were executables and containerexecs, the kinds that had no objects yet. That points to the 60-second per-attempt timeout of the AppHost's watch calls rather than the 5-minute restart.

This is not specific to slow image pulls: a MySQL container needs about 2 minutes to become healthy by itself, so pre-pulling the images does not avoid it. With the API timeouts raised to 8 minutes (via reflection) the AppHost's connection never carried more than 5 watches in 23 consecutive runs of that sample, and without it two consecutive runs failed. The details are in a comment on microsoft/aspire#20609, next to microsoft/aspire#20972.

[release/13.6] Keep DCP watches draining and close abandoned connecti…

This should be fixed in the just released 13.6.3

Navigation Menu

Repository navigation

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

Summary

Environment

What happens

Where I think it is

Why only macOS CI (probably)

Expected behavior

Questions

Related

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

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

Description

Summary

Environment

What happens

Where I think it is

Why only macOS CI (probably)

Expected behavior

Questions

Related

Activity

bart-vmware commented on Oct 2, 2026

aetherxeg-source commented on Oct 2, 2026

bart-vmware commented on Oct 2, 2026

bart-vmware commented on Oct 9, 2026

danegsta commented on Oct 10, 2026

danegsta commented on Oct 10, 2026

bart-vmware commented on Oct 13, 2026

danegsta commented on Oct 13, 2026

bart-vmware commented on Oct 14, 2026

danegsta commented on Oct 22, 2026

Metadata

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Issue actions