dockercompose: fix profiles failing to start (#6322)

[kinland]

This solves the issue I reported in #6322 by adding --profile ___ to the docker compose up command

[kinland]

I am not sure why the TestBuildControllerResourceDepTrumpsInitialBuild test in internal/engine/buildcontroller_test.go failed; when I run the test suite locally, it passes:

Through VSCode:

Click to see log

Running tool: /home/kinland/.asdf/shims/go test -timeout 30s -run ^TestBuildControllerResourceDepTrumpsInitialBuild$ github.com/tilt-dev/tilt/internal/engine

=== RUN   TestBuildControllerResourceDepTrumpsInitialBuild
I0304 21:26:40.835693   14857 handler.go:275] Adding GroupVersion tilt.dev v1alpha1 to ResourceManager
I0304 21:26:40.971714   14857 object_count_tracker.go:151] "StorageObjectCountTracker pruner is exiting"
E0304 21:26:40.971728   14857 writers.go:122] apiserver was unable to write a JSON response: write memu 127.0.0.1:1->1709616400958572760: io: read/write on closed pipe
W0304 21:26:40.971822   14857 reflector.go:462] /home/kinland/repos/tilt/internal/engine/sigs.k8s.io/controller-runtime/pkg/cache/internal/informers.go:105: watch of *v1alpha1.UISession ended with: an error on the server ("unable to decode an event from the watch stream: read memu 1709616400839284084->127.0.0.1:1: EOF") has prevented the request from succeeding
E0304 21:26:40.971841   14857 status.go:71] apiserver received an error that is not an metav1.Status: &net.OpError{Op:"write", Net:"memu", Source:memconn.Addr{Name:"127.0.0.1:1", network:"memu"}, Addr:memconn.Addr{Name:"1709616400958572760", network:"memu"}, Err:(*errors.errorString)(0x61c5a80)}: write memu 127.0.0.1:1->1709616400958572760: io: read/write on closed pipe
E0304 21:26:40.971749   14857 wrap.go:54] timeout or abort while handling: method=GET URI="/apis/tilt.dev/v1alpha1/uiresources" audit-ID="bb927e77-f886-4355-97e0-ac92e3c3b92a"
E0304 21:26:40.971790   14857 writers.go:122] apiserver was unable to write a JSON response: http: Handler timeout
W0304 21:26:40.971916   14857 reflector.go:462] /home/kinland/repos/tilt/internal/engine/sigs.k8s.io/controller-runtime/pkg/cache/internal/informers.go:105: watch of *v1alpha1.ToggleButton ended with: an error on the server ("unable to decode an event from the watch stream: read memu 1709616400841795011->127.0.0.1:1: EOF") has prevented the request from succeeding
W0304 21:26:40.971954   14857 reflector.go:462] /home/kinland/repos/tilt/internal/engine/sigs.k8s.io/controller-runtime/pkg/cache/internal/informers.go:105: watch of *v1alpha1.LiveUpdate ended with: an error on the server ("unable to decode an event from the watch stream: read memu 1709616400841923375->127.0.0.1:1: EOF") has prevented the request from succeeding
W0304 21:26:40.971981   14857 reflector.go:462] /home/kinland/repos/tilt/internal/engine/sigs.k8s.io/controller-runtime/pkg/cache/internal/informers.go:105: watch of *v1alpha1.PodLogStream ended with: an error on the server ("unable to decode an event from the watch stream: read memu 1709616400839197633->127.0.0.1:1: EOF") has prevented the request from succeeding
W0304 21:26:40.971973   14857 reflector.go:462] /home/kinland/repos/tilt/internal/engine/sigs.k8s.io/controller-runtime/pkg/cache/internal/informers.go:105: watch of *v1alpha1.Cmd ended with: an error on the server ("unable to decode an event from the watch stream: read memu 1709616400840084267->127.0.0.1:1: EOF") has prevented the request from succeeding
W0304 21:26:40.971987   14857 reflector.go:462] /home/kinland/repos/tilt/internal/engine/sigs.k8s.io/controller-runtime/pkg/cache/internal/informers.go:105: watch of *v1alpha1.ImageMap ended with: an error on the server ("unable to decode an event from the watch stream: read memu 1709616400841624237->127.0.0.1:1: EOF") has prevented the request from succeeding
W0304 21:26:40.971998   14857 reflector.go:462] /home/kinland/repos/tilt/internal/engine/sigs.k8s.io/controller-runtime/pkg/cache/internal/informers.go:105: watch of *v1alpha1.Cluster ended with: an error on the server ("unable to decode an event from the watch stream: read memu 1709616400839339365->127.0.0.1:1: EOF") has prevented the request from succeeding
W0304 21:26:40.972012   14857 reflector.go:462] /home/kinland/repos/tilt/internal/engine/sigs.k8s.io/controller-runtime/pkg/cache/internal/informers.go:105: watch of *v1alpha1.DockerComposeService ended with: an error on the server ("unable to decode an event from the watch stream: read memu 1709616400842847578->127.0.0.1:1: EOF") has prevented the request from succeeding
W0304 21:26:40.972009   14857 reflector.go:462] /home/kinland/repos/tilt/internal/engine/sigs.k8s.io/controller-runtime/pkg/cache/internal/informers.go:105: watch of *v1alpha1.ConfigMap ended with: an error on the server ("unable to decode an event from the watch stream: read memu 1709616400839954679->127.0.0.1:1: EOF") has prevented the request from succeeding
W0304 21:26:40.971986   14857 reflector.go:462] /home/kinland/repos/tilt/internal/engine/sigs.k8s.io/controller-runtime/pkg/cache/internal/informers.go:105: watch of *v1alpha1.KubernetesApply ended with: an error on the server ("unable to decode an event from the watch stream: read memu 1709616400840926065->127.0.0.1:1: EOF") has prevented the request from succeeding
W0304 21:26:40.972025   14857 reflector.go:462] /home/kinland/repos/tilt/internal/engine/sigs.k8s.io/controller-runtime/pkg/cache/internal/informers.go:105: watch of *v1alpha1.DockerComposeLogStream ended with: an error on the server ("unable to decode an event from the watch stream: read memu 1709616400844163768->127.0.0.1:1: EOF") has prevented the request from succeeding
W0304 21:26:40.972025   14857 reflector.go:462] /home/kinland/repos/tilt/internal/engine/sigs.k8s.io/controller-runtime/pkg/cache/internal/informers.go:105: watch of *v1alpha1.UIResource ended with: an error on the server ("unable to decode an event from the watch stream: read memu 1709616400839290667->127.0.0.1:1: EOF") has prevented the request from succeeding
W0304 21:26:40.972036   14857 reflector.go:462] /home/kinland/repos/tilt/internal/engine/sigs.k8s.io/controller-runtime/pkg/cache/internal/informers.go:105: watch of *v1alpha1.KubernetesDiscovery ended with: an error on the server ("unable to decode an event from the watch stream: read memu 1709616400840358294->127.0.0.1:1: EOF") has prevented the request from succeeding
W0304 21:26:40.972042   14857 reflector.go:462] /home/kinland/repos/tilt/internal/engine/sigs.k8s.io/controller-runtime/pkg/cache/internal/informers.go:105: watch of *v1alpha1.CmdImage ended with: an error on the server ("unable to decode an event from the watch stream: read memu 1709616400839520252->127.0.0.1:1: EOF") has prevented the request from succeeding
W0304 21:26:40.972017   14857 reflector.go:462] /home/kinland/repos/tilt/internal/engine/sigs.k8s.io/controller-runtime/pkg/cache/internal/informers.go:105: watch of *v1alpha1.PortForward ended with: an error on the server ("unable to decode an event from the watch stream: read memu 1709616400838079087->127.0.0.1:1: EOF") has prevented the request from succeeding
W0304 21:26:40.972039   14857 reflector.go:462] /home/kinland/repos/tilt/internal/engine/sigs.k8s.io/controller-runtime/pkg/cache/internal/informers.go:105: watch of *v1alpha1.Extension ended with: an error on the server ("unable to decode an event from the watch stream: read memu 1709616400843181795->127.0.0.1:1: EOF") has prevented the request from succeeding
W0304 21:26:40.972048   14857 reflector.go:462] /home/kinland/repos/tilt/internal/engine/sigs.k8s.io/controller-runtime/pkg/cache/internal/informers.go:105: watch of *v1alpha1.Session ended with: an error on the server ("unable to decode an event from the watch stream: read memu 1709616400842069049->127.0.0.1:1: EOF") has prevented the request from succeeding
W0304 21:26:40.972045   14857 reflector.go:462] /home/kinland/repos/tilt/internal/engine/sigs.k8s.io/controller-runtime/pkg/cache/internal/informers.go:105: watch of *v1alpha1.UIButton ended with: an error on the server ("unable to decode an event from the watch stream: read memu 1709616400841562101->127.0.0.1:1: EOF") has prevented the request from succeeding
W0304 21:26:40.972024   14857 reflector.go:462] /home/kinland/repos/tilt/internal/engine/sigs.k8s.io/controller-runtime/pkg/cache/internal/informers.go:105: watch of *v1alpha1.Tiltfile ended with: an error on the server ("unable to decode an event from the watch stream: read memu 1709616400843169188->127.0.0.1:1: EOF") has prevented the request from succeeding
W0304 21:26:40.972052   14857 reflector.go:462] /home/kinland/repos/tilt/internal/engine/sigs.k8s.io/controller-runtime/pkg/cache/internal/informers.go:105: watch of *v1alpha1.FileWatch ended with: an error on the server ("unable to decode an event from the watch stream: read memu 1709616400841614599->127.0.0.1:1: EOF") has prevented the request from succeeding
--- PASS: TestBuildControllerResourceDepTrumpsInitialBuild (0.15s)
PASS
ok      github.com/tilt-dev/tilt/internal/engine        0.192s

