diff --git a/pkg/compose/create.go b/pkg/compose/create.go index 01cc3aacc7..1d2add52b5 100644 --- a/pkg/compose/create.go +++ b/pkg/compose/create.go @@ -71,6 +71,28 @@ func (s *composeService) Create(ctx context.Context, project *types.Project, opt } func (s *composeService) create(ctx context.Context, project *types.Project, options api.CreateOptions) error { + project, observed, plan, err := s.preparePlan(ctx, project, options, ScopeCreate) + if err != nil { + return err + } + + // Emit "Running" events for containers that are already up-to-date, so + // the progress display accounts for containers the plan will not touch. + emitRunningEvents(project, observed, plan, s.events) + + return s.executePlan(ctx, project, observed, plan) +} + +// preparePlan resolves the project model, ensures the resources the plan +// itself doesn't own (images, models, external networks/volumes), observes +// the daemon, and reconciles all of it into a Plan — without creating, +// starting, or otherwise touching a single container, network, or volume. +// create's split from this is pure extraction: callers that need the +// canonical project, the daemon snapshot, or the plan itself before deciding +// how to run it (detached up's single-plan Create+Start, interactive up's +// phase boundary, #14081) call this directly instead of create with a wider +// scope; create itself still just chains ScopeCreate with executePlan. +func (s *composeService) preparePlan(ctx context.Context, project *types.Project, options api.CreateOptions, scope ReconcileScope) (*types.Project, *ObservedState, *Plan, error) { if len(options.Services) == 0 { options.Services = project.ServiceNames() } @@ -82,40 +104,40 @@ func (s *composeService) create(ctx context.Context, project *types.Project, opt err := project.CheckContainerNameUnicity() if err != nil { - return err + return nil, nil, nil, err } err = s.ensureImagesExists(ctx, project, options.Build, options.QuietPull, options.SkipProviders) if err != nil { - return err + return nil, nil, nil, err } err = s.ensureModels(ctx, project, options.QuietPull) if err != nil { - return err + return nil, nil, nil, err } prepareNetworks(project) externalNetworks, err := s.checkExternalNetworks(ctx, project) if err != nil { - return err + return nil, nil, nil, err } prepareVolumes(project) externalVolumes, err := s.checkExternalVolumes(ctx, project) if err != nil { - return err + return nil, nil, nil, err } // Temporary implementation of use_api_socket until we get actual support inside docker engine project, err = s.useAPISocket(project) if err != nil { - return err + return nil, nil, nil, err } observed, err := s.collectObservedState(ctx, project) if err != nil { - return err + return nil, nil, nil, err } observed.setResolvedNetworks(externalNetworks, project) observed.setResolvedVolumes(externalVolumes) @@ -129,16 +151,14 @@ func (s *composeService) create(ctx context.Context, project *types.Project, opt "--remove-orphans flag to clean it up.", observed.orphanNames()) } - plan, err := reconcile(ctx, project, observed, toReconcileOptions(options), s.prompt) + reconcileOptions := toReconcileOptions(options) + reconcileOptions.Scope = scope + plan, err := reconcile(ctx, project, observed, reconcileOptions, s.prompt) if err != nil { - return err + return nil, nil, nil, err } - // Emit "Running" events for containers that are already up-to-date, so - // the progress display accounts for containers the plan will not touch. - emitRunningEvents(project, observed, plan, s.events) - - return s.executePlan(ctx, project, observed, plan) + return project, observed, plan, nil } func prepareNetworks(project *types.Project) { diff --git a/pkg/compose/executor.go b/pkg/compose/executor.go index b9b7cd9bd1..3f3ed85134 100644 --- a/pkg/compose/executor.go +++ b/pkg/compose/executor.go @@ -18,11 +18,14 @@ package compose import ( "context" + "errors" "fmt" "sync" + "time" "github.com/compose-spec/compose-go/v2/types" "golang.org/x/sync/errgroup" + "golang.org/x/sync/semaphore" "github.com/docker/compose/v5/pkg/api" ) @@ -47,6 +50,17 @@ type planExecutor struct { // round-trip per create. containersMu sync.Mutex containersByService map[string]Containers + + // waitTimeout, when non-zero, bounds OpWaitCondition nodes only (see + // executeNode) -- not the rest of the plan, and with its OWN fresh + // window per wait node rather than a single shared deadline counted + // down from before the plan started. up -d --wait-timeout must cap how + // long a dependency's health/completion condition is waited on, the + // same thing start()'s own per-dependency WaitTimeout already does + // today -- without also capping unrelated create/start/hook work, and + // without letting that unrelated work's duration eat into (or exhaust) + // a wait's own budget (docker/compose#14290 review). + waitTimeout time.Duration } // reconciliationContext holds results produced by completed nodes so that downstream @@ -147,67 +161,253 @@ func (exec *planExecutor) run(ctx context.Context, plan *Plan) error { groups := exec.buildGroupTracker(plan) events := exec.compose.events - // Every node's goroutine is dispatched unconditionally, so one waiting on - // a dependency never occupies a concurrency slot -- only the actual - // executeNode call does, via the semaphore below. This also means - // deadlock-freedom no longer depends on plan.Nodes staying topologically - // sorted: a goroutine blocked on <-done[dep.ID] holds no slot for a - // still-pending dependency to be starved on. - eg, ctx := errgroup.WithContext(ctx) - limiter := newOptionalLimiter(exec.compose.maxConcurrency) + rs := &runState{ + done: done, + recordFailure: recordFailure, + failedDependency: failedDependency, + groups: groups, + events: events, + limiter: newOptionalLimiter(exec.compose.maxConcurrency), + } + + var createNodes, startNodes []*PlanNode for _, node := range plan.Nodes { - eg.Go(func() error { - // Wait for all dependencies - for _, dep := range node.DependsOn { - select { - case <-done[dep.ID]: - case <-ctx.Done(): - return ctx.Err() - } - } + if node.Phase == PhaseStart { + startNodes = append(startNodes, node) + } else { + createNodes = append(createNodes, node) + } + } - // A dependency may have just failed without ctx being canceled - // yet (see failures' comment above) -- skip this node exactly - // like a canceled one: no slot acquired, no event emitted, its - // own dependents unblocked with the same failure recorded. - if err := failedDependency(node.DependsOn); err != nil { - // Store the original error, not a wrapped one: this node's own - // dependents look it up the same way, and wrapping it again at - // every hop would compound "dependency failed: " prefixes down - // a multi-node chain (create -> pre_start -> start -> post_start). - recordFailure(node.ID, err) - close(done[node.ID]) - return fmt.Errorf("dependency failed: %w", err) + // A Create-phase node depending on a Start-phase node would deadlock + // forever: runPhase(createNodes, ...) only closes rs.done for nodes in + // createNodes, so runNode's `<-rs.done[dep.ID]` would block on a channel + // nothing ever closes, since the Start phase isn't even dispatched until + // the Create phase this node is blocking returns. Nothing in the + // reconciler should ever produce this edge, but failing fast with a + // clear error beats a silent hang if it ever does. + for _, node := range createNodes { + for _, dep := range node.DependsOn { + if dep.Phase == PhaseStart { + return fmt.Errorf("invalid plan: create-phase node %d depends on start-phase node %d", node.ID, dep.ID) } + } + } - if err := acquireSlot(ctx, limiter); err != nil { - recordFailure(node.ID, err) - close(done[node.ID]) - return err - } - defer releaseSlot(limiter) + // The Create phase is a hard barrier: no Start-phase node is even + // dispatched until every Create-phase node has succeeded. This isn't + // just about not canceling unrelated in-flight Create work on a Start + // failure (phaseCancel already keeps that scoped per phase, see its own + // doc comment) -- it's that a Start-phase node whose own DependsOn + // edges are all satisfied has no reason to wait for a COMPLETELY + // UNRELATED Create-phase node elsewhere in the plan, so without this + // barrier a service could already be starting while a sibling it has no + // relationship with is still being created, or fails. The old + // create()-then-start() sequence never allowed that: the whole create + // phase, project-wide, always finished (or failed, with start() never + // invoked at all) before any dependency wait, or anything else in the + // start phase, even began. Interactive up's attach/printer session + // depends on this too: it takes exclusive hold of the terminal for the + // create phase's own progress display, handing it over to continuous + // container log streaming only once the create phase is entirely done + // -- a Start-phase node's log output interleaving with Create's + // progress bars has nowhere consistent to go. + if err := exec.runPhase(createNodes, rs, newPhaseCancel(ctx)); err != nil { + return err + } + return exec.runPhase(startNodes, rs, newPhaseCancel(ctx)) +} + +// runPhase dispatches every node in nodes concurrently (respecting their own +// DependsOn edges via rs.done, same as a single-phase plan always did) and +// waits for them all to finish. phase is this call's own cancellation scope: +// a node failing here cancels phase.ctx for its siblings in THIS call only, +// never a concurrently-running call for a different phase (not that there +// is one today -- run() calls this sequentially -- but runNode has no way +// to tell, so this still matters if that ever changes). See phaseCancel's +// doc comment for why a node's failure goes through phase.fail instead of +// errgroup.Group's own first-error-wins race. +func (exec *planExecutor) runPhase(nodes []*PlanNode, rs *runState, phase *phaseCancel) error { + defer phase.cancel() + eg := errgroup.Group{} + for _, node := range nodes { + eg.Go(func() error { + return exec.runNode(node, rs, phase) + }) + } + err := eg.Wait() + if phase.err != nil { + return phase.err + } + return err +} - // Emit group start event if this is the first node of a group - groups.onNodeStart(node, events) +// phaseCancel bundles one phase's cancellation context with the bookkeeping +// needed to make exactly one node's failure authoritative for it: fail is +// called by every node in this phase that errors out, but its body -- the +// event emission and the actual ctx cancellation -- runs for only the first +// caller, via once. That single gate point fixes two related races a plain +// "if nodeCtx.Err() == nil" check can't: two genuinely concurrent failures +// in the same phase racing to emit onNodeError (the old errgroup.WithContext +// made this vanishingly unlikely by canceling ctx atomically with recording +// the error; splitting cancellation into our own explicit call reopened the +// window), and errgroup.Group's own first-error-wins race picking a +// cancellation casualty's bare context.Canceled over the actual originating +// error once cancellation starts unblocking siblings (see run()'s use of +// err, set here, instead of eg.Wait()'s own return value). +type phaseCancel struct { + ctx context.Context + cancel context.CancelFunc + once sync.Once + err error +} - err := exec.executeNode(ctx, node) +func newPhaseCancel(parent context.Context) *phaseCancel { + p := &phaseCancel{} + p.ctx, p.cancel = context.WithCancel(parent) + return p +} - if err == nil { - // Emit group done event if this is the last node of a group - groups.onNodeDone(node, events) - } else { - recordFailure(node.ID, err) - if ctx.Err() == nil { - groups.onNodeError(node, events, err) - } - } +// fail registers node's failure as this phase's cause, for the first caller +// only: it emits the group error event and cancels the phase's context. Any +// later caller's err is silently dropped -- by the time it could run, this +// phase is already canceled, so it is never anything but a cancellation +// casualty of the first failure, not a new one of its own. +func (p *phaseCancel) fail(node *PlanNode, events api.EventProcessor, groups *groupTracker, err error) { + p.once.Do(func() { + p.err = err + groups.onNodeError(node, events, err) + p.cancel() + }) +} - close(done[node.ID]) - return err - }) +// runState carries the per-run() state every node's goroutine shares: the +// done-channel per node, dependency-failure bookkeeping, group event +// tracking, and the concurrency limiter. Shared across both phases (built +// once in run(), before either runs) since done/failures must stay visible +// to a Start-phase node depending on a Create-phase one across the barrier +// between them. Split out of run() purely to keep runNode a plain method +// instead of a closure captured in a loop. +type runState struct { + done map[int]chan struct{} + recordFailure func(id int, err error) + failedDependency func(deps []*PlanNode) error + groups *groupTracker + events api.EventProcessor + limiter *semaphore.Weighted +} + +// runNode executes one plan node: waits for its dependencies, skips it if +// one of them failed, then dispatches it and records the outcome. phase is +// the cancellation scope of the runPhase call driving it -- see runPhase and +// phaseCancel's own doc comments. +func (exec *planExecutor) runNode(node *PlanNode, rs *runState, phase *phaseCancel) error { + nodeCtx := phase.ctx + + // Every exit path below must close rs.done[node.ID] exactly once, or a + // dependent blocks on it forever: deferred once here instead of before + // each individual return, so a future added exit path can't reintroduce + // the gap the original dependency-wait early-return had (no reachable + // hang today -- every dependent in the same phase shares this same + // nodeCtx, already canceled by the time it would matter -- but nothing + // enforces that staying true as the plan DAG grows new shapes). + defer close(rs.done[node.ID]) + + // Wait for all dependencies + for _, dep := range node.DependsOn { + select { + case <-rs.done[dep.ID]: + case <-nodeCtx.Done(): + return nodeCtx.Err() + } + } + + // A dependency may have just failed without nodeCtx being canceled yet + // (see run()'s failures comment) -- skip this node exactly like a + // canceled one: no slot acquired, no event emitted, its own dependents + // unblocked with the same failure recorded. + if err := rs.failedDependency(node.DependsOn); err != nil { + // Store the original error, not a wrapped one: this node's own + // dependents look it up the same way, and wrapping it again at + // every hop would compound "dependency failed: " prefixes down a + // multi-node chain (create -> pre_start -> start -> post_start). + rs.recordFailure(node.ID, err) + return fmt.Errorf("dependency failed: %w", err) + } + + if err := acquireSlot(nodeCtx, rs.limiter); err != nil { + rs.recordFailure(node.ID, err) + return err } + defer releaseSlot(rs.limiter) - return eg.Wait() + // Emit group start event if this is the first node of a group + rs.groups.onNodeStart(node, rs.events) + + err := exec.executeNode(nodeCtx, node) + + if err == nil { + // Emit group done event if this is the last node of a group + rs.groups.onNodeDone(node, rs.events) + return nil + } + + rs.recordFailure(node.ID, err) + if nodeCtx.Err() == nil { + // This node's own failure, not an inherited cancellation: a node + // whose nodeCtx is already canceled failed because of that + // cancellation, not a new failure of its own to propagate. phase.fail + // itself gates on being the first such failure in this phase (see its + // doc comment) -- this outer check only spares every later, + // cancellation-casualty caller the cost of building the error-event + // payload it would be dropped anyway. + phase.fail(node, rs.events, rs.groups, err) + } + return err +} + +// errWaitTimeout marks the failure of an OpWaitCondition node whose own +// --wait-timeout window (planExecutor.waitTimeout) expired, as opposed to any +// other DeadlineExceeded that can surface from a plan: an engine call timing +// out, a hook, or an external deadline on the caller's context. Callers that +// translate a wait timeout into a user-facing message key on this rather than +// on DeadlineExceeded, which is not specific to waits. The wrapped error still +// satisfies errors.Is(err, context.DeadlineExceeded). +var errWaitTimeout = errors.New("timeout waiting for dependencies") + +// translateWaitTimeout turns a plan failure caused by a wait node's own +// --wait-timeout window (see errWaitTimeout) into the "timeout waiting for +// dependencies" message the imperative start path always reported for a +// depends_on wait timing out, with or without --wait, and leaves any other +// error as is. It is deliberately not the "application not healthy" message: +// that one belongs to the final --wait readiness check that runs after the +// plan, which has its own translation. +func translateWaitTimeout(err error) error { + if !errors.Is(err, errWaitTimeout) { + return err + } + return errors.New("timeout waiting for dependencies") +} + +// execBoundedWaitCondition runs an OpWaitCondition node under its own fresh +// planExecutor.waitTimeout window, if one is set, and marks a failure caused +// by that window expiring with errWaitTimeout. origCtx.Err() == nil rules out +// an earlier deadline inherited from the caller having fired instead: both +// make the derived context report DeadlineExceeded, but only the former is +// this wait's own timeout. +func (exec *planExecutor) execBoundedWaitCondition(origCtx context.Context, op Operation) error { + ctx := origCtx + if exec.waitTimeout > 0 { + var cancel context.CancelFunc + ctx, cancel = context.WithTimeout(origCtx, exec.waitTimeout) + defer cancel() + } + err := exec.execWaitCondition(ctx, origCtx, op) + if err != nil && exec.waitTimeout > 0 && origCtx.Err() == nil && + errors.Is(ctx.Err(), context.DeadlineExceeded) && errors.Is(err, context.DeadlineExceeded) { + return fmt.Errorf("%w: %w", errWaitTimeout, err) + } + return err } // executeNode dispatches a single plan node to the appropriate API call. @@ -239,7 +439,7 @@ func (exec *planExecutor) executeNode(ctx context.Context, node *PlanNode) error case OpCreateHookContainer: return exec.execCreateHookContainer(ctx, node) case OpWaitCondition: - return exec.execWaitCondition(ctx, op) + return exec.execBoundedWaitCondition(ctx, op) case OpRunPreStart: return exec.execRunPreStart(ctx, op) case OpRunPostStart: diff --git a/pkg/compose/executor_ops.go b/pkg/compose/executor_ops.go index 49921b725f..7c36e909ed 100644 --- a/pkg/compose/executor_ops.go +++ b/pkg/compose/executor_ops.go @@ -219,13 +219,17 @@ func (exec *planExecutor) resolveContainerSummary(op Operation) (container.Summa // warning, not a plan failure — matching waitDependencies' own // optional-dependency handling. // -// Unlike waitDependencies, this applies no deadline of its own: nothing -// produces one yet (no ReconcileOptions field feeds a per-wait timeout the -// way api.CreateOptions.WaitTimeout does today). A future caller needing that -// — e.g. `up --wait` once it runs on the plan — wraps ctx before executing -// the plan, or adds a Timeout to the operation for execWaitCondition to wrap -// here. -func (exec *planExecutor) execWaitCondition(ctx context.Context, op Operation) error { +// Unlike waitDependencies, this has no timeout of its own to apply here -- +// ctx is used exactly as given, already wrapped (or not) by executeNode's +// OpWaitCondition dispatch in executor.go. origCtx is ctx as it stood right +// before that wrap, passed through unchanged to waitDependency, which needs +// it to tell its own wait timeout apart from an inherited deadline (see its +// doc comment). upDetached (up.go) is the caller that needs a timeout here +// at all: planExecutor.waitTimeout gives this node its own fresh per-wait +// window, the same thing start()'s own WaitTimeout already threads through +// every waitDependencies call -- without also bounding unrelated Create or +// Start work the way wrapping the whole plan's ctx would. +func (exec *planExecutor) execWaitCondition(ctx, origCtx context.Context, op Operation) error { s := exec.compose exec.containersMu.Lock() waitingFor := exec.containersByService[op.Name].filter(isNotOneOff, isNotHookContainer) @@ -248,7 +252,8 @@ func (exec *planExecutor) execWaitCondition(ctx context.Context, op Operation) e // itself instead. waitDependency only ever reads this for one // practically unreachable log line (an unsupported depends_on condition, // filtered out before a plan is ever built). - return s.waitDependency(ctx, op.ResourceID, op.Name, config, waitingFor) + // + return s.waitDependency(ctx, origCtx, op.ResourceID, op.Name, config, waitingFor) } // execRunPreStart runs the service's pre_start hooks against the runner @@ -383,5 +388,43 @@ func (exec *planExecutor) execRenameContainer(ctx context.Context, node *PlanNod _, err := exec.compose.apiClient().ContainerRename(ctx, createdID, client.ContainerRenameOptions{ NewName: op.Name, }) - return err + if err != nil { + return err + } + // Update the create node's own result in place rather than publishing a + // separate entry under this node's ID: plannedReplica deliberately keeps + // every start-phase reference (resolveContainerID, groupEventName) + // pointed at CreateNodeID, not at this rename node, so they all see the + // rename take effect without each needing their own case for "was this + // replica's container ever renamed". The ID is unchanged by a rename; + // only the name this node is renaming-TO replaces the create's own + // temporary one. + exec.pctx.set(op.CreateNodeID, operationResult{ContainerID: createdID, ContainerName: op.Name}) + + // execCreateContainer published this container into the live view under + // its temporary name (the only name it had at that point); refresh it in + // place now that the rename landed, or OpWaitCondition and any sibling + // execCreateContainer resolving a service reference keep seeing the + // temporary one for the rest of the plan's execution. + if op.Service != nil { + exec.containersMu.Lock() + found := false + for i, ctr := range exec.containersByService[op.Service.Name] { + if ctr.ID == createdID { + exec.containersByService[op.Service.Name][i].Names = []string{"/" + op.Name} + found = true + break + } + } + exec.containersMu.Unlock() + if !found { + // Shouldn't happen: the DAG guarantees execCreateContainer's + // append ran before this node does. Logged rather than silently + // skipped, so a future regression that breaks that invariant is + // at least visible instead of just quietly serving the + // temporary name downstream again. + logrus.Warnf("execRenameContainer: container %s not found in live view for service %s; dependents may see the stale temporary name", createdID, op.Service.Name) + } + } + return nil } diff --git a/pkg/compose/executor_start_test.go b/pkg/compose/executor_start_test.go index f0c821bc11..2981f4c5b2 100644 --- a/pkg/compose/executor_start_test.go +++ b/pkg/compose/executor_start_test.go @@ -20,9 +20,13 @@ package compose import ( "context" + "errors" + "fmt" "net" "sync" + "sync/atomic" "testing" + "time" "github.com/compose-spec/compose-go/v2/types" "github.com/docker/cli/cli/config/configfile" @@ -80,7 +84,7 @@ func TestExecWaitCondition_RequiredMissingDependencyFails(t *testing.T) { svc, _, _ := newStartPhaseTestService(t) exec := svc.newPlanExecutor(&types.Project{Name: "test"}, emptyObservedState("test"), nil) - err := exec.execWaitCondition(t.Context(), Operation{ + err := exec.execWaitCondition(t.Context(), t.Context(), Operation{ Name: "db", Condition: types.ServiceConditionHealthy, }) @@ -95,7 +99,7 @@ func TestExecWaitCondition_OptionalMissingDependencyIsTolerated(t *testing.T) { svc, _, recorder := newStartPhaseTestService(t) exec := svc.newPlanExecutor(&types.Project{Name: "test"}, emptyObservedState("test"), nil) - err := exec.execWaitCondition(t.Context(), Operation{ + err := exec.execWaitCondition(t.Context(), t.Context(), Operation{ Name: "db", Condition: types.ServiceConditionHealthy, BestEffort: true, @@ -137,7 +141,7 @@ func TestExecWaitCondition_HealthyConditionSatisfied(t *testing.T) { exec := svc.newPlanExecutor(&types.Project{Name: "test"}, observed, nil) exec.containersByService["db"] = Containers{dbSummary} - err := exec.execWaitCondition(t.Context(), Operation{ + err := exec.execWaitCondition(t.Context(), t.Context(), Operation{ Name: "db", Condition: types.ServiceConditionHealthy, }) @@ -145,6 +149,443 @@ func TestExecWaitCondition_HealthyConditionSatisfied(t *testing.T) { assert.DeepEqual(t, recorder.byID["Container test-db-1"], []string{api.StatusWaiting, api.StatusHealthy}) } +// TestExecutePlanWaitConditionRespectsContextDeadline is a regression test +// for a gap a reviewer caught on upDetached (pkg/compose/up.go): the plan's +// own OpWaitCondition nodes have no timeout of their own (unlike the +// imperative engine's waitDependencies, which already threaded WaitTimeout +// through every per-dependency wait, not just the final --wait check) -- +// they rely entirely on whatever ctx they're given (directly, or via +// exec.waitTimeout -- see TestExecutePlanWaitDeadlineOnlyBoundsWaitNodes for +// that path specifically). This drives a real OpWaitCondition node +// (service_healthy, never satisfied) through the full executePlan/run() DAG +// path -- not execWaitCondition in isolation -- under a short deadline on +// the ctx run() itself is given, and asserts it returns promptly with +// ctx.Err(), proving the deadline really does propagate from the caller into +// the plan's blocking nodes. +func TestExecutePlanWaitConditionRespectsContextDeadline(t *testing.T) { + svc, apiClient, _ := newStartPhaseTestService(t) + + dbSummary := container.Summary{ + ID: "db-id", + Names: []string{"/test-db-1"}, + Labels: map[string]string{api.ServiceLabel: "db", api.OneoffLabel: "False"}, + } + apiClient.EXPECT().ContainerInspect(gomock.Any(), "db-id", gomock.Any()).Return(client.ContainerInspectResult{ + Container: container.InspectResponse{ + ID: "db-id", + Name: "/test-db-1", + State: &container.State{ + Status: container.StateRunning, + Health: &container.Health{Status: container.Starting}, + }, + Config: &container.Config{Healthcheck: &container.HealthConfig{Test: []string{"CMD", "true"}}}, + }, + }, nil).AnyTimes() + + plan := &Plan{} + plan.addNode(Operation{ + Type: OpWaitCondition, + ResourceID: "wait:db:service_healthy", + Name: "db", + Condition: types.ServiceConditionHealthy, + }, "") + + exec := svc.newPlanExecutor(&types.Project{Name: "test"}, emptyObservedState("test"), nil) + exec.containersByService["db"] = Containers{dbSummary} + + ctx, cancel := context.WithTimeout(t.Context(), 200*time.Millisecond) + defer cancel() + + start := time.Now() + err := exec.run(ctx, plan) + elapsed := time.Since(start) + + assert.ErrorIs(t, err, context.DeadlineExceeded) + assert.Assert(t, elapsed < 5*time.Second, "execWaitCondition's polling loop did not stop at the deadline (took %s)", elapsed) +} + +// TestExecutePlanWaitDeadlineOnlyBoundsWaitNodes is a regression test for a +// Copilot review finding on #14290: upDetached originally bounded +// --wait-timeout by wrapping the whole run() ctx, which would have also +// capped unrelated Create-phase and Start-phase work (network/container +// creation, hooks) that was never subject to --wait-timeout in the old +// create()+start() sequence. exec.waitTimeout (set by upDetached, consulted +// only in executeNode's OpWaitCondition case) must bound exclusively the +// blocking dependency wait, leaving every other node on the plan's plain, +// deadline-free ctx. This plan pairs a never-satisfied OpWaitCondition with +// an OpCreateNetwork that has no deadline of its own: if waitTimeout leaked +// into the whole run(), the network create would race the same short +// deadline instead of completing normally. +func TestExecutePlanWaitDeadlineOnlyBoundsWaitNodes(t *testing.T) { + svc, apiClient, _ := newStartPhaseTestService(t) + + dbSummary := container.Summary{ + ID: "db-id", + Names: []string{"/test-db-1"}, + Labels: map[string]string{api.ServiceLabel: "db", api.OneoffLabel: "False"}, + } + apiClient.EXPECT().ContainerInspect(gomock.Any(), "db-id", gomock.Any()).Return(client.ContainerInspectResult{ + Container: container.InspectResponse{ + ID: "db-id", + Name: "/test-db-1", + State: &container.State{ + Status: container.StateRunning, + Health: &container.Health{Status: container.Starting}, + }, + Config: &container.Config{Healthcheck: &container.HealthConfig{Test: []string{"CMD", "true"}}}, + }, + }, nil).AnyTimes() + nw := types.NetworkConfig{Name: "test_default"} + // the network create must run on a context with no deadline at all: the + // wait's own window is derived for the OpWaitCondition node only, so a + // deadline showing up here would mean waitTimeout leaked into the plan + var networkCtxHadDeadline atomic.Bool + apiClient.EXPECT().NetworkCreate(gomock.Any(), "test_default", gomock.Any()). + DoAndReturn(func(ctx context.Context, _ string, _ client.NetworkCreateOptions) (client.NetworkCreateResult, error) { + _, has := ctx.Deadline() + networkCtxHadDeadline.Store(has) + return client.NetworkCreateResult{ID: "net-id"}, nil + }) + + plan := &Plan{} + plan.addNode(Operation{ + Type: OpCreateNetwork, + ResourceID: "network:default", + Name: nw.Name, + Network: &nw, + }, "") + plan.addNode(Operation{ + Type: OpWaitCondition, + ResourceID: "wait:db:service_healthy", + Name: "db", + Condition: types.ServiceConditionHealthy, + }, "") + + exec := svc.newPlanExecutor(&types.Project{Name: "test"}, emptyObservedState("test"), nil) + exec.containersByService["db"] = Containers{dbSummary} + exec.waitTimeout = 200 * time.Millisecond + + start := time.Now() + err := exec.run(t.Context(), plan) + elapsed := time.Since(start) + + assert.ErrorIs(t, err, context.DeadlineExceeded) + assert.Assert(t, !networkCtxHadDeadline.Load(), "waitTimeout leaked into a non-wait node's context") + assert.Assert(t, elapsed < 5*time.Second, "waitTimeout did not bound the stuck OpWaitCondition node (took %s)", elapsed) +} + +// TestExecutePlanOptionalWaitDoesNotSwallowInheritedDeadline is a regression +// test for a Copilot review finding on #14290: waitDependency originally +// tolerated any DeadlineExceeded on an optional dependency as long as the +// caller had configured a timeout at all (exec.waitTimeout > 0), regardless +// of whether THIS wait's own timeout, or an earlier deadline inherited from +// the caller's own ctx, was the one that actually fired. Both make +// ctx.Done() report DeadlineExceeded once the earlier of the two elapses, so +// a bare "did I configure a timeout" flag can't tell them apart -- an +// optional dependency would then silently swallow a real external deadline +// (e.g. the process's own context, or a test harness timeout) and report +// success. This plan's single OpWaitCondition node never resolves +// (BestEffort: true) and exec.waitTimeout is set far longer than the ctx +// passed into exec.run, so the INHERITED deadline is always the one that +// fires first: the error must still propagate, not be tolerated as if +// exec.waitTimeout itself had elapsed. +func TestExecutePlanOptionalWaitDoesNotSwallowInheritedDeadline(t *testing.T) { + svc, apiClient, _ := newStartPhaseTestService(t) + + dbSummary := container.Summary{ + ID: "db-id", + Names: []string{"/test-db-1"}, + Labels: map[string]string{api.ServiceLabel: "db", api.OneoffLabel: "False"}, + } + apiClient.EXPECT().ContainerInspect(gomock.Any(), "db-id", gomock.Any()).Return(client.ContainerInspectResult{ + Container: container.InspectResponse{ + ID: "db-id", + Name: "/test-db-1", + State: &container.State{ + Status: container.StateRunning, + Health: &container.Health{Status: container.Starting}, + }, + Config: &container.Config{Healthcheck: &container.HealthConfig{Test: []string{"CMD", "true"}}}, + }, + }, nil).AnyTimes() + + plan := &Plan{} + plan.addNode(Operation{ + Type: OpWaitCondition, + ResourceID: "wait:db:service_healthy", + Name: "db", + Condition: types.ServiceConditionHealthy, + BestEffort: true, + }, "") + + exec := svc.newPlanExecutor(&types.Project{Name: "test"}, emptyObservedState("test"), nil) + exec.containersByService["db"] = Containers{dbSummary} + exec.waitTimeout = 10 * time.Second + + ctx, cancel := context.WithTimeout(t.Context(), 200*time.Millisecond) + defer cancel() + + start := time.Now() + err := exec.run(ctx, plan) + elapsed := time.Since(start) + + assert.ErrorIs(t, err, context.DeadlineExceeded, "an inherited deadline must not be swallowed just because this wait is optional and exec.waitTimeout is set") + assert.Assert(t, elapsed < 5*time.Second, "took too long to fail on the inherited deadline (took %s)", elapsed) +} + +// TestExecutePlanOptionalWaitTimeoutIsToleratedWithoutInheritedDeadline is +// the positive-case counterpart to +// TestExecutePlanOptionalWaitDoesNotSwallowInheritedDeadline: with no +// inherited deadline at all (plain t.Context() passed into exec.run), this +// wait's own exec.waitTimeout elapsing on an optional dependency must still +// be tolerated as before (nil, not an error) -- the origCtx refactor must +// not have turned every DeadlineExceeded into a hard failure. +func TestExecutePlanOptionalWaitTimeoutIsToleratedWithoutInheritedDeadline(t *testing.T) { + svc, apiClient, _ := newStartPhaseTestService(t) + + dbSummary := container.Summary{ + ID: "db-id", + Names: []string{"/test-db-1"}, + Labels: map[string]string{api.ServiceLabel: "db", api.OneoffLabel: "False"}, + } + apiClient.EXPECT().ContainerInspect(gomock.Any(), "db-id", gomock.Any()).Return(client.ContainerInspectResult{ + Container: container.InspectResponse{ + ID: "db-id", + Name: "/test-db-1", + State: &container.State{ + Status: container.StateRunning, + Health: &container.Health{Status: container.Starting}, + }, + Config: &container.Config{Healthcheck: &container.HealthConfig{Test: []string{"CMD", "true"}}}, + }, + }, nil).AnyTimes() + + plan := &Plan{} + plan.addNode(Operation{ + Type: OpWaitCondition, + ResourceID: "wait:db:service_healthy", + Name: "db", + Condition: types.ServiceConditionHealthy, + BestEffort: true, + }, "") + + exec := svc.newPlanExecutor(&types.Project{Name: "test"}, emptyObservedState("test"), nil) + exec.containersByService["db"] = Containers{dbSummary} + exec.waitTimeout = 200 * time.Millisecond + + start := time.Now() + err := exec.run(t.Context(), plan) + elapsed := time.Since(start) + + assert.NilError(t, err, "exec.waitTimeout elapsing on its own, with no inherited deadline, must still be tolerated for an optional dependency") + assert.Assert(t, elapsed < 5*time.Second, "took too long (took %s)", elapsed) +} + +// TestExecutePlanCreatePhaseIsABarrierBeforeStartPhase is a regression test +// for a Copilot review finding on #14291: a Start-phase node's own DependsOn +// edges being satisfied is not enough to let it run -- nothing stopped it +// from starting while a COMPLETELY UNRELATED Create-phase node elsewhere in +// the plan was still in flight (or about to fail), something the old +// create()-then-start() sequence never allowed (the whole create phase, +// project-wide, always finished -- or failed, with start() never invoked at +// all -- before any dependency wait, or anything else in the start phase, +// even began). Interactive up's attach/printer session needs that same +// guarantee: it takes exclusive hold of the terminal for the create phase's +// progress display, handing it to continuous container log streaming only +// once the create phase is entirely done. This pairs a slow, unrelated +// network create (Phase: PhaseCreate, the default, no DependsOn edge to +// anything in the Start phase) with an OpStartContainer node (Phase: +// PhaseStart) and asserts ContainerStart is never called before the network +// create has fully returned. Uses OpStartContainer rather than +// OpWaitCondition deliberately: execWaitCondition's underlying poll loop +// only checks on a 500ms ticker (never on entry), which would make a +// same-order-of-magnitude Create delay pass this assertion even with no +// barrier at all, and so couldn't actually catch a regression here. +func TestExecutePlanCreatePhaseIsABarrierBeforeStartPhase(t *testing.T) { + svc, apiClient := newTestService(t) + + var createDone atomic.Bool + nw := types.NetworkConfig{Name: "test_default"} + apiClient.EXPECT().NetworkCreate(gomock.Any(), "test_default", gomock.Any()). + DoAndReturn(func(context.Context, string, client.NetworkCreateOptions) (client.NetworkCreateResult, error) { + time.Sleep(100 * time.Millisecond) + createDone.Store(true) + return client.NetworkCreateResult{ID: "net-id"}, nil + }) + + apiClient.EXPECT().ContainerStart(gomock.Any(), "db-id", gomock.Any()). + DoAndReturn(func(context.Context, string, client.ContainerStartOptions) (client.ContainerStartResult, error) { + assert.Assert(t, createDone.Load(), "the Start-phase container start began before the unrelated Create-phase network create returned") + return client.ContainerStartResult{}, nil + }) + + plan := &Plan{} + plan.addNode(Operation{ + Type: OpCreateNetwork, + ResourceID: "network:default", + Name: nw.Name, + Network: &nw, + }, "") + start := plan.addNode(Operation{ + Type: OpStartContainer, + ResourceID: "service:db:1", + Container: &container.Summary{ID: "db-id", Names: []string{"/test-db-1"}}, + }, "") + start.Phase = PhaseStart + + exec := svc.newPlanExecutor(&types.Project{Name: "test"}, emptyObservedState("test"), nil) + + assert.NilError(t, exec.run(t.Context(), plan)) + assert.Assert(t, createDone.Load()) +} + +// TestExecutePlanCreatePhaseFailureCancelsCreatePhase verifies phase-scoped +// cancellation didn't weaken the Create phase's own existing fail-fast +// behavior -- two independent (no DependsOn edge) Create-phase nodes, one +// failing immediately, must still cancel the other's in-flight work. Both +// nodes default to Phase: PhaseCreate (addNode's zero value), so they share +// the same runPhase call's phaseCancel. +func TestExecutePlanCreatePhaseFailureCancelsCreatePhase(t *testing.T) { + svc, apiClient := newTestService(t) + + apiClient.EXPECT().NetworkCreate(gomock.Any(), "test_default", gomock.Any()). + Return(client.NetworkCreateResult{}, errors.New("boom")) + + var volumeCreateCtxErr error + volumeCreateDone := make(chan struct{}) + apiClient.EXPECT().VolumeCreate(gomock.Any(), gomock.Any()). + DoAndReturn(func(ctx context.Context, _ client.VolumeCreateOptions) (client.VolumeCreateResult, error) { + defer close(volumeCreateDone) + <-ctx.Done() + volumeCreateCtxErr = ctx.Err() + return client.VolumeCreateResult{}, ctx.Err() + }) + + nw := types.NetworkConfig{Name: "test_default"} + vol := types.VolumeConfig{Name: "data", Driver: "local"} + + plan := &Plan{} + plan.addNode(Operation{ + Type: OpCreateNetwork, + ResourceID: "network:default", + Name: nw.Name, + Network: &nw, + }, "") + plan.addNode(Operation{ + Type: OpCreateVolume, + ResourceID: "volume:data", + Name: vol.Name, + Volume: &vol, + }, "") + + exec := svc.newPlanExecutor(&types.Project{Name: "test"}, emptyObservedState("test"), nil) + + // run waits for every node, and VolumeCreate blocks until its ctx ends: if + // the sibling failure ever stopped canceling it, run would hang until the + // suite-wide timeout. This deadline turns that into a local failure, and + // the context.Canceled assertion below tells it apart from the sibling + // cancellation the test is about. + ctx, cancel := context.WithTimeout(t.Context(), 5*time.Second) + defer cancel() + err := exec.run(ctx, plan) + assert.ErrorContains(t, err, "boom") + + select { + case <-volumeCreateDone: + default: + t.Fatal("run returned before VolumeCreate did") + } + assert.ErrorIs(t, volumeCreateCtxErr, context.Canceled, "VolumeCreate's ctx must be canceled by a sibling Create-phase node failing, not by the test's own deadline") +} + +// TestExecutePlanCreatePhaseFailureNeverDispatchesStartPhase complements +// TestExecutePlanCreatePhaseIsABarrierBeforeStartPhase: that test proves the +// Start phase waits for a successful Create phase, this one proves a failed +// Create phase skips the Start phase entirely rather than dispatching it and +// canceling it. run() must return the Create-phase error before runPhase is +// ever called on startNodes -- ContainerStart's .Times(0) fails the test the +// instant it's called at all, not just if it fails to be called. +func TestExecutePlanCreatePhaseFailureNeverDispatchesStartPhase(t *testing.T) { + svc, apiClient := newTestService(t) + + apiClient.EXPECT().NetworkCreate(gomock.Any(), "test_default", gomock.Any()). + Return(client.NetworkCreateResult{}, errors.New("boom")) + apiClient.EXPECT().ContainerStart(gomock.Any(), gomock.Any(), gomock.Any()).Times(0) + + nw := types.NetworkConfig{Name: "test_default"} + + plan := &Plan{} + plan.addNode(Operation{ + Type: OpCreateNetwork, + ResourceID: "network:default", + Name: nw.Name, + Network: &nw, + }, "") + start := plan.addNode(Operation{ + Type: OpStartContainer, + ResourceID: "service:db:1", + Container: &container.Summary{ID: "db-id", Names: []string{"/test-db-1"}}, + }, "") + start.Phase = PhaseStart + + exec := svc.newPlanExecutor(&types.Project{Name: "test"}, emptyObservedState("test"), nil) + + err := exec.run(t.Context(), plan) + assert.ErrorContains(t, err, "boom") +} + +// TestExecutePlanConcurrentPhaseFailureKeepsOriginatingError exercises a +// Copilot/docker-agent finding on the phase-scoped cancellation fix: +// errgroup.Group's plain Wait() returns whichever goroutine's error reaches +// its internal sync.Once first, with no idea which one actually caused the +// others to fail -- a sibling unblocked by a phase's cancellation and +// returning a bare context.Canceled of its own could in principle win that +// race over the originating node's real error. phaseCancel's own sync.Once +// records the first failure explicitly, and run() prefers it over +// eg.Wait()'s own pick, closing that window regardless of goroutine +// scheduling. This test runs the scenario under real concurrency (one +// immediately-failing node alongside many siblings unblocked by its +// cancellation, via dependency-wait on a PlanNode ID never added to the +// plan -- rs.done[dep.ID] is then a nil map entry, so the only way out of +// the select is <-nodeCtx.Done(), firing the instant the phase cancels) and +// asserts the real error always surfaces. Note: in practice the Go runtime +// never actually lets a sibling win this race in this in-process test -- +// the originating goroutine keeps running uninterrupted through its own +// short return path before the scheduler gets around to any of the +// newly-runnable siblings -- so reverting the fix does not make this test +// fail; its value is exercising the mechanism under load, not proving the +// fix by ablation. The fix's correctness instead rests on reading +// errgroup's own errOnce.Do source directly (golang.org/x/sync/errgroup), +// confirmed independently by two reviewers. +func TestExecutePlanConcurrentPhaseFailureKeepsOriginatingError(t *testing.T) { + svc, _ := newTestService(t) + + plan := &Plan{} + fail := plan.addNode(Operation{ + Type: OpWaitCondition, + ResourceID: "wait:missing:service_healthy", + Name: "missing", // no registered containers under this name -> immediate failure + Condition: types.ServiceConditionHealthy, + }, "") + fail.Phase = PhaseStart + + phantom := &PlanNode{ID: -1} // never added to plan.Nodes; its done-channel is never created + const siblings = 30 + for i := range siblings { + blocked := plan.addNode(Operation{ + Type: OpWaitCondition, + ResourceID: fmt.Sprintf("wait:phantom:%d", i), + Name: "phantom", + }, "", phantom) + blocked.Phase = PhaseStart + } + + exec := svc.newPlanExecutor(&types.Project{Name: "test"}, emptyObservedState("test"), nil) + + err := exec.run(t.Context(), plan) + assert.ErrorContains(t, err, "missing dependency missing") +} + // TestExecStartContainer_EnrichedResolvesCreateNodeAndStarts verifies that a // start-phase OpStartContainer (Service set) resolves its target through the // CreateContainer node it references — the same reconciliationContext @@ -189,6 +630,113 @@ func TestExecStartContainer_EnrichedResolvesCreateNodeAndStarts(t *testing.T) { assert.NilError(t, err) } +// TestExecutePlanRecreateThenStartUsesFinalName is a regression test: a +// recreate's create node is planned under a temporary name +// (planRecreateContainer's "_" dance, to avoid colliding with +// the old container still holding the final name), and the final name is +// applied by a separate OpRenameContainer node. The start phase's event +// naming (groupEventName) and resolveContainerID both read +// pctx.get(CreateNodeID) by design (plannedReplica keeps every start-phase +// reference pointed at the create node, not the rename node) -- so +// execRenameContainer must update that same entry in place once it renames +// the container, or the start phase reports progress under the stale +// temporary name forever. Caught via e2e (TestRestartWithDependencies) +// before this node-result update existed. +func TestExecutePlanRecreateThenStartUsesFinalName(t *testing.T) { + svc, apiClient, recorder := newStartPhaseTestService(t) + + service := types.ServiceConfig{Name: "web", ContainerSpec: types.ContainerSpec{Image: "alpine"}} + project := &types.Project{Name: "test", Services: types.Services{"web": service}} + + const tmpName = "abc123456789_test-web-1" + const finalName = "test-web-1" + + apiClient.EXPECT().ContainerCreate(gomock.Any(), gomock.Any()). + Return(client.ContainerCreateResult{ID: "new-id"}, nil) + apiClient.EXPECT().ContainerInspect(gomock.Any(), "new-id", gomock.Any()). + Return(client.ContainerInspectResult{Container: container.InspectResponse{ + ID: "new-id", + Name: "/" + tmpName, + Config: &container.Config{}, + NetworkSettings: &container.NetworkSettings{}, + }}, nil) + apiClient.EXPECT().ContainerRename(gomock.Any(), "new-id", client.ContainerRenameOptions{NewName: finalName}). + Return(client.ContainerRenameResult{}, nil) + apiClient.EXPECT().ContainerStart(gomock.Any(), "new-id", gomock.Any()). + Return(client.ContainerStartResult{}, nil) + + plan := &Plan{} + create := plan.addNode(Operation{ + Type: OpCreateContainer, + ResourceID: "service:web:1", + Cause: "config changed (tmpName)", + Service: &service, + Name: tmpName, + Number: 1, + }, "") + rename := plan.addNode(Operation{ + Type: OpRenameContainer, + ResourceID: "service:web:1", + Cause: "finalize recreate", + Name: finalName, + CreateNodeID: create.ID, + }, "", create) + plan.addNode(Operation{ + Type: OpStartContainer, + ResourceID: "service:web:1", + Cause: "start", + Service: &service, + CreateNodeID: create.ID, + }, "start:web:1", rename).Phase = PhaseStart + + err := svc.executePlan(t.Context(), project, emptyObservedState("test"), plan) + assert.NilError(t, err) + + // The start group's eventName is resolved lazily from + // pctx.get(CreateNodeID) (see groupEventName) once the start node + // actually runs -- by then the rename has already completed, so this + // must be the post-rename name, not create's own temporary one. + assert.DeepEqual(t, recorder.byID["Container "+finalName], []string{api.StatusStarting, api.StatusStarted}) +} + +// TestExecRenameContainer_RefreshesLiveViewName is the sibling regression to +// TestExecutePlanRecreateThenStartUsesFinalName: execCreateContainer +// publishes the new container into containersByService (the live view +// OpWaitCondition and sibling execCreateContainer calls read by service +// name) under its temporary name -- the only one it had at that point. +// Without execRenameContainer refreshing that same entry, a dependent +// waiting on this service's health (depends_on: condition: service_healthy) +// reports Waiting/Healthy under the stale temporary name for the rest of the +// plan's execution, exactly like TestRestartWithDependencies caught in e2e. +func TestExecRenameContainer_RefreshesLiveViewName(t *testing.T) { + svc, apiClient, _ := newStartPhaseTestService(t) + + service := types.ServiceConfig{Name: "web"} + project := &types.Project{Name: "test", Services: types.Services{"web": service}} + + const tmpName = "abc123456789_test-web-1" + const finalName = "test-web-1" + + apiClient.EXPECT().ContainerRename(gomock.Any(), "new-id", client.ContainerRenameOptions{NewName: finalName}). + Return(client.ContainerRenameResult{}, nil) + + exec := svc.newPlanExecutor(project, emptyObservedState("test"), nil) + exec.pctx.set(1, operationResult{ContainerID: "new-id", ContainerName: tmpName}) + exec.containersByService["web"] = Containers{{ID: "new-id", Names: []string{"/" + tmpName}}} + + node := &PlanNode{ID: 2, Operation: Operation{ + Type: OpRenameContainer, + Name: finalName, + Service: &service, + CreateNodeID: 1, + }} + + err := exec.execRenameContainer(t.Context(), node) + assert.NilError(t, err) + + assert.DeepEqual(t, exec.containersByService["web"][0].Names, []string{"/" + finalName}) +} + // TestExecRunPreStart_SkipsWhenReplicaAlreadyRunning covers the // observe-to-execute drift guard: the plan scheduled RunPreStart because no // replica was running at observation time, but a replica started in the @@ -541,3 +1089,175 @@ func TestExecutePlanFailedPreStartGatesStart(t *testing.T) { "Creating", "Created", api.StatusStarting, preStartErr, }) } + +// TestExecutePlanWaitTimeoutIsMarked verifies that a wait node's own +// --wait-timeout window expiring is reported as errWaitTimeout -- the marker +// upDetached and start() translate into a user-facing message -- while still +// satisfying context.DeadlineExceeded. +func TestExecutePlanWaitTimeoutIsMarked(t *testing.T) { + svc, apiClient, _ := newStartPhaseTestService(t) + + dbSummary := container.Summary{ + ID: "db-id", + Names: []string{"/test-db-1"}, + Labels: map[string]string{api.ServiceLabel: "db", api.OneoffLabel: "False"}, + } + apiClient.EXPECT().ContainerInspect(gomock.Any(), "db-id", gomock.Any()).Return(client.ContainerInspectResult{ + Container: container.InspectResponse{ + ID: "db-id", + Name: "/test-db-1", + State: &container.State{ + Status: container.StateRunning, + Health: &container.Health{Status: container.Starting}, + }, + Config: &container.Config{Healthcheck: &container.HealthConfig{Test: []string{"CMD", "true"}}}, + }, + }, nil).AnyTimes() + + plan := &Plan{} + plan.addNode(Operation{ + Type: OpWaitCondition, + ResourceID: "wait:db:service_healthy", + Name: "db", + Condition: types.ServiceConditionHealthy, + }, "") + + exec := svc.newPlanExecutor(&types.Project{Name: "test"}, emptyObservedState("test"), nil) + exec.containersByService["db"] = Containers{dbSummary} + exec.waitTimeout = 200 * time.Millisecond + + err := exec.run(t.Context(), plan) + assert.ErrorIs(t, err, errWaitTimeout) + assert.ErrorIs(t, err, context.DeadlineExceeded) +} + +// TestExecutePlanOtherDeadlinesAreNotWaitTimeouts verifies that a +// DeadlineExceeded that is not a wait node's own window expiring is never +// marked errWaitTimeout, even with --wait-timeout set: an engine call timing +// out in a node that is not a wait, and a deadline inherited from the +// caller's context firing during a wait. Translating either into a +// dependency-readiness message would blame the wrong thing. +func TestExecutePlanOtherDeadlinesAreNotWaitTimeouts(t *testing.T) { + t.Run("engine call timing out in a non-wait node", func(t *testing.T) { + svc, apiClient, _ := newStartPhaseTestService(t) + apiClient.EXPECT().ContainerStart(gomock.Any(), "db-id", gomock.Any()). + Return(client.ContainerStartResult{}, context.DeadlineExceeded) + + plan := &Plan{} + plan.addNode(Operation{ + Type: OpStartContainer, + ResourceID: "service:db:1", + Container: &container.Summary{ID: "db-id", Names: []string{"/test-db-1"}}, + }, "").Phase = PhaseStart + + exec := svc.newPlanExecutor(&types.Project{Name: "test"}, emptyObservedState("test"), nil) + exec.waitTimeout = time.Minute + + err := exec.run(t.Context(), plan) + assert.ErrorIs(t, err, context.DeadlineExceeded) + assert.Assert(t, !errors.Is(err, errWaitTimeout), "an engine-call timeout was marked as a wait timeout: %v", err) + }) + + t.Run("deadline inherited from the caller during a wait", func(t *testing.T) { + svc, apiClient, _ := newStartPhaseTestService(t) + dbSummary := container.Summary{ + ID: "db-id", + Names: []string{"/test-db-1"}, + Labels: map[string]string{api.ServiceLabel: "db", api.OneoffLabel: "False"}, + } + apiClient.EXPECT().ContainerInspect(gomock.Any(), "db-id", gomock.Any()).Return(client.ContainerInspectResult{ + Container: container.InspectResponse{ + ID: "db-id", + Name: "/test-db-1", + State: &container.State{ + Status: container.StateRunning, + Health: &container.Health{Status: container.Starting}, + }, + Config: &container.Config{Healthcheck: &container.HealthConfig{Test: []string{"CMD", "true"}}}, + }, + }, nil).AnyTimes() + + plan := &Plan{} + plan.addNode(Operation{ + Type: OpWaitCondition, + ResourceID: "wait:db:service_healthy", + Name: "db", + Condition: types.ServiceConditionHealthy, + }, "") + + exec := svc.newPlanExecutor(&types.Project{Name: "test"}, emptyObservedState("test"), nil) + exec.containersByService["db"] = Containers{dbSummary} + exec.waitTimeout = time.Minute // far longer than the caller's own deadline + + ctx, cancel := context.WithTimeout(t.Context(), 200*time.Millisecond) + defer cancel() + err := exec.run(ctx, plan) + assert.ErrorIs(t, err, context.DeadlineExceeded) + assert.Assert(t, !errors.Is(err, errWaitTimeout), "an inherited deadline was marked as a wait timeout: %v", err) + }) +} + +// TestExecutePlanWaitTimeoutSurvivesDependentSkip verifies the marker is still +// what run() returns when a node depends on the wait that timed out: the +// dependent is skipped with "dependency failed: ...", but it is the wait's own +// failure that is reported, so the caller still translates it. +func TestExecutePlanWaitTimeoutSurvivesDependentSkip(t *testing.T) { + svc, apiClient, _ := newStartPhaseTestService(t) + + dbSummary := container.Summary{ + ID: "db-id", + Names: []string{"/test-db-1"}, + Labels: map[string]string{api.ServiceLabel: "db", api.OneoffLabel: "False"}, + } + apiClient.EXPECT().ContainerInspect(gomock.Any(), "db-id", gomock.Any()).Return(client.ContainerInspectResult{ + Container: container.InspectResponse{ + ID: "db-id", + Name: "/test-db-1", + State: &container.State{ + Status: container.StateRunning, + Health: &container.Health{Status: container.Starting}, + }, + Config: &container.Config{Healthcheck: &container.HealthConfig{Test: []string{"CMD", "true"}}}, + }, + }, nil).AnyTimes() + // no ContainerStart expectation: the dependent must never run + + plan := &Plan{} + wait := plan.addNode(Operation{ + Type: OpWaitCondition, + ResourceID: "wait:db:service_healthy", + Name: "db", + Condition: types.ServiceConditionHealthy, + }, "") + // both in the Start phase, like the reconciler plans them: the skipped + // dependent only exists if the wait that fails is in its own phase + wait.Phase = PhaseStart + plan.addNode(Operation{ + Type: OpStartContainer, + ResourceID: "service:app:1", + Container: &container.Summary{ID: "app-id", Names: []string{"/test-app-1"}}, + }, "", wait).Phase = PhaseStart + + exec := svc.newPlanExecutor(&types.Project{Name: "test"}, emptyObservedState("test"), nil) + exec.containersByService["db"] = Containers{dbSummary} + exec.waitTimeout = 200 * time.Millisecond + + err := exec.run(t.Context(), plan) + assert.ErrorIs(t, err, errWaitTimeout) +} + +func TestTranslateWaitTimeout(t *testing.T) { + marked := fmt.Errorf("%w: %w", errWaitTimeout, context.DeadlineExceeded) + other := errors.New("boom") + + // a depends_on wait timing out is a dependency timeout, whether or not + // --wait was given: "application not healthy" is the final readiness + // check's message, not this one's + assert.Error(t, translateWaitTimeout(marked), "timeout waiting for dependencies") + + // anything that is not a wait's own timeout comes back untouched: a bare + // DeadlineExceeded included + assert.Equal(t, translateWaitTimeout(other), other) + assert.Equal(t, translateWaitTimeout(context.DeadlineExceeded), context.DeadlineExceeded) + assert.NilError(t, translateWaitTimeout(nil)) +} diff --git a/pkg/compose/reconcile.go b/pkg/compose/reconcile.go index cb2b805b21..c1a9421dc3 100644 --- a/pkg/compose/reconcile.go +++ b/pkg/compose/reconcile.go @@ -1172,6 +1172,30 @@ func (r *reconciler) setContainerNode(service string, number int, node *PlanNode r.containerNodes[service][number] = node } +// exceptionalStateRestartNodes returns every create-phase bare-restart node +// (OpStartContainer) planned for this service's exceptional-state (paused, +// dead) replicas, in deterministic replica-number order. serviceNodes keeps +// only the LAST node processed for a service's create-phase convergence -- +// correct for a single replica, but a scaled service with more than one +// exceptional-state replica needs every one of them in startChainEnds, or a +// service_started consumer could run while another replica's restart is +// still pending. +func (r *reconciler) exceptionalStateRestartNodes(service string) []*PlanNode { + planned := r.containerNodes[service] + numbers := make([]int, 0, len(planned)) + for number, node := range planned { + if node.Operation.Type == OpStartContainer { + numbers = append(numbers, number) + } + } + sort.Ints(numbers) + nodes := make([]*PlanNode, len(numbers)) + for i, number := range numbers { + nodes[i] = planned[number] + } + return nodes +} + // startPhaseReplicas collects the replicas to start, ascending number: // containers materialized by the create phase plus observed up-to-date // containers not running — exactly the isNotRunning set the imperative start @@ -1305,17 +1329,22 @@ func (r *reconciler) waitConditionNode(dep string, cfg types.ServiceDependency, // planProviderStart is the start-phase visit of a provider service: no // container to start, but its own depends_on still applies — the imperative // startService waits on it for every service, providers included. Its chain -// end is those prerequisites, else its create-phase RunProvider node. +// end is its create-phase RunProvider node (the deployment itself), plus +// those dependency prerequisites when it has any -- a consumer must wait for +// both: the provider's own dependencies satisfied AND the provider actually +// deployed, not either in isolation. Before this ordering was corrected, a +// provider with both an upstream dependency and a downstream consumer let +// the dependency wait substitute for the deploy node entirely, so the +// consumer could start while the provider's plugin/relay deployment was +// still running. func (r *reconciler) planProviderStart(service types.ServiceConfig) error { depNodes, err := r.startPhaseDependencies(service) if err != nil { return err } ends := depNodes - if len(ends) == 0 { - if node, ok := r.serviceNodes[service.Name]; ok { - ends = []*PlanNode{node} - } + if node, ok := r.serviceNodes[service.Name]; ok && !slices.Contains(ends, node) { + ends = append(ends, node) } if len(ends) > 0 { r.startChainEnds[service.Name] = ends @@ -1327,7 +1356,13 @@ func (r *reconciler) planServiceStart(service types.ServiceConfig) error { if service.Provider != nil { return r.planProviderStart(service) } - if service.GetScale() == 0 { + // imperative parity (startService): deploy.replicas: 0 is an unconditional + // no-op, but a service with scale: 0 is still visited -- its depends_on + // conditions are evaluated and its dependents ordered after them -- and + // whatever replicas it already owns are started (scope Start only: the + // create phase removes them all under CreateStart). It is just never an + // error for it to have no container to start. + if service.Deploy != nil && service.Deploy.Replicas != nil && *service.Deploy.Replicas == 0 { return nil } @@ -1341,7 +1376,7 @@ func (r *reconciler) planServiceStart(service types.ServiceConfig) error { if err != nil { return err } - if len(replicas) == 0 && !anyRunning && r.options.Scope == ScopeStart { + if len(replicas) == 0 && !anyRunning && r.options.Scope == ScopeStart && service.GetScale() > 0 { // imperative parity (startService): a scale>0 service with no // container at all cannot be started — only reachable under scope // Start, since CreateStart would have planned the missing creates @@ -1349,11 +1384,19 @@ func (r *reconciler) planServiceStart(service types.ServiceConfig) error { } if len(replicas) == 0 { // the visit still happened: dependents order after its prerequisites - // (waits, service_started edges), else after the create phase + // (waits, service_started edges) AND after every create phase's own + // exceptional-state restart node (anyRunning via a bare + // OpStartContainer, same reasoning as planProviderStart) -- not + // either/or: a consumer must wait for both the dependency and every + // such restart actually happening, or it can start before a + // paused/dead replica's container is running again. A scaled + // service can have more than one exceptional-state replica, so this + // collects all of them (exceptionalStateRestartNodes), not just the + // single last node serviceNodes retains. ends := depNodes - if len(ends) == 0 { - if node, ok := r.serviceNodes[service.Name]; ok { - ends = []*PlanNode{node} + for _, node := range r.exceptionalStateRestartNodes(service.Name) { + if !slices.Contains(ends, node) { + ends = append(ends, node) } } if len(ends) > 0 { @@ -1511,13 +1554,18 @@ func (r *reconciler) planRecreateContainer(service types.ServiceConfig, oc *Obse }, group, removeDeps...) // 4. Rename to final name. Link to the create node so the executor can - // fetch the resulting container ID directly. + // fetch the resulting container ID directly. Service is set so + // execRenameContainer can refresh that container's entry in the live + // containersByService view (OpWaitCondition and sibling create calls + // read it by service name) once the rename actually lands — otherwise + // they'd keep seeing the temporary name past this node. finalName := getContainerName(r.project.Name, service, oc.Number) renameNode := r.plan.addNode(Operation{ Type: OpRenameContainer, ResourceID: resID, Cause: "finalize recreate", Name: finalName, + Service: &serviceCopy, CreateNodeID: createNode.ID, }, group, removeNode) diff --git a/pkg/compose/reconcile_start_test.go b/pkg/compose/reconcile_start_test.go index 7064197fb2..dc4abbd425 100644 --- a/pkg/compose/reconcile_start_test.go +++ b/pkg/compose/reconcile_start_test.go @@ -307,6 +307,69 @@ func TestPlanStart_AllRunningStillWaitsOnConditions(t *testing.T) { assert.Assert(t, !wait.Operation.BestEffort) } +// Imperative parity (startService): a service with scale: 0 is still visited +// -- its depends_on conditions are evaluated before the no-op, so an unhealthy +// dependency still fails `up`/`start` and whatever is ordered after the +// service is ordered after those prerequisites -- and under scope Start the +// replicas it already owns are started. Only deploy.replicas: 0 is an +// unconditional no-op. Having no container is never an error for it. +func TestPlanStart_ScaleZeroIsStillVisited(t *testing.T) { + zero := 0 + db := types.ServiceConfig{Name: "db"} + scaled := serviceWithDeps("app", types.DependsOnConfig{"db": {Condition: types.ServiceConditionHealthy, Required: true}}) + scaled.Scale = &zero + deployed := serviceWithDeps("job", types.DependsOnConfig{"db": {Condition: types.ServiceConditionHealthy, Required: true}}) + deployed.Deploy = &types.DeployConfig{Replicas: &zero} + project := &types.Project{ + Name: "myproject", + Services: types.Services{"db": db, "app": scaled, "job": deployed}, + } + dbHash, err := serviceHashWithResolvedRefs(db, nil) + assert.NilError(t, err) + observed := emptyObserved() + observed.Containers["db"] = []ObservedContainer{observedServiceContainer("db", 1, container.StateRunning, dbHash)} + + // no container for the scale-zero service: its dependency wait is planned + // and nothing is an error; deploy.replicas: 0 plans nothing at all + for _, scope := range []ReconcileScope{ScopeStart, ScopeCreateStart} { + plan, err := reconcile(t.Context(), project, observed, startScopeOptions(scope), noPrompt) + assert.NilError(t, err) + waits := 0 + for _, n := range plan.Nodes { + switch n.Operation.Type { + case OpWaitCondition: + waits++ + assert.Equal(t, n.Operation.Name, "db") + case OpStartContainer, OpCreateContainer: + t.Fatalf("no container expected for scale-zero services, got %s %s:\n%s", n.Operation.Type, n.Operation.ResourceID, plan) + } + } + assert.Equal(t, waits, 1, "one deduplicated db wait, from app only:\n%s", plan) + } + + // scope Start also starts the replicas the scale-zero service still owns + appHash, err := serviceHashWithResolvedRefs(scaled, nil) + assert.NilError(t, err) + observed.Containers["app"] = []ObservedContainer{observedServiceContainer("app", 1, container.StateExited, appHash)} + plan, err := reconcile(t.Context(), project, observed, startScopeOptions(ScopeStart), noPrompt) + assert.NilError(t, err) + var started []string + for _, n := range plan.Nodes { + if n.Operation.Type == OpStartContainer { + started = append(started, n.Operation.ResourceID) + } + } + assert.DeepEqual(t, started, []string{"service:app:1"}) + + // the create phase removes every replica of a scale-zero service before + // the start phase looks: nothing to start under CreateStart + plan, err = reconcile(t.Context(), project, observed, startScopeOptions(ScopeCreateStart), noPrompt) + assert.NilError(t, err) + for _, n := range plan.Nodes { + assert.Assert(t, n.Operation.Type != OpStartContainer, "unexpected start node:\n%s", plan) + } +} + // Imperative parity (startService): under scope Start, a scale>0 service // with no container at all fails the plan the way `compose start` fails. func TestPlanStart_NoContainerToStartFails(t *testing.T) { @@ -381,6 +444,169 @@ func TestPlanStart_ProviderWaitsOnDependencies(t *testing.T) { assert.Equal(t, wait.Operation.Condition, types.ServiceConditionHealthy) } +// TestPlanStart_ProviderConsumerWaitsForDeployment is a regression test for +// a Copilot review finding on #14290: once ScopeCreateStart became the real, +// exercised path for detached up, planProviderStart's startChainEnds for a +// provider WITH its own depends_on was just that dependency's wait node -- +// dropping the provider's own OpRunProvider (deployment) node entirely. A +// downstream consumer of the provider could therefore start while the +// provider plugin/relay deployment was still running, a barrier the old +// create-then-start two-phase sequence guaranteed for free. +func TestPlanStart_ProviderConsumerWaitsForDeployment(t *testing.T) { + db := types.ServiceConfig{Name: "db"} + db.HealthCheck = &types.HealthCheckConfig{Test: []string{"CMD", "true"}} + prov := serviceWithDeps("prov", types.DependsOnConfig{"db": {Condition: types.ServiceConditionHealthy, Required: true}}) + prov.Provider = &types.ServiceProviderConfig{Type: "test"} + consumer := serviceWithDeps("consumer", types.DependsOnConfig{"prov": {Condition: types.ServiceConditionStarted, Required: true}}) + project := &types.Project{ + Name: "myproject", + Services: types.Services{"db": db, "prov": prov, "consumer": consumer}, + } + dbHash, err := serviceHashWithResolvedRefs(db, nil) + assert.NilError(t, err) + consumerHash, err := serviceHashWithResolvedRefs(consumer, nil) + assert.NilError(t, err) + observed := emptyObserved() + observed.Containers["db"] = []ObservedContainer{ + observedServiceContainer("db", 1, container.StateRunning, dbHash), + } + observed.Containers["consumer"] = []ObservedContainer{ + observedServiceContainer("consumer", 1, container.StateExited, consumerHash), + } + + plan, err := reconcile(t.Context(), project, observed, startScopeOptions(ScopeCreateStart), noPrompt) + assert.NilError(t, err) + + var providerNode, consumerStartNode *PlanNode + for _, n := range plan.Nodes { + switch { + case n.Operation.Type == OpRunProvider: + providerNode = n + case n.Operation.Type == OpStartContainer && n.Operation.ResourceID == "service:consumer:1": + consumerStartNode = n + } + } + if providerNode == nil { + t.Fatalf("expected an OpRunProvider node for prov:\n%s", plan) + } + if consumerStartNode == nil { + t.Fatalf("expected a start node for consumer:\n%s", plan) + } + assert.Assert(t, slices.Contains(consumerStartNode.DependsOn, providerNode), + "consumer's start must depend on the provider's own deployment node, not just its depends_on wait:\n%s", plan) +} + +// TestPlanStart_ExceptionalStateConsumerWaitsForRestart is the sibling +// regression to TestPlanStart_ProviderConsumerWaitsForDeployment for an +// ordinary (non-provider) service: the same either/or bug in +// planServiceStart's len(replicas) == 0 branch dropped the service's own +// create-phase bare-restart node (TestPlanStart_ExceptionalStateReplicaCountsAsRunning) +// from startChainEnds whenever the service also had its own depends_on, +// keeping only the dependency wait. A downstream service_started consumer +// could then start before a paused/dead service's only container was +// actually running again. +func TestPlanStart_ExceptionalStateConsumerWaitsForRestart(t *testing.T) { + db := types.ServiceConfig{Name: "db"} + db.HealthCheck = &types.HealthCheckConfig{Test: []string{"CMD", "true"}} + app := serviceWithDeps("app", types.DependsOnConfig{"db": {Condition: types.ServiceConditionHealthy, Required: true}}) + consumer := serviceWithDeps("consumer", types.DependsOnConfig{"app": {Condition: types.ServiceConditionStarted, Required: true}}) + project := &types.Project{ + Name: "myproject", + Services: types.Services{"db": db, "app": app, "consumer": consumer}, + } + dbHash, err := serviceHashWithResolvedRefs(db, nil) + assert.NilError(t, err) + appHash, err := serviceHashWithResolvedRefs(app, nil) + assert.NilError(t, err) + consumerHash, err := serviceHashWithResolvedRefs(consumer, nil) + assert.NilError(t, err) + observed := emptyObserved() + observed.Containers["db"] = []ObservedContainer{ + observedServiceContainer("db", 1, container.StateRunning, dbHash), + } + observed.Containers["app"] = []ObservedContainer{ + observedServiceContainer("app", 1, container.StatePaused, appHash), + } + observed.Containers["consumer"] = []ObservedContainer{ + observedServiceContainer("consumer", 1, container.StateExited, consumerHash), + } + + plan, err := reconcile(t.Context(), project, observed, startScopeOptions(ScopeCreateStart), noPrompt) + assert.NilError(t, err) + + var appRestartNode, consumerStartNode *PlanNode + for _, n := range plan.Nodes { + switch { + case n.Operation.Type == OpStartContainer && n.Operation.ResourceID == "service:app:1": + appRestartNode = n + case n.Operation.Type == OpStartContainer && n.Operation.ResourceID == "service:consumer:1": + consumerStartNode = n + } + } + if appRestartNode == nil { + t.Fatalf("expected the create-phase bare-restart node for app:\n%s", plan) + } + if consumerStartNode == nil { + t.Fatalf("expected a start node for consumer:\n%s", plan) + } + assert.Assert(t, slices.Contains(consumerStartNode.DependsOn, appRestartNode), + "consumer's start must depend on app's own restart node, not just its depends_on wait:\n%s", plan) +} + +// TestPlanStart_ScaledExceptionalStateConsumerWaitsForEveryRestart is a +// regression test for a Copilot review finding on +// TestPlanStart_ExceptionalStateConsumerWaitsForRestart's own fix: for a +// scaled service, serviceNodes keeps only the LAST create-phase node +// processed, so a consumer's start only ended up depending on the highest- +// numbered replica's restart. With two exceptional-state replicas, the +// consumer must depend on BOTH restart nodes, not just one. +func TestPlanStart_ScaledExceptionalStateConsumerWaitsForEveryRestart(t *testing.T) { + two := 2 + app := types.ServiceConfig{Name: "app", Deploy: &types.DeployConfig{Replicas: &two}} + consumer := serviceWithDeps("consumer", types.DependsOnConfig{"app": {Condition: types.ServiceConditionStarted, Required: true}}) + project := &types.Project{ + Name: "myproject", + Services: types.Services{"app": app, "consumer": consumer}, + } + appHash, err := serviceHashWithResolvedRefs(app, nil) + assert.NilError(t, err) + consumerHash, err := serviceHashWithResolvedRefs(consumer, nil) + assert.NilError(t, err) + observed := emptyObserved() + observed.Containers["app"] = []ObservedContainer{ + observedServiceContainer("app", 1, container.StatePaused, appHash), + observedServiceContainer("app", 2, container.StateDead, appHash), + } + observed.Containers["consumer"] = []ObservedContainer{ + observedServiceContainer("consumer", 1, container.StateExited, consumerHash), + } + + plan, err := reconcile(t.Context(), project, observed, startScopeOptions(ScopeCreateStart), noPrompt) + assert.NilError(t, err) + + var restart1, restart2, consumerStartNode *PlanNode + for _, n := range plan.Nodes { + switch { + case n.Operation.Type == OpStartContainer && n.Operation.ResourceID == "service:app:1": + restart1 = n + case n.Operation.Type == OpStartContainer && n.Operation.ResourceID == "service:app:2": + restart2 = n + case n.Operation.Type == OpStartContainer && n.Operation.ResourceID == "service:consumer:1": + consumerStartNode = n + } + } + if restart1 == nil || restart2 == nil { + t.Fatalf("expected both replicas' bare-restart nodes:\n%s", plan) + } + if consumerStartNode == nil { + t.Fatalf("expected a start node for consumer:\n%s", plan) + } + assert.Assert(t, slices.Contains(consumerStartNode.DependsOn, restart1), + "consumer's start must depend on replica 1's restart node:\n%s", plan) + assert.Assert(t, slices.Contains(consumerStartNode.DependsOn, restart2), + "consumer's start must depend on replica 2's restart node too, not just the last one processed:\n%s", plan) +} + // A replica condemned by scale-down must never receive a start-phase node: // the imperative engine only starts what survives the convergence — and the // condemned replica does not count as running for the pre_start gating. diff --git a/pkg/compose/service_containers.go b/pkg/compose/service_containers.go index 0ac19ee9b7..c13ff9eef1 100644 --- a/pkg/compose/service_containers.go +++ b/pkg/compose/service_containers.go @@ -160,6 +160,7 @@ func containerReasonEvents(containers Containers, eventFunc func(string, string) const ServiceConditionRunningOrHealthy = "running_or_healthy" func (s *composeService) waitDependencies(ctx context.Context, project *types.Project, dependant string, dependencies types.DependsOnConfig, containers Containers, timeout time.Duration) error { + origCtx := ctx if timeout > 0 { withTimeout, cancelFunc := context.WithTimeout(ctx, timeout) defer cancelFunc() @@ -184,7 +185,7 @@ func (s *composeService) waitDependencies(ctx context.Context, project *types.Pr } eg.Go(func() error { - return s.waitDependency(ctx, dependant, dep, config, waitingFor) + return s.waitDependency(ctx, origCtx, dependant, dep, config, waitingFor) }) } err := eg.Wait() @@ -197,7 +198,21 @@ func (s *composeService) waitDependencies(ctx context.Context, project *types.Pr // waitDependency polls the dependency's containers until its depends_on // condition is satisfied (done), definitively failed (err), or ctx is // cancelled. Each check reports (done, err): (false, nil) means keep polling. -func (s *composeService) waitDependency(ctx context.Context, dependant, dep string, config types.ServiceDependency, waitingFor Containers) error { +// origCtx is ctx as it stood before the caller wrapped it with this wait's +// own timeout (if any) -- comparing origCtx.Err() against ctx.Err() at the +// moment ctx.Done() fires is how this tells apart a DeadlineExceeded this +// specific call's own wrap is responsible for from one inherited from an +// ancestor context the caller never touched. A bare "did the caller +// configure a timeout at all" flag isn't enough: if origCtx itself already +// carries an earlier deadline, wrapping it with context.WithTimeout still +// makes both origCtx and ctx report DeadlineExceeded once that earlier +// deadline fires, even though this call's own timeout never actually +// elapsed -- only origCtx.Err() == nil proves this wrap's own timeout is +// the one that fired. Only that case is safe to tolerate on an optional +// dependency; an inherited deadline means something else entirely (an +// external deadline, a test harness timeout) fired, and must keep +// propagating regardless of Required. +func (s *composeService) waitDependency(ctx, origCtx context.Context, dependant, dep string, config types.ServiceDependency, waitingFor Containers) error { ticker := time.NewTicker(500 * time.Millisecond) defer ticker.Stop() for { @@ -205,8 +220,20 @@ func (s *composeService) waitDependency(ctx context.Context, dependant, dep stri case <-ticker.C: case <-ctx.Done(): // An expired deadline is precisely the failure this wait is meant - // to detect; only a plain cancellation (Ctrl-C) stays silent. + // to detect for a required dependency; only a plain cancellation + // (Ctrl-C) stays silent either way. An optional dependency + // tolerates a timeout exactly like it tolerates any other + // definitive failure the check* functions below report — + // skipped, not aborted — but only this call's OWN timeout: an + // inherited deadline is a different, real failure the caller + // must still see. if errors.Is(ctx.Err(), context.DeadlineExceeded) { + if !config.Required && origCtx.Err() == nil { + s.events.On(containerReasonEvents(waitingFor, skippedEvent, + fmt.Sprintf("optional dependency %q did not satisfy %q before the timeout", dep, config.Condition))...) + logrus.Warnf("optional dependency %q did not satisfy %q before the timeout", dep, config.Condition) + return nil + } return ctx.Err() } return nil diff --git a/pkg/compose/service_containers_test.go b/pkg/compose/service_containers_test.go index d6e3527c50..42e20290a7 100644 --- a/pkg/compose/service_containers_test.go +++ b/pkg/compose/service_containers_test.go @@ -865,6 +865,35 @@ func TestWaitDependencyDeadline(t *testing.T) { assert.Error(t, err, "timeout waiting for dependencies") }) + // Regression guard: an optional dependency's deadline expiring (new as of + // planExecutor.waitTimeout giving execWaitCondition a real timeout for + // the first time -- see waitDependency's ctx.Done() branch) must be + // tolerated exactly like any other definitive failure of an optional + // dependency, not surfaced as "timeout waiting for dependencies". + t.Run("expired deadline on an optional dependency is skipped, not an error", func(t *testing.T) { + optionalDeps := types.DependsOnConfig{ + "db": {Condition: types.ServiceConditionHealthy, Required: false}, + } + err := tested.(*composeService).waitDependencies(t.Context(), &project, "app", optionalDeps, containers, 50*time.Millisecond) + assert.NilError(t, err) + }) + + // Regression guard: the tolerance above must apply only to a deadline + // THIS call's own timeout parameter is responsible for -- an unrelated, + // already-expired deadline the caller brought in (timeout == 0, so this + // call set no deadline of its own) is a different, real failure that + // must still propagate even for an optional dependency. + t.Run("an inherited parent deadline is not swallowed for an optional dependency", func(t *testing.T) { + optionalDeps := types.DependsOnConfig{ + "db": {Condition: types.ServiceConditionHealthy, Required: false}, + } + parentCtx, cancel := context.WithTimeout(t.Context(), time.Millisecond) + defer cancel() + time.Sleep(10 * time.Millisecond) // let the parent's own deadline actually expire first + err := tested.(*composeService).waitDependencies(parentCtx, &project, "app", optionalDeps, containers, 0) + assert.Error(t, err, "timeout waiting for dependencies") + }) + t.Run("user cancellation is not a wait failure", func(t *testing.T) { ctx, cancel := context.WithCancel(t.Context()) cancel() diff --git a/pkg/compose/up.go b/pkg/compose/up.go index 2c7998a46b..2f6aafef1b 100644 --- a/pkg/compose/up.go +++ b/pkg/compose/up.go @@ -44,14 +44,10 @@ import ( func (s *composeService) Up(ctx context.Context, project *types.Project, options api.UpOptions) error { err := Run(ctx, tracing.SpanWrapFunc("project/up", tracing.ProjectOptions(ctx, project), func(ctx context.Context) error { - err := s.create(ctx, project, options.Create) - if err != nil { - return err - } if options.Start.Attach == nil { - return s.start(ctx, project.Name, options.Start, nil) + return s.upDetached(ctx, project, options) } - return nil + return s.create(ctx, project, options.Create) }), "up", s.events) if err != nil { return err @@ -67,6 +63,95 @@ func (s *composeService) Up(ctx context.Context, project *types.Project, options return s.runInteractiveUp(ctx, project, options) } +// upDetached runs detached `up`'s Create and Start phases as a single plan: +// the semantic switchover from create() + start() -- two separate daemon +// snapshots, the second blind to what the first just did -- to one +// preparePlan/executePlan pass covering both phases (epic #14081, lot 2). +// Interactive up keeps the create()+start() sequence for now: its own +// create/start phase boundary (attach/printer/monitor setup in between) is a +// separate, riskier item of the same lot. +func (s *composeService) upDetached(ctx context.Context, project *types.Project, options api.UpOptions) error { + project, observed, plan, err := s.preparePlan(ctx, project, options.Create, ScopeCreateStart) + if err != nil { + return err + } + + // Must run against the pre-execution snapshot: observed only labels a + // container Running if it already was one before this plan touched + // anything, exactly what "the plan won't touch it" is supposed to mean. + emitRunningEvents(project, observed, plan, s.events) + + // The plan's own OpWaitCondition nodes (service_healthy / + // service_completed_successfully dependency waits) block with no timeout + // of their own -- unlike start()'s per-dependency waitDependencies call, + // which already threads WaitTimeout through every wait unconditionally + // (InDependencyOrder passes it to startService regardless of + // options.Wait -- --wait-timeout alone, with no --wait, is a legal CLI + // combination nothing rejects). exec.waitTimeout bounds exactly those + // nodes (see executeNode), each with its OWN fresh window starting when + // that wait begins -- not a single shared budget counted down from + // before the plan even started. Sharing one absolute deadline across + // create/start/hook work and every wait would let slow, unrelated work + // alone exhaust it, failing an otherwise healthy deployment as "not + // healthy" with no wait ever actually timing out -- start()'s real, + // per-wait-independent behavior never had that failure mode. + exec := s.newPlanExecutor(project, observed, nil) + exec.waitTimeout = options.Start.WaitTimeout + + if err := exec.run(ctx, plan); err != nil { + return translateWaitTimeout(err) + } + + if !options.Start.Wait { + return nil + } + + // The plan may have created or recreated containers: this verification + // needs their current IDs, which the pre-execution observed snapshot + // above doesn't have for a container that didn't exist yet at + // observation time. The listing runs on the caller's context, before the + // --wait-timeout window opens, so daemon-listing latency never eats into + // the budget the readiness polling is owed (any deadline it hits is the + // caller's own, unrelated to --wait-timeout, and is returned as such). + containers, err := s.getContainers(ctx, project.Name, oneOffExclude, true) + if err != nil { + return err + } + + // The check then opens its own fresh WaitTimeout window, same as every + // OpWaitCondition node above and start()'s own final --wait check did -- + // not whatever's left of a shared budget, which unrelated plan work could + // already have exhausted with no wait ever at risk. + // + // origCtx is kept so the DeadlineExceeded check below can tell this fresh + // window expiring (origCtx still fine) apart from origCtx's own, + // independent deadline propagating through the derived one (origCtx + // already done): a parent deadline firing first makes the derived + // context's Err() report DeadlineExceeded too, inherited from the + // parent, even though this window's own timer never fired. + origCtx := ctx + if options.Start.WaitTimeout > 0 { + withTimeout, cancel := context.WithTimeout(ctx, options.Start.WaitTimeout) + defer cancel() + ctx = withTimeout + } + + depends := types.DependsOnConfig{} + for _, svc := range project.Services { + depends[svc.Name] = types.ServiceDependency{ + Condition: getDependencyCondition(svc, project), + Required: true, + } + } + if err := s.waitDependencies(ctx, project, project.Name, depends, containers, 0); err != nil { + if options.Start.WaitTimeout > 0 && origCtx.Err() == nil && errors.Is(ctx.Err(), context.DeadlineExceeded) { + return fmt.Errorf("application not healthy after %s", options.Start.WaitTimeout) + } + return err + } + return nil +} + // upSession carries the state shared between the goroutines driving an // interactive `compose up` once services are created: the errgroup running // them, the collected errors, and the application exit status.