perf: cut redundant work out of job setup and teardown (#1218)

Implement speedups to job start and shutdown. - Create the job container while services are still becoming healthy, and poll their health at a flat one second instead of a 2s to 32s doubling backoff - Pull each service image once instead of twice, and fetch a warm action cache once instead of twice - Report the job result before reclaiming its volumes, and reap volumes stranded by a runner that died mid-job | Step | Scenario | Before | After | | --- | --- | --- | --- | | Complete job | Large workspace volume | 4.2s | 0.4s | | Set up job | One service, 2s health interval | 7.08s | 3.26s | | Set up job | Two cached actions from github.com | 1.81s | 1.34s | | Set up job | Two cached actions from gitea.com | 2.42s | 1.95s | | Set up job | Two actions, cold action cache | 6.62s | unchanged | | Set up job | Minimal job, no services or actions | 0.62s | unchanged | Assisted-by: Claude Code:Opus 5 Reviewed-on: https://gitea.com/gitea/runner/pulls/1218 Reviewed-by: bircni <bircni@icloud.com> Co-authored-by: silverwind <me@silverwind.io>
2026-09-21 19:37:07 +02:00 · 2026-09-10 19:00:06 +00:00
parent 498282caaa
commit 54978255f5
11 changed files with 591 additions and 254 deletions
@@ -68,6 +68,7 @@ type RunContext struct {
 	actionInputs        map[string]any // inputs of the composite action this runs, nil for a job
 	Masks               []string
 	cleanUpJobContainer common.Executor
+	deferVolumeCleanup  func(common.Executor)
 	caller              *caller           // job calling this RunContext (reusable workflows)
 	workflowCallInputs  map[string]any    // the caller's with:, resolved once by resolveWorkflowCall
 	workflowCallSecrets map[string]string // the caller's secrets:, resolved once by resolveWorkflowCall
@@ -98,6 +99,7 @@ type RunContext struct {
 	hasBash        *bool // memoized implicit-shell probe, only set on the top-level RunContext
 	jobNetworkName string
 	dockerProxy    *container.DockerProxy
+	hadDockerProxy bool
 	// stepEnv is a copy of the running step's environment, so that workflow commands parsed out
 	// of the container's output can be judged against it. Written by runStepExecutor and read on
 	// the log-writer goroutine, hence unsecureCommandMu, which also guards unsecureCommandErr.
@@ -459,8 +461,15 @@ func printStartJobContainerGroup(ctx context.Context, image, name, network strin
 // newContainer is a variable so tests can substitute a container that needs no Docker daemon.
 var newContainer = container.NewContainer

+type jobVolumeCleanupKey struct{}
+
+func WithJobVolumeCleanup(ctx context.Context, deferCleanup func(common.Executor)) context.Context {
+	return context.WithValue(ctx, jobVolumeCleanupKey{}, deferCleanup)
+}
+
 func (rc *RunContext) startJobContainer() common.Executor {
 	return func(ctx context.Context) error {
+		rc.deferVolumeCleanup, _ = ctx.Value(jobVolumeCleanupKey{}).(func(common.Executor))
 		logger := common.Logger(ctx)
 		image := rc.platformImage
 		logWriter := rc.commandLogWriter(ctx)
@@ -484,7 +493,7 @@ func (rc *RunContext) startJobContainer() common.Executor {
 		// if using service containers, will create a new network for the containers.
 		// and it will be removed after at last.
 		networkName, createAndDeleteNetwork := rc.networkNameForGitea()
-		rc.cleanUpJobContainer = rc.cleanupJobResources(networkName, createAndDeleteNetwork)
+		rc.cleanUpJobContainer = rc.cleanupJobResources(networkName, createAndDeleteNetwork, false)

 		// add service containers
 		for serviceID, spec := range rc.Run.Job().Services {
@@ -610,10 +619,10 @@ func (rc *RunContext) startJobContainer() common.Executor {
 		}
 		defer printStartJobContainerGroup(ctx, image, name, networkName)()
 		if err := common.NewPipelineExecutor(
-			rc.stopJobContainer(),
+			rc.cleanupJobResources(networkName, createAndDeleteNetwork, true),
 			rc.pullServicesImages(rc.Config.ForcePull),
 			rc.JobContainer.Pull(rc.Config.ForcePull),
-		).Finally(rc.closeContainer())(ctx); err != nil {
+		)(ctx); err != nil {
 			return err
 		}
 		rc.startDockerProxy(ctx)
@@ -629,7 +638,7 @@ func (rc *RunContext) startJobContainer() common.Executor {
 				IfBool(createAndDeleteNetwork),
 			rc.startServiceContainers(),
 			rc.reportUnstartedServices(),
-			rc.waitForServiceContainers(),
+			func(ctx context.Context) error { return rc.createJobVolumes(ctx, containerInput.Mounts) },
 			rc.JobContainer.Create(rc.Config.ContainerCapAdd, rc.Config.ContainerCapDrop),
 			rc.JobContainer.Start(false),
 			rc.captureJobContainerInfo(),
@@ -642,6 +651,7 @@ func (rc *RunContext) startJobContainer() common.Executor {
 				Mode: 0o666,
 				Body: "",
 			}),
+			rc.waitForServiceContainers(),
 		)(ctx)
 	}
 }
@@ -654,7 +664,7 @@ func (rc *RunContext) commandLogWriter(ctx context.Context) io.Writer {
 	})
 }

-func (rc *RunContext) cleanupJobResources(networkName string, createAndDeleteNetwork bool) common.Executor {
+func (rc *RunContext) cleanupJobResources(networkName string, createAndDeleteNetwork, preclean bool) common.Executor {
 	return func(ctx context.Context) error {
 		logger := common.Logger(ctx)
 		errs := []error{rc.closeDockerProxy(ctx)}
@@ -665,14 +675,13 @@ func (rc *RunContext) cleanupJobResources(networkName string, createAndDeleteNet
 			logger.Infof("Cleaning up services for job %s", rc.JobName)
 			errs = append(errs, rc.stopServiceContainers()(ctx))
 		}
-		if !common.Dryrun(ctx) {
+		if !common.Dryrun(ctx) && (preclean || rc.hadDockerProxy) {
 			errs = append(errs, container.RemoveDockerJobResources(ctx, rc.jobContainerName()))
 		}
-		if rc.JobContainer != nil {
-			name := rc.jobContainerName()
-			errs = append(errs,
-				container.NewDockerVolumeRemoveExecutor(name, false)(ctx),
-				container.NewDockerVolumeRemoveExecutor(name+"-env", false)(ctx))
+		if preclean || rc.deferVolumeCleanup == nil {
+			errs = append(errs, rc.cleanupJobVolumes(ctx))
+		} else {
+			rc.deferVolumeCleanup(rc.cleanupJobVolumes)
 		}
 		if createAndDeleteNetwork {
 			logger.Infof("Cleaning up network for job %s, and network name is: %s", rc.JobName, networkName)
@@ -682,10 +691,34 @@ func (rc *RunContext) cleanupJobResources(networkName string, createAndDeleteNet
 	}
 }

+func (rc *RunContext) createJobVolumes(ctx context.Context, mounts map[string]string) error {
+	runnerUUID := rc.Config.ContainerNetworkCreateOptions.RunnerUUID
+	if runnerUUID == "" || common.Dryrun(ctx) {
+		return nil
+	}
+	name := rc.jobContainerName()
+	volumeNames := []string{name, name + "-env"}
+	if _, ok := mounts[name]; !ok { // the workspace is a bind mount, the env volume is always ours
+		volumeNames = volumeNames[1:]
+	}
+	return container.CreateJobVolumes(ctx, runnerUUID, volumeNames)
+}
+
+func (rc *RunContext) cleanupJobVolumes(ctx context.Context) error {
+	if rc.JobContainer == nil {
+		return nil
+	}
+	name := rc.jobContainerName()
+	return errors.Join(
+		container.NewDockerVolumeRemoveExecutor(name, false)(ctx),
+		container.NewDockerVolumeRemoveExecutor(name+"-env", false)(ctx))
+}
+
 func (rc *RunContext) closeDockerProxy(ctx context.Context) error {
 	if rc.dockerProxy == nil {
 		return nil
 	}
+	rc.hadDockerProxy = true
 	err := rc.dockerProxy.Close(ctx)
 	rc.dockerProxy = nil
 	if err != nil {
@@ -777,7 +810,6 @@ func (rc *RunContext) startServiceContainers() common.Executor {
 		execs := []common.Executor{}
 		for _, svc := range rc.serviceContainers {
 			execs = append(execs, common.NewPipelineExecutor(
-				svc.container.Pull(false),
 				svc.container.Create(rc.Config.ContainerCapAdd, rc.Config.ContainerCapDrop),
 				svc.container.Start(false),
 			))
@@ -803,12 +835,9 @@ func (rc *RunContext) stopServiceContainers() common.Executor {
 	}
 }

-const (
-	defaultServiceReadyTimeout = 5 * time.Minute
-	serviceReadyPollMax        = 32 * time.Second
-)
+const defaultServiceReadyTimeout = 5 * time.Minute

-var serviceReadyPollInterval = 2 * time.Second // a variable so tests need not wait
+const serviceReadyPollInterval = time.Second

 // reportUnstartedServices logs a service that did not start. The steps that need it
 // report it better than the runner can, so the job carries on.
@@ -868,7 +897,7 @@ func (rc *RunContext) waitForServiceContainers() common.Executor {
 // ready at once and one that exited is left to the steps that need it.
 func (svc *serviceContainer) waitUntilHealthy(ctx context.Context, timeout time.Duration) error {
 	rawLogger := common.Logger(ctx).WithField(rawOutputField, true)
-	interval := serviceReadyPollInterval
+	loggedStarting := false

 	ctx, cancel := context.WithTimeout(ctx, timeout)
 	defer cancel()
@@ -898,12 +927,14 @@ func (svc *serviceContainer) waitUntilHealthy(ctx context.Context, timeout time.
 			return nil
 		}

-		rawLogger.Infof("%s service is starting, waiting %d seconds before checking again.", svc.name, int(interval.Seconds()))
+		if !loggedStarting {
+			rawLogger.Infof("%s service is starting.", svc.name)
+			loggedStarting = true
+		}
 		select {
 		case <-ctx.Done(): // reported at the top of the loop
-		case <-time.After(interval):
+		case <-time.After(serviceReadyPollInterval):
 		}
-		interval = min(interval*2, serviceReadyPollMax)
 	}
 }

@@ -7,15 +7,21 @@ package runner
 import (
 	"bytes"
 	"context"
+	"encoding/json/v2"
 	"errors"
 	"fmt"
 	"io"
+	"maps"
+	"net"
 	"net/http"
 	"net/http/httptest"
 	"os"
+	"path/filepath"
 	"runtime"
+	"slices"
 	"strings"
 	"testing"
+	"testing/synctest"
 	"time"

 	"gitea.com/gitea/runner/act/common"
@@ -24,6 +30,7 @@ import (
 	"gitea.dev/actionslib/pkg/exprparser"
 	"gitea.dev/actionslib/pkg/model"
 	"github.com/docker/cli/cli/compose/loader"
+	"github.com/moby/moby/api/types/volume"
 	log "github.com/sirupsen/logrus"
 	assert "github.com/stretchr/testify/assert"
 	"github.com/stretchr/testify/mock"
@@ -240,8 +247,20 @@ func (fakeContainer) Inspect(context.Context) (*container.Info, error) {

 func (fakeContainer) DumpLogs(context.Context) error { return nil }

-// startJobContainerInputs runs startJobContainer against fakeContainer and returns the
-// inputs it built, one per container.
+func fakeDockerDaemon(t *testing.T, handler http.HandlerFunc) {
+	t.Helper()
+	daemon := httptest.NewServer(http.HandlerFunc(func(writer http.ResponseWriter, request *http.Request) {
+		writer.Header().Set("Content-Type", "application/json")
+		if strings.HasSuffix(request.URL.Path, "/_ping") {
+			writer.Header().Set("API-Version", "1.47")
+		} else {
+			handler(writer, request)
+		}
+	}))
+	t.Cleanup(daemon.Close)
+	t.Setenv("DOCKER_HOST", daemon.URL)
+}
+
 func startJobContainerInputs(t *testing.T, workflowYAML string, cfg *Config) []*container.NewContainerInput {
 	t.Helper()
 	workflow, err := model.ReadWorkflow(strings.NewReader(workflowYAML))
@@ -282,6 +301,8 @@ func startJobContainerInputs(t *testing.T, workflowYAML string, cfg *Config) []*
 			_, _ = io.WriteString(w, "[]")
 		case strings.HasSuffix(r.URL.Path, "/volumes"):
 			_, _ = io.WriteString(w, `{"Volumes":[]}`)
+		case r.Method == http.MethodDelete && strings.Contains(r.URL.Path, "/volumes/"):
+			w.WriteHeader(http.StatusNoContent)
 		case strings.HasSuffix(r.URL.Path, "/info"):
 			_, _ = io.WriteString(w, `{"Architecture":"amd64","OSType":"linux"}`)
 		default:
@@ -647,39 +668,142 @@ func TestCleanupJobResourcesCleansServicesWithoutJobContainer(t *testing.T) {
 		serviceContainers: []*serviceContainer{{name: "svc", container: service}},
 	}

-	err := rc.cleanupJobResources("external-network", false)(common.WithDryrun(t.Context(), true))
+	err := rc.cleanupJobResources("external-network", false, true)(common.WithDryrun(t.Context(), true))
 	require.NoError(t, err)
 	service.AssertExpectations(t)
 }

-// cleanup used to bail out on a previous step's error and on a cancelled context
-func TestCleanupJobResourcesContinuesAfterFailure(t *testing.T) {
-	t.Setenv("DOCKER_HOST", "unix:///nonexistent.sock")
-
-	removeError, closeError := errors.New("remove service"), errors.New("close service")
-	jobContainer := &containerMock{}
-	jobContainer.On("Remove").Return(func(context.Context) error { return errors.New("removal failed") }).Once()
-	service := &containerMock{}
-	service.On("Remove").Return(func(context.Context) error { return removeError }).Once()
-	service.On("Close").Return(func(context.Context) error { return closeError }).Once()
-
+func TestCleanupJobVolumesReapsAbandonedDeferredCleanup(t *testing.T) {
+	now := time.Date(2026, time.September, 10, 12, 0, 0, 0, time.UTC)
 	rc := &RunContext{
-		Name:              "job",
-		Config:            &Config{},
-		Run:               &model.Run{Workflow: &model.Workflow{Name: "wf"}, JobID: "job"},
-		JobContainer:      jobContainer,
-		serviceContainers: []*serviceContainer{{name: "svc", container: service}},
+		Config:       &Config{ContainerNetworkCreateOptions: container.NewDockerNetworkCreateExecutorInput{RunnerUUID: "runner-1"}},
+		Run:          &model.Run{Workflow: &model.Workflow{Name: "workflow"}, JobID: "job"},
+		JobContainer: fakeContainer{},
 	}
+	volumes := map[string]volume.Volume{}
+	fakeDockerDaemon(t, func(writer http.ResponseWriter, request *http.Request) {
+		path := strings.TrimPrefix(request.URL.Path, "/v1.47")
+		switch {
+		case path == "/volumes/create":
+			options := volume.Volume{CreatedAt: now.Format(time.RFC3339)}
+			assert.NoError(t, json.UnmarshalRead(request.Body, &options))
+			volumes[options.Name] = options
+			assert.NoError(t, json.MarshalWrite(writer, volumes[options.Name]))
+		case path == "/volumes":
+			assert.JSONEq(t, `{"label":{"com.gitea.runner.uuid=runner-1":true},"dangling":{"true":true}}`, request.URL.Query().Get("filters"))
+			assert.NoError(t, json.MarshalWrite(writer, map[string]any{"Volumes": slices.Collect(maps.Values(volumes))}))
+		case request.Method == http.MethodDelete:
+			name := strings.TrimPrefix(path, "/volumes/")
+			assert.NotContains(t, []string{"1", "true"}, request.URL.Query().Get("force"))
+			if name == "became-active" || name == "remove-failed" {
+				writer.WriteHeader(http.StatusConflict)
+				_, _ = fmt.Fprintf(writer, `{"message":%q}`, name)
+				return
+			}
+			delete(volumes, name)
+			writer.WriteHeader(http.StatusNoContent)
+		default:
+			t.Errorf("unexpected Docker request: %s %s", request.Method, request.URL)
+		}
+	})
+	name := rc.jobContainerName()
+	require.NoError(t, rc.createJobVolumes(t.Context(), map[string]string{name: "/workspace", name + "-env": "/var/run/act", "shared-cache": "/cache"}))
+	assert.ElementsMatch(t, []string{name, name + "-env"}, slices.Collect(maps.Keys(volumes)))
+	rc.deferVolumeCleanup = func(common.Executor) {}
+	require.NoError(t, rc.cleanupJobResources("", false, false)(t.Context()))
+	require.Len(t, volumes, 2)
+	for _, name := range []string{"became-active", "remove-failed"} {
+		volumes[name] = volume.Volume{Name: name, Labels: volumes[rc.jobContainerName()].Labels, CreatedAt: now.Format(time.RFC3339)}
+	}
+	volumes["foreign"] = volume.Volume{Name: "foreign", Labels: map[string]string{"com.gitea.runner.uuid": "runner-2"}, CreatedAt: now.Format(time.RFC3339)}
+	volumes["fresh"] = volume.Volume{Name: "fresh", Labels: volumes[name].Labels, CreatedAt: now.Add(48 * time.Hour).Format(time.RFC3339)}
+	volumes["unknown-age"] = volume.Volume{Name: "unknown-age", Labels: volumes[name].Labels}
+	err := container.RemoveOrphanJobVolumes(t.Context(), "runner-1", now.Add(24*time.Hour))
+	require.ErrorContains(t, err, "became-active")
+	require.ErrorContains(t, err, "remove-failed")
+	assert.ElementsMatch(t, []string{"became-active", "remove-failed", "foreign", "fresh", "unknown-age"}, slices.Collect(maps.Keys(volumes)))
+}

-	ctx, cancel := context.WithCancel(context.Background())
-	cancel()
-	err := rc.cleanupJobResources("job-network", true)(ctx)
-	require.ErrorContains(t, err, "removal failed")
-	require.ErrorIs(t, err, removeError)
-	require.ErrorIs(t, err, closeError)
-	require.ErrorIs(t, err, context.Canceled)
-	jobContainer.AssertExpectations(t)
-	service.AssertExpectations(t)
+func TestCleanupJobResourcesContinuesAfterFailure(t *testing.T) {
+	t.Setenv("TMPDIR", "/tmp")
+	proxyDir := t.TempDir()
+	for _, name := range []string{"synchronous", "proxy", "closed proxy", "deferred", "preclean deferred", "canceled"} {
+		t.Run(name, func(t *testing.T) {
+			proxy, preclean, deferred := strings.HasSuffix(name, "proxy"), strings.HasPrefix(name, "preclean"), strings.HasSuffix(name, "deferred")
+			if proxy && runtime.GOOS == "windows" {
+				t.Skip("Unix socket ownership is unavailable on Windows")
+			}
+			jobError, removeError, closeError := errors.New("remove job"), errors.New("remove service"), errors.New("close service")
+			job, service := &containerMock{}, &containerMock{}
+			job.On("Remove").Return(func(context.Context) error { return jobError }).Once()
+			service.On("Remove").Return(func(context.Context) error { return removeError }).Once()
+			service.On("Close").Return(func(context.Context) error { return closeError }).Once()
+			rc := &RunContext{
+				Config:            &Config{},
+				Run:               &model.Run{Workflow: &model.Workflow{Name: "wf"}, JobID: "job"},
+				JobContainer:      job,
+				serviceContainers: []*serviceContainer{{name: "svc", container: service}},
+			}
+			var volumeCleanup []common.Executor
+			if deferred {
+				rc.deferVolumeCleanup = func(cleanup common.Executor) { volumeCleanup = append(volumeCleanup, cleanup) }
+			}
+			volumeRemovals := 0
+			fakeDockerDaemon(t, func(writer http.ResponseWriter, request *http.Request) {
+				if request.Method == http.MethodDelete {
+					volumeRemovals++
+				}
+				operation := request.Method + " " + strings.TrimPrefix(request.URL.Path, "/v1.47")
+				if request.URL.Query().Has("filters") {
+					operation = "labelled " + operation
+				}
+				writer.WriteHeader(http.StatusInternalServerError)
+				_, _ = fmt.Fprintf(writer, `{"message":%q}`, operation)
+			})
+			if proxy {
+				listener, err := net.Listen("unix", filepath.Join(proxyDir, "d.sock"))
+				require.NoError(t, err)
+				t.Cleanup(func() { require.NoError(t, listener.Close()) })
+				rc.dockerProxy, err = container.StartDockerProxy(listener.Addr().String(), proxyDir, rc.jobContainerName())
+				require.NoError(t, err)
+				t.Cleanup(func() { require.NoError(t, rc.closeDockerProxy(context.Background())) })
+				if name == "closed proxy" {
+					require.NoError(t, rc.closeDockerProxy(t.Context()))
+				}
+			}
+			ctx, cancel := context.WithCancel(t.Context())
+			defer cancel()
+			if name == "canceled" {
+				cancel()
+			}
+			err := rc.cleanupJobResources("job-network", true, preclean)(ctx)
+			if deferred && !preclean {
+				require.Len(t, volumeCleanup, 1)
+				assert.Zero(t, volumeRemovals)
+				err = errors.Join(err, volumeCleanup[0](ctx))
+			} else {
+				assert.Empty(t, volumeCleanup)
+			}
+			for _, failure := range []error{jobError, removeError, closeError} {
+				require.ErrorIs(t, err, failure)
+			}
+			if name == "canceled" {
+				require.ErrorIs(t, err, context.Canceled)
+			} else {
+				for _, operation := range []string{"DELETE /volumes/" + rc.jobContainerName(), "DELETE /volumes/" + rc.jobContainerName() + "-env", "GET /networks"} {
+					require.ErrorContains(t, err, operation)
+				}
+				assert.Equal(t, 2, volumeRemovals)
+			}
+			assert.Equal(t, proxy || preclean, strings.Contains(err.Error(), "labelled GET /containers/json"))
+			if proxy || preclean {
+				require.ErrorContains(t, err, "labelled GET /networks")
+				require.ErrorContains(t, err, "labelled GET /volumes")
+			}
+			assert.Nil(t, rc.dockerProxy)
+			assert.Equal(t, proxy, rc.hadDockerProxy)
+		})
+	}
 }

 // TestInterpolateOutputsIsPerMatrixCombo guards the matrix-output fix: combinations share one
@@ -1089,65 +1213,96 @@ func TestRunContext_cleanupFailedStart(t *testing.T) {
 	type ctxKey string
 	const sentinel = ctxKey("sentinel")

-	// the fresh context is cancelled via defer on return, so capture state inside the stub
-	type capture struct {
-		calls    int
-		err      error
-		sentinel any
-		cancel   context.CancelFunc
-	}
-	newRC := func(c *capture) *RunContext {
-		return &RunContext{
-			JobName: "job",
-			cleanUpJobContainer: func(ctx context.Context) error {
-				c.calls++
-				if c.cancel != nil {
-					c.cancel()
-				}
+	for name, canceled := range map[string]bool{"cancellation during cleanup": false, "already canceled": true} {
+		t.Run(name, func(t *testing.T) {
+			ctx, cancel := context.WithCancel(context.WithValue(t.Context(), sentinel, "v"))
+			defer cancel()
+			if canceled {
+				cancel()
+			}
+			calls := 0
+			(&RunContext{cleanUpJobContainer: func(ctx context.Context) error {
+				calls++
+				cancel()
 				deadline, ok := ctx.Deadline()
 				require.True(t, ok)
 				assert.WithinDuration(t, time.Now().Add(time.Minute), deadline, time.Second)
-				c.err = ctx.Err()
-				c.sentinel = ctx.Value(sentinel)
+				require.NoError(t, ctx.Err())
+				assert.Equal(t, "v", ctx.Value(sentinel))
 				return nil
-			},
-		}
+			}}).cleanupFailedStart(ctx)
+			assert.Equal(t, 1, calls)
+		})
 	}

-	t.Run("detaches teardown from cancellation during cleanup", func(t *testing.T) {
-		ctx, cancel := context.WithCancel(context.WithValue(context.Background(), sentinel, "v"))
-		defer cancel()
-		c := capture{cancel: cancel}
+	for _, testcase := range []struct {
+		name, health string
+		pullError    error
+	}{
+		{name: "healthy", health: container.HealthHealthy},
+		{name: "unhealthy", health: container.HealthUnhealthy},
+		{name: "pull failure", pullError: errors.New("pull failed")},
+	} {
+		t.Run(testcase.name, func(t *testing.T) {
+			var operations []string
+			record := func(operation string, failure error) func(context.Context) error {
+				return func(context.Context) error {
+					operations = append(operations, operation)
+					return failure
+				}
+			}
+			job, service := &containerMock{}, &containerMock{}
+			for name, instance := range map[string]*containerMock{"job": job, "service": service} {
+				instance.On("Pull", true).Return(record(name+".Pull", map[string]error{"job": testcase.pullError}[name]))
+				instance.On("Create", mock.Anything, mock.Anything).Return(record(name+".Create", nil))
+				instance.On("Start", false).Return(record(name+".Start", nil))
+				instance.On("Remove").Return(record(name+".Remove", nil))
+				instance.On("Close").Return(record(name+".Close", nil))
+			}
+			job.On("Copy", mock.Anything, mock.Anything).Return(record("job.Copy", nil))
+			job.On("Inspect", mock.Anything).Return(&container.Info{ID: "job-id"}, nil).
+				Run(func(mock.Arguments) { operations = append(operations, "job.Inspect") })
+			for _, health := range []string{container.HealthStarting, testcase.health} {
+				service.On("Inspect", mock.Anything).Return(&container.Info{State: "running", Health: health}, nil).
+					Run(func(mock.Arguments) { operations = append(operations, "service.Inspect") }).Once()
+			}
+			service.On("DumpLogs", mock.Anything).Return(nil).
+				Run(func(mock.Arguments) { operations = append(operations, "service.DumpLogs") })
+			origNewContainer := newContainer
+			newContainer = func(input *container.NewContainerInput) container.ExecutionsEnvironment {
+				return map[string]*containerMock{"postgres:latest": service, "node:20": job}[input.Image]
+			}
+			t.Cleanup(func() { newContainer = origNewContainer })
+			workflow, err := model.ReadWorkflow(strings.NewReader("jobs: {job: {services: {postgres: {image: postgres:latest}}}}"))
+			require.NoError(t, err)
+			rc := &RunContext{
+				Config:        &Config{ForcePull: true, ContainerNetworkMode: "host", Workdir: "/workspace"},
+				Run:           &model.Run{JobID: "job", Workflow: workflow},
+				platformImage: "node:20",
+			}
+			ctx := common.WithDryrun(t.Context(), true)
+			rc.ExprEval = rc.NewExpressionEvaluator(ctx)
+			err = rc.startContainer().Then(rc.stopContainer()).Finally(rc.closeContainer())(ctx)
+			want := "job.Remove service.Remove service.Close service.Pull job.Pull"
+			if testcase.pullError != nil {
+				require.ErrorIs(t, err, testcase.pullError)
+			} else {
+				want += " service.Create service.Start service.Inspect job.Create job.Start job.Inspect job.Copy service.Inspect"
+				if testcase.health == container.HealthUnhealthy {
+					require.ErrorContains(t, err, "the service 'postgres' is unhealthy")
+					want += " service.DumpLogs"
+				} else {
+					require.NoError(t, err)
+				}
+			}
+			assert.Equal(t, strings.Fields(want+" job.Remove service.Remove service.Close job.Close"), operations)
+		})
+	}

-		newRC(&c).cleanupFailedStart(ctx)
-
-		assert.Equal(t, 1, c.calls)
-		require.NoError(t, c.err)
-		assert.Equal(t, "v", c.sentinel)
-	})
-
-	t.Run("falls back to a fresh context when the input is done", func(t *testing.T) {
-		var c capture
-		ctx, cancel := context.WithCancel(context.WithValue(context.Background(), sentinel, "v"))
-		cancel()
-
-		newRC(&c).cleanupFailedStart(ctx)
-
-		assert.Equal(t, 1, c.calls)
-		require.NoError(t, c.err)
-		assert.Equal(t, "v", c.sentinel)
-	})
-
-	t.Run("no-op when there is nothing to clean up", func(t *testing.T) {
-		assert.NotPanics(t, func() { (&RunContext{}).cleanupFailedStart(context.Background()) })
-	})
+	(&RunContext{}).cleanupFailedStart(t.Context())
 }

 func TestWaitForServiceContainers(t *testing.T) {
-	origInterval := serviceReadyPollInterval
-	serviceReadyPollInterval = time.Millisecond
-	defer func() { serviceReadyPollInterval = origInterval }()
-
 	newRunContext := func(timeout time.Duration, services ...*serviceContainer) *RunContext {
 		return &RunContext{
 			Config:            &Config{ServiceReadyTimeout: timeout},
@@ -1165,16 +1320,26 @@ func TestWaitForServiceContainers(t *testing.T) {
 		service.AssertExpectations(t)
 	})

-	t.Run("waits while a service is still starting", func(t *testing.T) {
-		service := &containerMock{}
-		service.On("Inspect", mock.Anything).
-			Return(&container.Info{ID: "id", State: "running", Health: container.HealthStarting}, nil).Twice()
-		service.On("Inspect", mock.Anything).
-			Return(&container.Info{ID: "id", State: "running", Health: container.HealthHealthy}, nil).Once()
+	t.Run("polls at a fixed interval and logs starting only once", func(t *testing.T) {
+		synctest.Test(t, func(t *testing.T) {
+			var pollTimes []time.Duration
+			started := time.Now()
+			service := &containerMock{}
+			service.On("Inspect", mock.Anything).
+				Run(func(_ mock.Arguments) { pollTimes = append(pollTimes, time.Since(started)) }).
+				Return(&container.Info{ID: "id", State: "running", Health: container.HealthStarting}, nil).Twice()
+			service.On("Inspect", mock.Anything).
+				Run(func(_ mock.Arguments) { pollTimes = append(pollTimes, time.Since(started)) }).
+				Return(&container.Info{ID: "id", State: "running", Health: container.HealthHealthy}, nil).Once()

-		rc := newRunContext(0, &serviceContainer{name: "postgres", container: service})
-		require.NoError(t, rc.waitForServiceContainers()(context.Background()))
-		service.AssertExpectations(t)
+			var output bytes.Buffer
+			logger := log.New()
+			logger.SetOutput(&output)
+			require.NoError(t, newRunContext(0, &serviceContainer{name: "postgres", container: service}).waitForServiceContainers()(common.WithLogger(t.Context(), logger.WithFields(nil))))
+			assert.Equal(t, []time.Duration{0, time.Second, 2 * time.Second}, pollTimes)
+			assert.Equal(t, 1, strings.Count(output.String(), "postgres service is starting."))
+			assert.Contains(t, output.String(), "postgres service is healthy.")
+		})
 	})

 	t.Run("fails with the probe output when a service is unhealthy", func(t *testing.T) {