Through gotestsum:

Click to see log

=== RUN   TestBuildControllerResourceDepTrumpsInitialBuild
E0304 21:49:57.403120   63676 finisher.go:175] FinishRequest: post-timeout activity - time-elapsed: 375.794µs, panicked: false, err: <nil>, panic-reason: <nil>
E0304 21:49:57.404125   63676 status.go:71] apiserver received an error that is not an metav1.Status: &errors.errorString{s:"http: Handler timeout"}: http: Handler timeout
E0304 21:49:57.404150   63676 writers.go:135] apiserver was unable to write a fallback JSON response: http: Handler timeout
E0304 21:49:57.404150   63676 status.go:71] apiserver received an error that is not an metav1.Status: &errors.errorString{s:"http: Handler timeout"}: http: Handler timeout
E0304 21:49:57.404156   63676 status.go:71] apiserver received an error that is not an metav1.Status: &errors.errorString{s:"http: Handler timeout"}: http: Handler timeout
E0304 21:49:57.404162   63676 writers.go:135] apiserver was unable to write a fallback JSON response: http: Handler timeout
E0304 21:49:57.405343   63676 writers.go:135] apiserver was unable to write a fallback JSON response: http: Handler timeout
E0304 21:49:57.405389   63676 timeout.go:142] post-timeout activity - time-elapsed: 2.800716ms, GET "/apis/tilt.dev/v1alpha1/podlogstreams/foo-default-foo-fakePodID" result: <nil>
E0304 21:49:57.405410   63676 timeout.go:142] post-timeout activity - time-elapsed: 2.652416ms, PUT "/apis/tilt.dev/v1alpha1/sessions/Tiltfile/status" result: <nil>
E0304 21:49:57.405424   63676 timeout.go:142] post-timeout activity - time-elapsed: 2.826881ms, GET "/apis/tilt.dev/v1alpha1/uiresources" result: <nil>
E0304 21:49:57.405528   63676 writers.go:135] apiserver was unable to write a fallback JSON response: http: Handler timeout
E0304 21:49:57.406675   63676 timeout.go:142] post-timeout activity - time-elapsed: 4.073803ms, GET "/apis/tilt.dev/v1alpha1/filewatches/image:gcr.io_some-project-162817_sancho" result: <nil>
I0304 21:49:57.411382   63676 handler.go:275] Adding GroupVersion tilt.dev v1alpha1 to ResourceManager
I0304 21:49:57.540116   63676 object_count_tracker.go:151] "StorageObjectCountTracker pruner is exiting"
W0304 21:49:57.540124   63676 reflector.go:462] sigs.k8s.io/controller-runtime/pkg/cache/internal/informers.go:105: watch of *v1alpha1.DockerComposeService ended with: an error on the server ("unable to decode an event from the watch stream: read memu 1709617797414754661->127.0.0.1:1: EOF") has prevented the request from succeeding
W0304 21:49:57.540225   63676 reflector.go:462] sigs.k8s.io/controller-runtime/pkg/cache/internal/informers.go:105: watch of *v1alpha1.Tiltfile ended with: an error on the server ("unable to decode an event from the watch stream: read memu 1709617797413338021->127.0.0.1:1: EOF") has prevented the request from succeeding
--- PASS: TestBuildControllerResourceDepTrumpsInitialBuild (0.14s)

