diff --git a/coderd/coderd.go b/coderd/coderd.go index 48483234a3..d094c05757 100644 --- a/coderd/coderd.go +++ b/coderd/coderd.go @@ -205,7 +205,7 @@ type Options struct { // tokens issued by and passed to the coordinator DRPC API. CoordinatorResumeTokenProvider tailnet.ResumeTokenProvider - HealthcheckFunc func(ctx context.Context, apiKey string) *healthsdk.HealthcheckReport + HealthcheckFunc func(ctx context.Context, apiKey string, progress *healthcheck.Progress) *healthsdk.HealthcheckReport HealthcheckTimeout time.Duration HealthcheckRefresh time.Duration WorkspaceProxiesFetchUpdater *atomic.Pointer[healthcheck.WorkspaceProxiesFetchUpdater] @@ -681,7 +681,7 @@ func New(options *Options) *API { } if options.HealthcheckFunc == nil { - options.HealthcheckFunc = func(ctx context.Context, apiKey string) *healthsdk.HealthcheckReport { + options.HealthcheckFunc = func(ctx context.Context, apiKey string, progress *healthcheck.Progress) *healthsdk.HealthcheckReport { // NOTE: dismissed healthchecks are marked in formatHealthcheck. // Not here, as this result gets cached. return healthcheck.Run(ctx, &healthcheck.ReportOptions{ @@ -709,6 +709,7 @@ func New(options *Options) *API { StaleInterval: provisionerdserver.StaleInterval, // TimeNow set to default, see healthcheck/provisioner.go }, + Progress: progress, }) } } @@ -1860,8 +1861,9 @@ type API struct { // This is used to gate features that are not yet ready for production. Experiments codersdk.Experiments - healthCheckGroup *singleflight.Group[string, *healthsdk.HealthcheckReport] - healthCheckCache atomic.Pointer[healthsdk.HealthcheckReport] + healthCheckGroup *singleflight.Group[string, *healthsdk.HealthcheckReport] + healthCheckCache atomic.Pointer[healthsdk.HealthcheckReport] + healthCheckProgress healthcheck.Progress statsReporter *workspacestats.Reporter diff --git a/coderd/coderdtest/coderdtest.go b/coderd/coderdtest/coderdtest.go index cd69cc2686..5014d3c383 100644 --- a/coderd/coderdtest/coderdtest.go +++ b/coderd/coderdtest/coderdtest.go @@ -69,6 +69,7 @@ import ( "github.com/coder/coder/v2/coderd/externalauth" "github.com/coder/coder/v2/coderd/files" "github.com/coder/coder/v2/coderd/gitsshkey" + "github.com/coder/coder/v2/coderd/healthcheck" "github.com/coder/coder/v2/coderd/httpmw" "github.com/coder/coder/v2/coderd/jobreaper" "github.com/coder/coder/v2/coderd/notifications" @@ -131,7 +132,7 @@ type Options struct { CoordinatorResumeTokenProvider tailnet.ResumeTokenProvider ConnectionLogger connectionlog.ConnectionLogger - HealthcheckFunc func(ctx context.Context, apiKey string) *healthsdk.HealthcheckReport + HealthcheckFunc func(ctx context.Context, apiKey string, progress *healthcheck.Progress) *healthsdk.HealthcheckReport HealthcheckTimeout time.Duration HealthcheckRefresh time.Duration diff --git a/coderd/debug.go b/coderd/debug.go index 4fe96f0b83..cd07fde235 100644 --- a/coderd/debug.go +++ b/coderd/debug.go @@ -83,17 +83,21 @@ func (api *API) debugDeploymentHealth(rw http.ResponseWriter, r *http.Request) { ctx, cancel := context.WithTimeout(context.Background(), api.Options.HealthcheckTimeout) defer cancel() - report := api.HealthcheckFunc(ctx, apiKey) + // Create and store progress tracker for timeout diagnostics. + report := api.HealthcheckFunc(ctx, apiKey, &api.healthCheckProgress) if report != nil { // Only store non-nil reports. api.healthCheckCache.Store(report) } + api.healthCheckProgress.Reset() return report, nil }) select { case <-ctx.Done(): + summary := api.healthCheckProgress.Summary() httpapi.Write(ctx, rw, http.StatusServiceUnavailable, codersdk.Response{ - Message: "Healthcheck is in progress and did not complete in time. Try again in a few seconds.", + Message: "Healthcheck timed out.", + Detail: summary, }) return case res := <-resChan: diff --git a/coderd/debug_test.go b/coderd/debug_test.go index 63021dcb38..c24f84923f 100644 --- a/coderd/debug_test.go +++ b/coderd/debug_test.go @@ -14,6 +14,8 @@ import ( "cdr.dev/slog/v3/sloggers/slogtest" "github.com/coder/coder/v2/coderd/coderdtest" + "github.com/coder/coder/v2/coderd/healthcheck" + "github.com/coder/coder/v2/codersdk" "github.com/coder/coder/v2/codersdk/healthsdk" "github.com/coder/coder/v2/testutil" ) @@ -28,7 +30,7 @@ func TestDebugHealth(t *testing.T) { ctx, cancel = context.WithTimeout(context.Background(), testutil.WaitShort) sessionToken string client = coderdtest.New(t, &coderdtest.Options{ - HealthcheckFunc: func(_ context.Context, apiKey string) *healthsdk.HealthcheckReport { + HealthcheckFunc: func(_ context.Context, apiKey string, _ *healthcheck.Progress) *healthsdk.HealthcheckReport { calls.Add(1) assert.Equal(t, sessionToken, apiKey) return &healthsdk.HealthcheckReport{ @@ -61,7 +63,7 @@ func TestDebugHealth(t *testing.T) { ctx, cancel = context.WithTimeout(context.Background(), testutil.WaitShort) sessionToken string client = coderdtest.New(t, &coderdtest.Options{ - HealthcheckFunc: func(_ context.Context, apiKey string) *healthsdk.HealthcheckReport { + HealthcheckFunc: func(_ context.Context, apiKey string, _ *healthcheck.Progress) *healthsdk.HealthcheckReport { calls.Add(1) assert.Equal(t, sessionToken, apiKey) return &healthsdk.HealthcheckReport{ @@ -93,19 +95,14 @@ func TestDebugHealth(t *testing.T) { // Need to ignore errors due to ctx timeout logger = slogtest.Make(t, &slogtest.Options{IgnoreErrors: true}) ctx, cancel = context.WithTimeout(context.Background(), testutil.WaitShort) + done = make(chan struct{}) client = coderdtest.New(t, &coderdtest.Options{ Logger: &logger, - HealthcheckTimeout: time.Microsecond, - HealthcheckFunc: func(context.Context, string) *healthsdk.HealthcheckReport { - t := time.NewTimer(time.Second) - defer t.Stop() - - select { - case <-ctx.Done(): - return &healthsdk.HealthcheckReport{} - case <-t.C: - return &healthsdk.HealthcheckReport{} - } + HealthcheckTimeout: time.Second, + HealthcheckFunc: func(_ context.Context, _ string, progress *healthcheck.Progress) *healthsdk.HealthcheckReport { + progress.Start("test") + <-done + return &healthsdk.HealthcheckReport{} }, }) _ = coderdtest.CreateFirstUser(t, client) @@ -115,8 +112,14 @@ func TestDebugHealth(t *testing.T) { res, err := client.Request(ctx, "GET", "/api/v2/debug/health", nil) require.NoError(t, err) defer res.Body.Close() - _, _ = io.ReadAll(res.Body) + close(done) + bs, err := io.ReadAll(res.Body) + require.NoError(t, err, "reading body") require.Equal(t, http.StatusServiceUnavailable, res.StatusCode) + var sdkResp codersdk.Response + require.NoError(t, json.Unmarshal(bs, &sdkResp), "unmarshaling sdk response") + require.Equal(t, "Healthcheck timed out.", sdkResp.Message) + require.Contains(t, sdkResp.Detail, "Still running: test (elapsed:") }) t.Run("Refresh", func(t *testing.T) { @@ -128,7 +131,7 @@ func TestDebugHealth(t *testing.T) { ctx, cancel = context.WithTimeout(context.Background(), testutil.WaitShort) client = coderdtest.New(t, &coderdtest.Options{ HealthcheckRefresh: time.Microsecond, - HealthcheckFunc: func(context.Context, string) *healthsdk.HealthcheckReport { + HealthcheckFunc: func(context.Context, string, *healthcheck.Progress) *healthsdk.HealthcheckReport { calls <- struct{}{} return &healthsdk.HealthcheckReport{} }, @@ -173,7 +176,7 @@ func TestDebugHealth(t *testing.T) { client = coderdtest.New(t, &coderdtest.Options{ HealthcheckRefresh: time.Hour, HealthcheckTimeout: time.Hour, - HealthcheckFunc: func(context.Context, string) *healthsdk.HealthcheckReport { + HealthcheckFunc: func(context.Context, string, *healthcheck.Progress) *healthsdk.HealthcheckReport { calls++ return &healthsdk.HealthcheckReport{ Time: time.Now(), @@ -207,7 +210,7 @@ func TestDebugHealth(t *testing.T) { ctx, cancel = context.WithTimeout(context.Background(), testutil.WaitShort) sessionToken string client = coderdtest.New(t, &coderdtest.Options{ - HealthcheckFunc: func(_ context.Context, apiKey string) *healthsdk.HealthcheckReport { + HealthcheckFunc: func(_ context.Context, apiKey string, _ *healthcheck.Progress) *healthsdk.HealthcheckReport { assert.Equal(t, sessionToken, apiKey) return &healthsdk.HealthcheckReport{ Time: time.Now(), diff --git a/coderd/healthcheck/healthcheck.go b/coderd/healthcheck/healthcheck.go index f33c318d33..b46f68f7f8 100644 --- a/coderd/healthcheck/healthcheck.go +++ b/coderd/healthcheck/healthcheck.go @@ -2,6 +2,9 @@ package healthcheck import ( "context" + "fmt" + "slices" + "strings" "sync" "time" @@ -10,8 +13,91 @@ import ( "github.com/coder/coder/v2/coderd/healthcheck/health" "github.com/coder/coder/v2/coderd/util/ptr" "github.com/coder/coder/v2/codersdk/healthsdk" + "github.com/coder/quartz" ) +// Progress tracks the progress of healthcheck components for timeout +// diagnostics. It records which checks have started and completed, along with +// their durations, to provide useful information when a healthcheck times out. +// The zero value is usable. +type Progress struct { + Clock quartz.Clock + mu sync.Mutex + checks map[string]*checkStatus +} + +type checkStatus struct { + startedAt time.Time + completedAt time.Time +} + +// Start records that a check has started. +func (p *Progress) Start(name string) { + p.mu.Lock() + defer p.mu.Unlock() + if p.Clock == nil { + p.Clock = quartz.NewReal() + } + if p.checks == nil { + p.checks = make(map[string]*checkStatus) + } + p.checks[name] = &checkStatus{startedAt: p.Clock.Now()} +} + +// Complete records that a check has finished. +func (p *Progress) Complete(name string) { + p.mu.Lock() + defer p.mu.Unlock() + if p.Clock == nil { + p.Clock = quartz.NewReal() + } + if p.checks == nil { + p.checks = make(map[string]*checkStatus) + } + if p.checks[name] == nil { + p.checks[name] = &checkStatus{startedAt: p.Clock.Now()} + } + p.checks[name].completedAt = p.Clock.Now() +} + +// Reset clears all recorded check statuses. +func (p *Progress) Reset() { + p.mu.Lock() + defer p.mu.Unlock() + p.checks = make(map[string]*checkStatus) +} + +// Summary returns a human-readable summary of check progress. +// Example: "Completed: AccessURL (95ms), Database (120ms). Still running: DERP, Websocket" +func (p *Progress) Summary() string { + p.mu.Lock() + defer p.mu.Unlock() + + var completed, running []string + for name, status := range p.checks { + if status.completedAt.IsZero() { + elapsed := p.Clock.Now().Sub(status.startedAt).Round(time.Millisecond) + running = append(running, fmt.Sprintf("%s (elapsed: %dms)", name, elapsed.Milliseconds())) + continue + } + duration := status.completedAt.Sub(status.startedAt).Round(time.Millisecond) + completed = append(completed, fmt.Sprintf("%s (%dms)", name, duration.Milliseconds())) + } + + // Sort for consistent output. + slices.Sort(completed) + slices.Sort(running) + + var parts []string + if len(completed) > 0 { + parts = append(parts, "Completed: "+strings.Join(completed, ", ")) + } + if len(running) > 0 { + parts = append(parts, "Still running: "+strings.Join(running, ", ")) + } + return strings.Join(parts, ". ") +} + type Checker interface { DERP(ctx context.Context, opts *derphealth.ReportOptions) healthsdk.DERPHealthReport AccessURL(ctx context.Context, opts *AccessURLReportOptions) healthsdk.AccessURLReport @@ -30,6 +116,10 @@ type ReportOptions struct { ProvisionerDaemons ProvisionerDaemonsReportDeps Checker Checker + + // Progress tracks healthcheck progress for timeout diagnostics. + // If set, each check will record its start and completion time. + Progress *Progress } type defaultChecker struct{} @@ -89,6 +179,10 @@ func Run(ctx context.Context, opts *ReportOptions) *healthsdk.HealthcheckReport } }() + if opts.Progress != nil { + opts.Progress.Start("DERP") + defer opts.Progress.Complete("DERP") + } report.DERP = opts.Checker.DERP(ctx, &opts.DerpHealth) }() @@ -101,6 +195,10 @@ func Run(ctx context.Context, opts *ReportOptions) *healthsdk.HealthcheckReport } }() + if opts.Progress != nil { + opts.Progress.Start("AccessURL") + defer opts.Progress.Complete("AccessURL") + } report.AccessURL = opts.Checker.AccessURL(ctx, &opts.AccessURL) }() @@ -113,6 +211,10 @@ func Run(ctx context.Context, opts *ReportOptions) *healthsdk.HealthcheckReport } }() + if opts.Progress != nil { + opts.Progress.Start("Websocket") + defer opts.Progress.Complete("Websocket") + } report.Websocket = opts.Checker.Websocket(ctx, &opts.Websocket) }() @@ -125,6 +227,10 @@ func Run(ctx context.Context, opts *ReportOptions) *healthsdk.HealthcheckReport } }() + if opts.Progress != nil { + opts.Progress.Start("Database") + defer opts.Progress.Complete("Database") + } report.Database = opts.Checker.Database(ctx, &opts.Database) }() @@ -137,6 +243,10 @@ func Run(ctx context.Context, opts *ReportOptions) *healthsdk.HealthcheckReport } }() + if opts.Progress != nil { + opts.Progress.Start("WorkspaceProxy") + defer opts.Progress.Complete("WorkspaceProxy") + } report.WorkspaceProxy = opts.Checker.WorkspaceProxy(ctx, &opts.WorkspaceProxy) }() @@ -149,6 +259,10 @@ func Run(ctx context.Context, opts *ReportOptions) *healthsdk.HealthcheckReport } }() + if opts.Progress != nil { + opts.Progress.Start("ProvisionerDaemons") + defer opts.Progress.Complete("ProvisionerDaemons") + } report.ProvisionerDaemons = opts.Checker.ProvisionerDaemons(ctx, &opts.ProvisionerDaemons) }() diff --git a/coderd/healthcheck/healthcheck_test.go b/coderd/healthcheck/healthcheck_test.go index 2b49b3215e..18407298d1 100644 --- a/coderd/healthcheck/healthcheck_test.go +++ b/coderd/healthcheck/healthcheck_test.go @@ -3,6 +3,7 @@ package healthcheck_test import ( "context" "testing" + "time" "github.com/stretchr/testify/assert" @@ -10,6 +11,7 @@ import ( "github.com/coder/coder/v2/coderd/healthcheck/derphealth" "github.com/coder/coder/v2/coderd/healthcheck/health" "github.com/coder/coder/v2/codersdk/healthsdk" + "github.com/coder/quartz" ) type testChecker struct { @@ -533,3 +535,69 @@ func TestHealthcheck(t *testing.T) { }) } } + +func TestCheckProgress(t *testing.T) { + t.Parallel() + + t.Run("Summary", func(t *testing.T) { + t.Parallel() + + mClock := quartz.NewMock(t) + progress := healthcheck.Progress{Clock: mClock} + + // Start some checks + progress.Start("Database") + progress.Start("DERP") + progress.Start("AccessURL") + + // Advance time to simulate check duration + mClock.Advance(100 * time.Millisecond) + + // Complete some checks + progress.Complete("Database") + progress.Complete("AccessURL") + + summary := progress.Summary() + + // Verify completed and running checks are listed with duration / elapsed + assert.Equal(t, summary, "Completed: AccessURL (100ms), Database (100ms). Still running: DERP (elapsed: 100ms)") + }) + + t.Run("EmptyProgress", func(t *testing.T) { + t.Parallel() + + mClock := quartz.NewMock(t) + progress := healthcheck.Progress{Clock: mClock} + summary := progress.Summary() + + // Should be empty string when nothing tracked + assert.Empty(t, summary) + }) + + t.Run("AllCompleted", func(t *testing.T) { + t.Parallel() + + mClock := quartz.NewMock(t) + progress := healthcheck.Progress{Clock: mClock} + progress.Start("Database") + progress.Start("DERP") + mClock.Advance(50 * time.Millisecond) + progress.Complete("Database") + progress.Complete("DERP") + + summary := progress.Summary() + assert.Equal(t, summary, "Completed: DERP (50ms), Database (50ms)") + }) + + t.Run("AllRunning", func(t *testing.T) { + t.Parallel() + + mClock := quartz.NewMock(t) + progress := healthcheck.Progress{Clock: mClock} + progress.Start("Database") + progress.Start("DERP") + + summary := progress.Summary() + assert.Equal(t, summary, "Still running: DERP (elapsed: 0ms), Database (elapsed: 0ms)") + }) +}