From 5fb5979ec0f11596bdde2c5789d75a17e9af8d25 Mon Sep 17 00:00:00 2001 From: Jamison Lahman Date: Thu, 30 Jul 2026 12:04:24 -0700 Subject: [PATCH] fix(cli): count every service that is not up in deploy status (#13616) Co-authored-by: Claude Opus 5 --- cli/cmd/deploy_lifecycle.go | 3 +- cli/internal/deploy/install/diagnose.go | 6 + cli/internal/deploy/install/lifecycle_test.go | 171 +++++++++++++++++- cli/internal/deploy/install/status.go | 135 ++++++++++---- 4 files changed, 281 insertions(+), 34 deletions(-) diff --git a/cli/cmd/deploy_lifecycle.go b/cli/cmd/deploy_lifecycle.go index 15049a8528..1cf8e4add6 100644 --- a/cli/cmd/deploy_lifecycle.go +++ b/cli/cmd/deploy_lifecycle.go @@ -46,7 +46,8 @@ CLI, by .env, and by the running containers (drift between them is flagged), plus per-container status and health. Read-only. Exit codes make it usable as a probe: 0 when everything is up and -healthy, 9 when no install exists, 1 when stopped or degraded.`, +healthy, 9 when no install exists, 1 when stopped, degraded, or still coming +up.`, Args: cobra.NoArgs, RunE: func(cmd *cobra.Command, args []string) error { d := install.NewDeps(ios, fullVersion()) diff --git a/cli/internal/deploy/install/diagnose.go b/cli/internal/deploy/install/diagnose.go index 6ce0596e98..5343585478 100644 --- a/cli/internal/deploy/install/diagnose.go +++ b/cli/internal/deploy/install/diagnose.go @@ -81,6 +81,12 @@ func (f containerFacts) diagnose(status string) string { case f.Restarts >= crashLoop: return fmt.Sprintf("has restarted %d times (%s) — it is crash-looping, not starting", f.Restarts, exitReason(f.ExitCode)) + case healthDetail(status) == "waiting": + // Inside a health check's start period, failing probes are how a + // container comes up — nothing to call a fault yet. The restart count + // above is what separates a slow start from a crash loop, and it has + // already had its say. + return "" case f.probe() != "": return "is running, but its health check keeps failing: " + f.probe() case strings.Contains(status, "(unhealthy)"): diff --git a/cli/internal/deploy/install/lifecycle_test.go b/cli/internal/deploy/install/lifecycle_test.go index a1653abc0a..609e0fe5aa 100644 --- a/cli/internal/deploy/install/lifecycle_test.go +++ b/cli/internal/deploy/install/lifecycle_test.go @@ -451,7 +451,7 @@ func TestStatusExplainsEveryContainerItCounted(t *testing.T) { out := outBuf(deps).String() for _, want := range []string{ - "2 of 3 containers are not running", + "2 of 3 services are not up", "nginx was created but never started", "code-interpreter is not running (exit 0", "logs --dir " + strconv.Quote(root) + " nginx code-interpreter\n", @@ -466,6 +466,173 @@ func TestStatusExplainsEveryContainerItCounted(t *testing.T) { } } +// A crash-looping container spends half its life reading "Up N seconds +// (health: starting)": sampled in that window it looks like a service on its +// way up, and being counted as one kept it out of the very command that would +// have shown why it keeps dying. The restart count is what tells the two +// apart, so the container that is only ever caught mid-restart still has to +// land in the report — and in the logs hint under it. +func TestStatusCatchesCrashLoopBetweenRestarts(t *testing.T) { + runner := &fakeRunner{handler: healthyDockerHandler} + root := installFixture(t, runner, "v4.2.0") + + psOut := "onyx-nginx-1\tnginx:1.25.5-alpine\tUp 2 hours\t0.0.0.0:3000->80/tcp\tnginx\n" + + "onyx-api_server-1\tonyxdotapp/onyx-backend:v4.2.0\tUp 2 seconds (health: starting)\t\tapi_server\n" + inspectOut := `{"name":"/onyx-api_server-1","restarts":9,"exit":255,"oom":false,"error":"","health":null}` + statusRunner := &fakeRunner{handler: func(c dockercmd.Command) (dockercmd.Result, error) { + switch { + case strings.Contains(argv(c), "ps -a"): + return dockercmd.Result{Stdout: psOut}, nil + case strings.Contains(argv(c), "inspect"): + return dockercmd.Result{Stdout: inspectOut}, nil + } + return healthyDockerHandler(c) + }} + shimDockerOnPath(t) + deps := testDeps(t, statusRunner, notFoundServer(t)) + err := RunStatus(context.Background(), deps, Options{Dir: root}, false) + if err == nil || !strings.Contains(err.Error(), "degraded") { + t.Fatalf("err = %v, want a degraded exit", err) + } + + out := outBuf(deps).String() + for _, want := range []string{ + "1 of 2 services are not up", + "9 restarts", + "api_server has restarted 9 times (exit 255)", + "crash-looping", + "logs --dir " + strconv.Quote(root) + " api_server\n", + } { + if !strings.Contains(out, want) { + t.Errorf("output missing %q:\n%s", want, out) + } + } + if strings.Contains(out, "All 2 services are up") { + t.Errorf("a crash-looping service was counted as up:\n%s", out) + } +} + +// Half the deployment has no health check at all (background, cache, +// opensearch, code-interpreter), so between two crashes those containers read +// as a plain "Up 2 seconds" — indistinguishable from a service that has just +// come up, except for the restart count. A container that young has to be +// inspected for it, or the crash loop stays invisible for exactly as long as +// the container is alive. A container that has been serving for hours is not +// inspected: its restart count is history, not a fault. +func TestStatusCatchesCrashLoopWithoutHealthCheck(t *testing.T) { + runner := &fakeRunner{handler: healthyDockerHandler} + root := installFixture(t, runner, "v4.2.0") + + psOut := "onyx-api_server-1\tonyxdotapp/onyx-backend:v4.2.0\tUp 2 hours (healthy)\t0.0.0.0:3000->80/tcp\tapi_server\n" + + "onyx-background-1\tonyxdotapp/onyx-backend:v4.2.0\tUp 2 seconds\t\tbackground\n" + inspectOut := `{"name":"/onyx-background-1","restarts":12,"exit":1,"oom":false,"error":"","health":null}` + statusRunner := &fakeRunner{handler: func(c dockercmd.Command) (dockercmd.Result, error) { + switch { + case strings.Contains(argv(c), "ps -a"): + return dockercmd.Result{Stdout: psOut}, nil + case strings.Contains(argv(c), "inspect"): + return dockercmd.Result{Stdout: inspectOut}, nil + } + return healthyDockerHandler(c) + }} + shimDockerOnPath(t) + deps := testDeps(t, statusRunner, notFoundServer(t)) + err := RunStatus(context.Background(), deps, Options{Dir: root}, false) + if err == nil || !strings.Contains(err.Error(), "degraded") { + t.Fatalf("err = %v, want a degraded exit", err) + } + + out := outBuf(deps).String() + for _, want := range []string{ + "1 of 2 services are not up", + "background has restarted 12 times (exit 1)", + "crash-looping", + "logs --dir " + strconv.Quote(root) + " background\n", + } { + if !strings.Contains(out, want) { + t.Errorf("output missing %q:\n%s", want, out) + } + } + for _, c := range statusRunner.calls { + if strings.Contains(argv(c), "inspect") && strings.Contains(argv(c), "api_server") { + t.Errorf("a container serving for hours was inspected: %s", argv(c)) + } + } +} + +// A restart count is a container's whole history and never goes back down, so +// on its own it cannot say what is happening now: a service that looped at +// boot and has served ever since is up, and the report has to say so. +func TestStatusForgivesOldRestartsOnceServing(t *testing.T) { + runner := &fakeRunner{handler: healthyDockerHandler} + root := installFixture(t, runner, "v4.2.0") + + psOut := "onyx-api_server-1\tonyxdotapp/onyx-backend:v4.2.0\tUp 2 hours (healthy)\t0.0.0.0:3000->80/tcp\tapi_server\n" + + "onyx-background-1\tonyxdotapp/onyx-backend:v4.2.0\tUp 3 hours\t\tbackground\n" + statusRunner := &fakeRunner{handler: func(c dockercmd.Command) (dockercmd.Result, error) { + switch { + case strings.Contains(argv(c), "ps -a"): + return dockercmd.Result{Stdout: psOut}, nil + case strings.Contains(argv(c), "inspect"): + return dockercmd.Result{Stdout: `{"name":"/onyx-background-1","restarts":12,"exit":1,"oom":false,"error":"","health":null}`}, nil + } + return healthyDockerHandler(c) + }} + shimDockerOnPath(t) + deps := testDeps(t, statusRunner, notFoundServer(t)) + if err := RunStatus(context.Background(), deps, Options{Dir: root}, false); err != nil { + t.Fatalf("RunStatus: %v\noutput:\n%s", err, outBuf(deps).String()) + } + if out := outBuf(deps).String(); !strings.Contains(out, "All 2 services are up") { + t.Errorf("a recovered container is still being called a failure:\n%s", out) + } +} + +// A service inside its health check's start period is not a failure — but it +// is not up either, and a report that calls it up has nothing left to say when +// it never comes up. Its probes fail by design while it starts, so the report +// must not read those back as a fault. +func TestStatusReportsServicesStillStarting(t *testing.T) { + runner := &fakeRunner{handler: healthyDockerHandler} + root := installFixture(t, runner, "v4.2.0") + + psOut := "onyx-nginx-1\tnginx:1.25.5-alpine\tUp 3 seconds\t0.0.0.0:3000->80/tcp\tnginx\n" + + "onyx-api_server-1\tonyxdotapp/onyx-backend:v4.2.0\tUp 3 seconds (health: starting)\t\tapi_server\n" + inspectOut := `{"name":"/onyx-api_server-1","restarts":0,"exit":0,"oom":false,"error":"",` + + `"health":{"Status":"starting","FailingStreak":1,"Log":[{"ExitCode":1,"Output":"connection refused"}]}}` + statusRunner := &fakeRunner{handler: func(c dockercmd.Command) (dockercmd.Result, error) { + switch { + case strings.Contains(argv(c), "ps -a"): + return dockercmd.Result{Stdout: psOut}, nil + case strings.Contains(argv(c), "inspect"): + return dockercmd.Result{Stdout: inspectOut}, nil + } + return healthyDockerHandler(c) + }} + shimDockerOnPath(t) + deps := testDeps(t, statusRunner, notFoundServer(t)) + err := RunStatus(context.Background(), deps, Options{Dir: root}, false) + if err == nil || !strings.Contains(err.Error(), "still starting") { + t.Fatalf("err = %v, want a still-starting exit", err) + } + + out := outBuf(deps).String() + for _, want := range []string{ + "1 of 2 services are still starting", + // Nothing to explain yet, so the hint follows the logs instead. + "Follow along: onyx-cli deploy logs -f --dir " + strconv.Quote(root) + " api_server\n", + } { + if !strings.Contains(out, want) { + t.Errorf("output missing %q:\n%s", want, out) + } + } + // A probe that fails during the start period is the container starting, not + // a health check that keeps failing. + if strings.Contains(out, "health check") { + t.Errorf("start-period probes reported as a failing health check:\n%s", out) + } +} + // The hint is the one line in the report the reader is meant to act on, so // the command carries the accent and the words around it don't. func TestFailureHintHighlightsTheCommand(t *testing.T) { @@ -479,7 +646,7 @@ func TestFailureHintHighlightsTheCommand(t *testing.T) { Service: "api_server", Status: "Restarting (255) 13 seconds ago", Diagnosis: "is crash-looping", - }}, notRunning) + }}) out := outBuf(deps).String() if !strings.Contains(out, in.paint.Accent("onyx-cli deploy logs api_server")) { diff --git a/cli/internal/deploy/install/status.go b/cli/internal/deploy/install/status.go index e43c6d19c0..3f901c95af 100644 --- a/cli/internal/deploy/install/status.go +++ b/cli/internal/deploy/install/status.go @@ -58,8 +58,8 @@ func (s Service) name() string { // RunStatus implements `deploy status`. Read-only: it never provisions or // mutates anything. Exit codes make it usable as a probe: 0 when installed -// with all services up and none unhealthy, NotAvailable when no install -// exists, General when stopped or degraded. +// with every service settled and up, NotAvailable when no install exists, +// General when stopped, degraded, or still coming up. func RunStatus(ctx context.Context, deps Deps, opts Options, jsonOut bool) error { in := newInstaller(deps, opts) return in.runStatus(ctx, jsonOut) @@ -112,16 +112,18 @@ func (in *installer) runStatus(ctx context.Context, jsonOut bool) error { } in.addFailureFacts(ctx, st.Services) - up, unhealthy := 0, 0 + up, starting, failing := 0, 0, 0 for _, s := range st.Services { - if isRunning(s) { + switch s.severity() { + case sevOK: up++ - } - if isUnhealthy(s) { - unhealthy++ + case sevWatch: + starting++ + default: + failing++ } } - st.Healthy = up > 0 && up == len(st.Services) && unhealthy == 0 + st.Healthy = up > 0 && up == len(st.Services) if jsonOut { code := exitcodes.Success @@ -146,7 +148,7 @@ func (in *installer) runStatus(ctx context.Context, jsonOut bool) error { return exitcodes.New(exitcodes.General, "deployment is stopped") } for _, s := range st.Services { - sev := severityOf(s.Status) + sev := s.severity() line := fmt.Sprintf(" %s %-40s %s", sev.paint(in.paint, sev.mark()), s.Name, in.paintStatus(s.Status)) if s.Restarts >= 2 { line += in.paint.Dim(fmt.Sprintf(" · %d restarts", s.Restarts)) @@ -157,20 +159,49 @@ func (in *installer) runStatus(ctx context.Context, jsonOut bool) error { if st.AccessURL != "" { in.infof("Access Onyx at: %s", st.AccessURL) } - if unhealthy > 0 { - in.failf("%d of %d services unhealthy", unhealthy, len(st.Services)) - in.explainFailures(st.Services, isUnhealthy) - return exitcodes.New(exitcodes.General, "deployment is degraded") - } - if up < len(st.Services) { - in.failf("%d of %d containers are not running", len(st.Services)-up, len(st.Services)) - in.explainFailures(st.Services, notRunning) - return exitcodes.New(exitcodes.General, "deployment is partially stopped") + // One count, one list: every service that isn't up is worth naming, + // whichever way it isn't. Splitting the verdict by kind used to drop the + // rest of them — and a service still working through its health check was + // counted as up, which is where a crash-looping container sampled between + // two restarts went missing. + if notUp := starting + failing; notUp > 0 { + if failing > 0 { + in.failf("%d of %d services are not up", notUp, len(st.Services)) + } else { + in.warnf("%d of %d services are still starting", notUp, len(st.Services)) + } + in.explainFailures(st.Services) + return exitcodes.New(exitcodes.General, notUpReason(st.Services)) } in.successf("All %d services are up", up) return nil } +// notUpReason names the worst thing on the board, which is what the one-line +// reason a probe reads should say: a health check that is failing outranks a +// container that is missing, and both outrank a deployment that simply hasn't +// finished coming up. +func notUpReason(services []Service) string { + stopped, looping := false, false + for _, s := range services { + switch { + case isUnhealthy(s): + return "deployment is degraded" + case notRunning(s): + stopped = true + case s.crashLooping(): + looping = true + } + } + switch { + case stopped: + return "deployment is partially stopped" + case looping: + return "deployment is degraded" + } + return "deployment is still starting" +} + func (in *installer) emitStatus(st Status, code exitcodes.Code) error { data, err := json.MarshalIndent(st, "", " ") if err != nil { @@ -260,20 +291,54 @@ func drift(tags ...string) bool { return false } -// isRunning, isUnhealthy and notRunning are the tests the verdict counts -// with, so the sentences underneath it can be selected by the same rule the -// number was. -func isRunning(s Service) bool { return strings.HasPrefix(s.Status, "Up") } -func notRunning(s Service) bool { return !isRunning(s) } +// severity is how much attention this service deserves, reading the restart +// count `docker ps` doesn't show: a container past the crash-loop threshold is +// failing whatever state this sample caught it in. +// +// The restart count only settles an unsettled container, though. It counts the +// restarts the policy has had to perform over the whole life of the container +// and never goes back down, so one that looped at boot and has served for +// hours since is up, and says so. +func (s Service) severity() severity { + if s.crashLooping() && unsettled(s.Status) { + return sevBad + } + return severityOf(s.Status) +} + +func (s Service) crashLooping() bool { return s.Restarts >= crashLoop } + +// justStarted matches the uptimes docker prints for a container that came up +// moments ago: "Up Less than a second", "Up 3 seconds", "Up About a minute". +var justStarted = regexp.MustCompile(`^Up (Less than a second|\d+ seconds?|About a minute)`) + +// unsettled reports whether `docker ps` alone can't call this container up: it +// is in no state to serve, or it is in one it entered moments ago. The second +// half is what a crash loop looks like between two restarts — a service with +// no health check to fail reads as a plain "Up 2 seconds" there, which is also +// how it reads when it is simply new, and only the restart count tells those +// apart. +func unsettled(status string) bool { + return severityOf(status) != sevOK || justStarted.MatchString(status) +} + +// isUp, isUnhealthy and notRunning are the tests the verdict counts with, so +// the sentences underneath it can be selected by the same rule the number was. +// A container is up once it has settled: one still inside its health check's +// start period has not, whatever the "Up" in front of its status says. +func isUp(s Service) bool { return s.severity() == sevOK } +func notRunning(s Service) bool { return !strings.HasPrefix(s.Status, "Up") } func isUnhealthy(s Service) bool { return strings.Contains(s.Status, "(unhealthy)") } -// addFailureFacts fills in what `docker ps` left out, for the containers a -// verdict could end up reporting. Only those: the extra call costs a -// round-trip, and a service that is up and healthy has nothing to explain. +// addFailureFacts fills in what `docker ps` left out, for the containers its +// listing couldn't settle on its own. Only those: the extra call costs a +// round-trip, and a service that has been serving for hours has nothing to +// explain. It selects on the status alone — the facts it fetches are what the +// fact-aware tests above read, so it cannot ask them. func (in *installer) addFailureFacts(ctx context.Context, services []Service) { var names []string for _, s := range services { - if notRunning(s) || isUnhealthy(s) { + if unsettled(s.Status) { names = append(names, s.Name) } } @@ -293,15 +358,17 @@ func (in *installer) addFailureFacts(ctx context.Context, services []Service) { // explainFailures says what is wrong with each service the verdict above it // counted, and names the one command that shows why. Without it the worst // state on the board — a container that keeps dying — is also the only one the -// report says nothing more about. troubled is the verdict's own test, so the -// report can't claim two failures and then explain one. -func (in *installer) explainFailures(services []Service, troubled func(Service) bool) { +// report says nothing more about. It selects on isUp, the verdict's own test, +// so the report can't claim two failures and then explain one. +func (in *installer) explainFailures(services []Service) { var names []string + coming := true for _, s := range services { - if !troubled(s) { + if isUp(s) { continue } names = append(names, s.name()) + coming = coming && s.severity() == sevWatch if s.Diagnosis != "" { in.plainf(" %s %s", s.name(), s.Diagnosis) } @@ -315,6 +382,12 @@ func (in *installer) explainFailures(services []Service, troubled func(Service) if len(names) > 3 { named = "" } + // Nothing has gone wrong when every one of them is still coming up, so the + // command to offer is the one that watches them finish. + if coming { + in.infof("Follow along: %s", in.paint.Accent("onyx-cli deploy logs -f"+in.dirArg()+named)) + return + } in.infof("See why: %s", in.paint.Accent("onyx-cli deploy logs"+in.dirArg()+named)) }