I considered that perhaps the issue is that your CircleCI system is using an older version of Docker that contains bugs related to the profiles feature.

I looked at where docker was running in the log, and did this locally:

$ docker version                                                                                                                                                                                                                                        Client:
 Cloud integration: v1.0.35+desktop.10
 Version:           25.0.3
 API version:       1.44
 Go version:        go1.21.6
 Git commit:        4debf41
 Built:             Tue Feb  6 21:13:00 2024
 OS/Arch:           linux/amd64
 Context:           default

and then through the image CircleCI is using:

$  docker run --rm --entrypoint docker docker/tilt-ci@sha256:dc3b3adf081a326a0b5a036e2490acecb1643412f0bdbe0e6ed5ce13521b7f93 version                                                                                                                   
Client: Docker Engine - Community
 Version:           20.10.23
 API version:       1.41
 Go version:        go1.18.10
 Git commit:        7155243
 Built:             Thu Jan 19 17:45:08 2023
 OS/Arch:           linux/amd64
 Context:           default
 Experimental:      true

I installed Docker Desktop 4.18.0, which has 20.10.24 (the closest that winget had - not sure why 4.17.0 is not in the version database, which would have had docker 20.10.23.)

Once I had installed that version of docker, I tried running again, and that still worked...

Through VSCode:

Click to see log

Running tool: /home/kinland/.asdf/shims/go test -timeout 30s -run ^TestBuildControllerResourceDepTrumpsInitialBuild$ github.com/tilt-dev/tilt/internal/engine

=== RUN   TestBuildControllerResourceDepTrumpsInitialBuild
I0304 22:13:20.205400   76237 handler.go:275] Adding GroupVersion tilt.dev v1alpha1 to ResourceManager
I0304 22:13:20.337061   76237 object_count_tracker.go:151] "StorageObjectCountTracker pruner is exiting"
E0304 22:13:20.337272   76237 writers.go:122] apiserver was unable to write a JSON response: http: Handler timeout
E0304 22:13:20.337364   76237 status.go:71] apiserver received an error that is not an metav1.Status: &errors.errorString{s:"http: Handler timeout"}: http: Handler timeout
W0304 22:13:20.337394   76237 reflector.go:462] /home/kinland/repos/tilt/internal/engine/sigs.k8s.io/controller-runtime/pkg/cache/internal/informers.go:105: watch of *v1alpha1.Cmd ended with: an error on the server ("unable to decode an event from the watch stream: read memu 1709619200208751866->127.0.0.1:1: EOF") has prevented the request from succeeding
W0304 22:13:20.337396   76237 reflector.go:462] /home/kinland/repos/tilt/internal/engine/sigs.k8s.io/controller-runtime/pkg/cache/internal/informers.go:105: watch of *v1alpha1.KubernetesApply ended with: an error on the server ("unable to decode an event from the watch stream: read memu 1709619200209613939->127.0.0.1:1: EOF") has prevented the request from succeeding
--- PASS: TestBuildControllerResourceDepTrumpsInitialBuild (0.14s)
E0304 22:13:20.337404   76237 finisher.go:175] FinishRequest: post-timeout activity - time-elapsed: 4.448µs, panicked: false, err: context canceled, panic-reason: <nil>
PASS
W0304 22:13:20.337412   76237 reflector.go:462] /home/kinland/repos/tilt/internal/engine/sigs.k8s.io/controller-runtime/pkg/cache/internal/informers.go:105: watch of *v1alpha1.ToggleButton ended with: an error on the server ("unable to decode an event from the watch stream: read memu 1709619200208912244->127.0.0.1:1: EOF") has prevented the request from succeeding
W0304 22:13:20.337468   76237 reflector.go:462] /home/kinland/repos/tilt/internal/engine/sigs.k8s.io/controller-runtime/pkg/cache/internal/informers.go:105: watch of *v1alpha1.CmdImage ended with: an error on the server ("unable to decode an event from the watch stream: read memu 1709619200208974933->127.0.0.1:1: EOF") has prevented the request from succeeding
ok      github.com/tilt-dev/tilt/internal/engine        0.187s

And through gotestsum:

Click to see log

=== RUN   TestBuildControllerResourceDepTrumpsInitialBuild
E0304 22:15:38.427557   83940 writers.go:122] apiserver was unable to write a JSON response: http: Handler timeout
E0304 22:15:38.428681   83940 status.go:71] apiserver received an error that is not an metav1.Status: &errors.errorString{s:"http: Handler timeout"}: http: Handler timeout
E0304 22:15:38.428707   83940 writers.go:135] apiserver was unable to write a fallback JSON response: http: Handler timeout
E0304 22:15:38.428711   83940 writers.go:135] apiserver was unable to write a fallback JSON response: http: Handler timeout
E0304 22:15:38.428730   83940 status.go:71] apiserver received an error that is not an metav1.Status: &errors.errorString{s:"http: Handler timeout"}: http: Handler timeout
E0304 22:15:38.429737   83940 writers.go:135] apiserver was unable to write a fallback JSON response: http: Handler timeout
E0304 22:15:38.429785   83940 timeout.go:142] post-timeout activity - time-elapsed: 2.561085ms, GET "/apis/tilt.dev/v1alpha1/uiresources" result: <nil>
E0304 22:15:38.429801   83940 timeout.go:142] post-timeout activity - time-elapsed: 2.460543ms, GET "/apis/tilt.dev/v1alpha1/filewatches/image:gcr.io_some-project-162817_sancho" result: <nil>
E0304 22:15:38.429832   83940 timeout.go:142] post-timeout activity - time-elapsed: 2.614329ms, GET "/apis/tilt.dev/v1alpha1/uisessions/Tiltfile" result: <nil>
I0304 22:15:38.435288   83940 handler.go:275] Adding GroupVersion tilt.dev v1alpha1 to ResourceManager
I0304 22:15:38.560857   83940 object_count_tracker.go:151] "StorageObjectCountTracker pruner is exiting"
E0304 22:15:38.560929   83940 wrap.go:54] timeout or abort while handling: method=GET URI="/apis/tilt.dev/v1alpha1/uisessions/Tiltfile" audit-ID="eadb2b2d-6335-4831-ac1d-2d2e0441da9e"
E0304 22:15:38.560943   83940 timeout.go:142] post-timeout activity - time-elapsed: 1.111µs, GET "/apis/tilt.dev/v1alpha1/uisessions/Tiltfile" result: <nil>
E0304 22:15:38.560961   83940 wrap.go:54] timeout or abort while handling: method=PUT URI="/apis/tilt.dev/v1alpha1/uiresources/foo/status" audit-ID="acb7dbc3-3247-4871-8d2d-f71825ead7d8"
E0304 22:15:38.560968   83940 finisher.go:175] FinishRequest: post-timeout activity - time-elapsed: 14.011µs, panicked: false, err: <nil>, panic-reason: <nil>
E0304 22:15:38.560972   83940 timeout.go:142] post-timeout activity - time-elapsed: 648ns, PUT "/apis/tilt.dev/v1alpha1/uiresources/foo/status" result: <nil>
E0304 22:15:38.561143   83940 writers.go:122] apiserver was unable to write a JSON response: http: Handler timeout
E0304 22:15:38.561164   83940 finisher.go:175] FinishRequest: post-timeout activity - time-elapsed: 2.33µs, panicked: false, err: <nil>, panic-reason: <nil>
--- PASS: TestBuildControllerResourceDepTrumpsInitialBuild (0.13s)

I also tried the same with Docker Desktop 4.16.3, but it passed there, too. So while it is possible the docker version was the culprit, I can't confirm that, as I am running on a different platform (running from within WSL2).

[nicks]

i think it was just a flaky test. LGTM!