Skip to content

Commit fd38b3b

Browse files
authored
fix(health): report degraded while a configured job is not scheduled, and finish shutdown (#781)
Closes #780. Follows from the #773 discussion: the daemon should not refuse to start on a rejected job, but it should stop claiming to be fine. ## The check could not see the failure it existed to report ```go func (hc *HealthChecker) checkScheduler() { check := HealthCheck{Name: "scheduler", Status: HealthStatusHealthy, Message: "Scheduler is operational"} // In a real implementation, this would check the actual scheduler // For now, we'll assume it's healthy if the service is running ``` A daemon with a mistyped schedule — a job that never fires — served a green `/health`, which is the probe `docs/INTEGRATION_PATTERNS.md` tells operators to point a container healthcheck at. After #777 the rejection is on stderr at startup, and nothing a monitoring system polls reflected it. Log lines get read once someone already suspects a problem. ## Where the state lives, and why there The scheduler records the jobs it refuses, keyed by name with the reason. Recording it in the scheduler rather than in the config loader is what makes this cover **jobs added long after startup** from Docker labels (`--docker-poll-interval`), not only those read from the INI at boot — every path that adds a job goes through `AddJob`. A name that later registers clears its own entry, as does removing the job, so a corrected config reloaded at runtime recovers **without a restart** instead of staying degraded until someone notices. ## Degraded, not unhealthy Per the comment at `health.go:24`, only `unhealthy` makes `/ready` answer 503. Taking a daemon out of rotation because one job of twenty has a typo would trade a silent failure for a louder one. `degraded` appears in the body of `/health` and `/healthz`, where an operator or an alert rule can act on it, while the jobs that do work keep running. ## Verified against a running daemon One good job and one unschedulable one: ```json { "status": "degraded", "checks": { "scheduler": { "status": "degraded", "message": "1 configured job(s) are not scheduled and will not run: broken" } } } ``` `/ready` still answers **200**. With both jobs valid it reports `healthy` with the original message. A checker constructed without a scheduler reports `degraded` rather than `healthy` — claiming health it has not established is the habit that made the old stub useless. That widens `NewHealthChecker` by one parameter; the callers in tests pass `nil`. ## Test plan - [x] `go test ./...` — green - [x] `go test -race -tags=e2e ./e2e/...` — green - [x] `golangci-lint run` incl. `--build-tags="e2e unix"` — 0 issues - [x] `lefthook run pre-push` — exit 0 - [x] Both directions checked against the real binary and its HTTP endpoints, including that `/ready` stays 200 - [x] Recovery covered: a refused job that later registers clears the complaint --- ## Follow-up from review Addressing the review found two further defects, both in the same family as the one above — a mechanism that looked like it worked because nothing checked whether it did. ### The health checker's loop could not be stopped `runPeriodicChecks` ran `for range ticker.C` with no exit. Harmless for the daemon's single instance, a leaked goroutine per case in tests. `Stop()` ends it, and the daemon calls it via a shutdown hook. ### Shutdown ended the process before its hooks had run Wiring that hook up showed it never ran. The daemon ended the process on `ShutdownChan`, which is closed when shutdown **starts**: ```go <-c.shutdownManager.ShutdownChan() // Give some time for graceful shutdown to complete <- it does not c.closeDone() ``` So only the first priority group ever executed. The web server has a hook registered to stop it gracefully, and that hook was killed mid-flight along with any request in progress. Measured on a release build, `SIGTERM` reached the end of shutdown in **0 of 5 runs**; with the fix, **5 of 5**. The e2e test that covers shutdown asserted on the substring `"graceful shutdown"` — which also matches `"Starting graceful shutdown"`, logged *before* the first hook. That is why it stayed green. It now requires the completion line. One caveat worth stating plainly: the e2e harness builds with `-race`, and the instrumentation reliably flips this race (5 of 5 runs complete even on the broken code). So the strengthened e2e assertion would **not** have caught this regression by itself. The deterministic guard is `TestShutdownDoneClosesOnlyAfterEveryHookRan` in `core`. ### `/health` reported a version of `1.0.0` for every build Hardcoded at the call site, so the endpoint could not be used to tell which ofelia was answering. It now reports the build's version, or `dev` when there are no ldflags. ## Verification of the follow-up ``` $ ofelia daemon --config=… (log-level=debug, web enabled), then SIGTERM Executing shutdown hook: scheduler (priority: 10) ... completed successfully Executing shutdown hook: http-server (priority: 20) ... completed successfully Executing shutdown hook: health-checker (priority: 30) ... completed successfully Graceful shutdown completed successfully ``` Before the fix, that log ended after the `scheduler` hook.
2 parents 4130200 + 86746a9 commit fd38b3b

13 files changed

Lines changed: 446 additions & 26 deletions

cli/daemon.go

Lines changed: 26 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -163,7 +163,25 @@ func (c *DaemonCommand) boot() (err error) {
163163
if c.dockerHandler != nil {
164164
dockerProvider = c.dockerHandler.GetDockerProvider()
165165
}
166-
c.healthChecker = web.NewHealthChecker(dockerProvider, "1.0.0")
166+
// The version was hardcoded to "1.0.0", so /health reported the same
167+
// number for every build ever shipped and could not be used to tell which
168+
// ofelia was answering. Dev builds have no ldflags and say so.
169+
reportedVersion := Version
170+
if reportedVersion == "" {
171+
reportedVersion = "dev"
172+
}
173+
c.healthChecker = web.NewHealthChecker(dockerProvider, c.scheduler, reportedVersion)
174+
175+
// Stop the checker's periodic loop on shutdown, after the server that
176+
// serves its result has gone (priority 20).
177+
c.shutdownManager.RegisterHook(core.ShutdownHook{
178+
Name: "health-checker",
179+
Priority: 30,
180+
Hook: func(context.Context) error {
181+
c.healthChecker.Stop()
182+
return nil
183+
},
184+
})
167185

168186
// Create graceful scheduler with shutdown support
169187
gracefulScheduler := core.NewGracefulScheduler(c.scheduler, c.shutdownManager)
@@ -264,11 +282,14 @@ func (c *DaemonCommand) start() error {
264282
// Start listening for shutdown signals
265283
c.shutdownManager.ListenForShutdown()
266284

267-
// Set up a goroutine to close done channel when shutdown completes
285+
// Set up a goroutine to close done channel when shutdown completes.
286+
//
287+
// This waited on ShutdownChan, which is closed when shutdown *starts*, so
288+
// the process exited while the hooks were still running: only the first
289+
// priority group (the scheduler) ever ran, and the web server was never
290+
// stopped gracefully despite the hook registered for it.
268291
go func() {
269-
<-c.shutdownManager.ShutdownChan()
270-
// Give some time for graceful shutdown to complete
271-
// The shutdown manager handles the actual shutdown process
292+
<-c.shutdownManager.Done()
272293
c.closeDone()
273294
}()
274295

core/scheduler.go

Lines changed: 46 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -58,9 +58,15 @@ type Scheduler struct {
5858
retryExecutor *RetryExecutor
5959
jobsByName map[string]Job
6060
disabledNames map[string]struct{}
61-
metricsRecorder MetricsRecorder
62-
clock Clock
63-
onJobComplete func(jobName string, success bool)
61+
// unschedulable records jobs the scheduler refused, keyed by name with the
62+
// reason as the value. A refused job never runs, and the only earlier trace
63+
// was a log line; keeping it here lets the health report say so, and covers
64+
// jobs added long after startup from Docker labels as well as those from
65+
// the config.
66+
unschedulable map[string]string
67+
metricsRecorder MetricsRecorder
68+
clock Clock
69+
onJobComplete func(jobName string, success bool)
6470
}
6571

6672
// concurrencySemaphore holds a swappable semaphore channel used by the
@@ -342,6 +348,7 @@ func (s *Scheduler) AddJob(j Job) error {
342348
// on demand via RunJob() which delegates to go-cron's TriggerEntryByName().
343349
func (s *Scheduler) AddJobWithTags(j Job, tags ...string) error {
344350
if j.GetSchedule() == "" {
351+
s.recordUnschedulable(j.GetName(), ErrEmptySchedule)
345352
return ErrEmptySchedule
346353
}
347354

@@ -365,12 +372,17 @@ func (s *Scheduler) AddJobWithTags(j Job, tags ...string) error {
365372
"Failed to register job %q - %q - %q",
366373
j.GetName(), j.GetCommand(), j.GetSchedule(),
367374
))
375+
s.recordUnschedulable(j.GetName(), err)
368376
return fmt.Errorf("add cron job: %w", err)
369377
}
370378
j.SetCronJobID(uint64(id))
371379
s.mu.Lock()
372380
s.Jobs = append(s.Jobs, j)
373381
s.jobsByName[j.GetName()] = j
382+
// A name that registers now is no longer unschedulable: a corrected config
383+
// reloaded at runtime has to clear the old complaint, or the health report
384+
// would stay degraded until a restart.
385+
delete(s.unschedulable, j.GetName())
374386
s.mu.Unlock()
375387

376388
if IsTriggeredSchedule(j.GetSchedule()) {
@@ -408,6 +420,9 @@ func (s *Scheduler) RemoveJob(j Job) error {
408420
}
409421
}
410422
delete(s.jobsByName, j.GetName())
423+
// A job removed from the config is no longer expected to run, so a past
424+
// refusal stops being a complaint about the current state.
425+
delete(s.unschedulable, j.GetName())
411426
delete(s.disabledNames, j.GetName())
412427
s.Removed = append(s.Removed, j)
413428
s.mu.Unlock()
@@ -635,6 +650,34 @@ func (s *Scheduler) GetActiveJobs() []Job {
635650
return jobs
636651
}
637652

653+
// recordUnschedulable notes that a job was refused, so the health report can
654+
// say a configured job is not running rather than leaving it to whoever reads
655+
// the startup log.
656+
func (s *Scheduler) recordUnschedulable(name string, reason error) {
657+
if name == "" {
658+
return
659+
}
660+
s.mu.Lock()
661+
defer s.mu.Unlock()
662+
if s.unschedulable == nil {
663+
s.unschedulable = make(map[string]string)
664+
}
665+
s.unschedulable[name] = reason.Error()
666+
}
667+
668+
// GetUnschedulableJobs returns a copy of the jobs the scheduler refused,
669+
// keyed by job name with the reason as the value. Empty means every job that
670+
// was offered is registered.
671+
func (s *Scheduler) GetUnschedulableJobs() map[string]string {
672+
s.mu.RLock()
673+
defer s.mu.RUnlock()
674+
out := make(map[string]string, len(s.unschedulable))
675+
for name, reason := range s.unschedulable {
676+
out[name] = reason
677+
}
678+
return out
679+
}
680+
638681
// getJob finds a job in the provided slice by name.
639682
func getJob(jobs []Job, name string) (Job, int) {
640683
for i, j := range jobs {
Lines changed: 68 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,68 @@
1+
// Copyright (c) 2025-2026 Netresearch DTT GmbH
2+
// SPDX-License-Identifier: MIT
3+
4+
package core
5+
6+
import (
7+
"testing"
8+
9+
"github.com/stretchr/testify/assert"
10+
"github.com/stretchr/testify/require"
11+
)
12+
13+
// A refused job is remembered so /health can name it. That memory has to end
14+
// when the job does, or an operator who fixed the problem by deleting the job
15+
// would be left with a permanently degraded daemon and no job to blame it on.
16+
17+
func TestSchedulerRecordsRefusedJob(t *testing.T) {
18+
t.Parallel()
19+
20+
job := &TestJob{}
21+
job.Name = "broken"
22+
job.Schedule = "not-a-schedule"
23+
24+
sc := NewScheduler(newDiscardLogger())
25+
require.Error(t, sc.AddJob(job))
26+
27+
refused := sc.GetUnschedulableJobs()
28+
require.Contains(t, refused, "broken")
29+
assert.NotEmpty(t, refused["broken"], "the recorded reason is what makes the report actionable")
30+
}
31+
32+
// TestSchedulerRemoveJobClearsUnschedulable covers the removal half: dropping
33+
// the job from the config has to drop the complaint with it.
34+
func TestSchedulerRemoveJobClearsUnschedulable(t *testing.T) {
35+
t.Parallel()
36+
37+
job := &TestJob{}
38+
job.Name = "broken"
39+
job.Schedule = "not-a-schedule"
40+
41+
sc := NewScheduler(newDiscardLogger())
42+
require.Error(t, sc.AddJob(job))
43+
require.Contains(t, sc.GetUnschedulableJobs(), "broken")
44+
45+
require.NoError(t, sc.RemoveJob(job))
46+
47+
assert.NotContains(t, sc.GetUnschedulableJobs(), "broken",
48+
"a job removed from the config still held /health degraded")
49+
}
50+
51+
// TestSchedulerGetUnschedulableJobsIsACopy pins that callers cannot reach into
52+
// the scheduler's state through the returned map: the health checker reads it
53+
// on every check, and a shared map would be a data race as well as a way to
54+
// silently erase a refusal.
55+
func TestSchedulerGetUnschedulableJobsIsACopy(t *testing.T) {
56+
t.Parallel()
57+
58+
job := &TestJob{}
59+
job.Name = "broken"
60+
job.Schedule = "not-a-schedule"
61+
62+
sc := NewScheduler(newDiscardLogger())
63+
require.Error(t, sc.AddJob(job))
64+
65+
delete(sc.GetUnschedulableJobs(), "broken")
66+
67+
assert.Contains(t, sc.GetUnschedulableJobs(), "broken")
68+
}

core/shutdown.go

Lines changed: 15 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -22,6 +22,7 @@ type ShutdownManager struct {
2222
hooks []ShutdownHook
2323
mu sync.Mutex
2424
shutdownChan chan struct{}
25+
doneChan chan struct{}
2526
isShuttingDown bool
2627
logger *slog.Logger
2728
}
@@ -43,6 +44,7 @@ func NewShutdownManager(logger *slog.Logger, timeout time.Duration) *ShutdownMan
4344
timeout: timeout,
4445
hooks: make([]ShutdownHook, 0),
4546
shutdownChan: make(chan struct{}),
47+
doneChan: make(chan struct{}),
4648
logger: logger,
4749
}
4850
}
@@ -89,6 +91,10 @@ func (sm *ShutdownManager) Shutdown() error {
8991
sm.isShuttingDown = true
9092
sm.mu.Unlock()
9193

94+
// Only one caller ever gets past the guard above, so this closes once and
95+
// covers every return path below, including the timeout.
96+
defer close(sm.doneChan)
97+
9298
sm.logger.Info(fmt.Sprintf("Starting graceful shutdown (timeout: %v)", sm.timeout))
9399

94100
// Create context with timeout
@@ -181,6 +187,15 @@ func (sm *ShutdownManager) ShutdownChan() <-chan struct{} {
181187
return sm.shutdownChan
182188
}
183189

190+
// Done returns a channel that's closed once every hook has run.
191+
//
192+
// ShutdownChan only says shutdown *began* — it is closed before the first hook
193+
// executes. Anything that ends the process must wait on this instead, or the
194+
// later priority groups are killed mid-flight and never run at all.
195+
func (sm *ShutdownManager) Done() <-chan struct{} {
196+
return sm.doneChan
197+
}
198+
184199
// IsShuttingDown returns true if shutdown is in progress
185200
func (sm *ShutdownManager) IsShuttingDown() bool {
186201
sm.mu.Lock()

core/shutdown_done_test.go

Lines changed: 87 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,87 @@
1+
// Copyright (c) 2025-2026 Netresearch DTT GmbH
2+
// SPDX-License-Identifier: MIT
3+
4+
package core
5+
6+
import (
7+
"context"
8+
"sync"
9+
"testing"
10+
"time"
11+
12+
"github.com/stretchr/testify/assert"
13+
"github.com/stretchr/testify/require"
14+
)
15+
16+
// The daemon ends the process when it sees shutdown finish. It used to watch
17+
// ShutdownChan, which is closed *before* the first hook runs, so everything
18+
// after the first priority group was killed mid-flight — the web server was
19+
// never stopped gracefully even though a hook was registered to do it. Done is
20+
// the signal that actually means finished, and these pin that meaning.
21+
22+
func TestShutdownDoneClosesOnlyAfterEveryHookRan(t *testing.T) {
23+
t.Parallel()
24+
25+
sm := NewShutdownManager(newDiscardLogger(), 5*time.Second)
26+
27+
var mu sync.Mutex
28+
var ran []string
29+
for _, h := range []struct {
30+
name string
31+
priority int
32+
}{{"first", 10}, {"second", 20}} {
33+
sm.RegisterHook(ShutdownHook{
34+
Name: h.name,
35+
Priority: h.priority,
36+
Hook: func(context.Context) error {
37+
mu.Lock()
38+
defer mu.Unlock()
39+
ran = append(ran, h.name)
40+
return nil
41+
},
42+
})
43+
}
44+
45+
select {
46+
case <-sm.Done():
47+
t.Fatal("Done was closed before shutdown had even started")
48+
default:
49+
}
50+
51+
require.NoError(t, sm.Shutdown())
52+
53+
select {
54+
case <-sm.Done():
55+
default:
56+
t.Fatal("Done was not closed once Shutdown returned")
57+
}
58+
59+
mu.Lock()
60+
defer mu.Unlock()
61+
assert.Equal(t, []string{"first", "second"}, ran,
62+
"every priority group has to run, in order, before Done closes")
63+
}
64+
65+
// TestShutdownDoneClosesWhenAHookTimesOut pins the other half: a hook that
66+
// overruns the deadline must not leave whoever waits on Done blocked forever.
67+
func TestShutdownDoneClosesWhenAHookTimesOut(t *testing.T) {
68+
t.Parallel()
69+
70+
sm := NewShutdownManager(newDiscardLogger(), 50*time.Millisecond)
71+
sm.RegisterHook(ShutdownHook{
72+
Name: "overruns",
73+
Priority: 10,
74+
Hook: func(ctx context.Context) error {
75+
<-ctx.Done()
76+
return ctx.Err()
77+
},
78+
})
79+
80+
require.Error(t, sm.Shutdown())
81+
82+
select {
83+
case <-sm.Done():
84+
case <-time.After(2 * time.Second):
85+
t.Fatal("Done stayed open after a hook overran the shutdown timeout")
86+
}
87+
}

e2e/graceful_shutdown_test.go

Lines changed: 17 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -29,7 +29,16 @@ func TestE2E_GracefulShutdown_SIGTERM(t *testing.T) {
2929
`
3030

3131
configPath := writeConfig(t, configBody)
32-
daemon := startDaemon(t, configPath)
32+
// The web server is enabled so the shutdown exercises more than one hook
33+
// priority group, which is what the completion assertion below is about.
34+
//
35+
// It is worth knowing what this test can and cannot catch: exiting without
36+
// waiting for the hooks is a race, and a release build loses it every time
37+
// (measured 0/5 completions), but this harness builds with -race, whose
38+
// instrumentation reliably flips the outcome (5/5). So the assertion below
39+
// would not have failed on the broken code here. The deterministic guard
40+
// for that is TestShutdownDoneClosesOnlyAfterEveryHookRan in core.
41+
daemon := startDaemon(t, configPath, "--enable-web", "--web-address="+reserveLoopbackAddr(t))
3342
defer daemon.shutdown(t, 10*time.Second) // safety net in case signal is lost
3443

3544
// Let the scheduler tick at least once so there is actual work to
@@ -64,10 +73,16 @@ func TestE2E_GracefulShutdown_SIGTERM(t *testing.T) {
6473

6574
// Verify the shutdown banner is emitted — proves the signal reached
6675
// ShutdownManager rather than the process being killed by a harness.
76+
//
77+
// The second needle used to be "graceful shutdown", which also matches
78+
// "Starting graceful shutdown" — logged *before* the first hook runs. So
79+
// this passed while the daemon exited mid-shutdown and every hook group
80+
// after the first was killed in flight. Only the completion line requires
81+
// that all of them actually finished.
6782
out := daemon.stdout.String()
6883
for _, needle := range []string{
6984
"Received shutdown signal",
70-
"graceful shutdown",
85+
"Graceful shutdown completed successfully",
7186
} {
7287
if !strings.Contains(out, needle) {
7388
t.Errorf("expected shutdown log to mention %q, got:\nstdout=%s",

web/auth_integration_test.go

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -106,7 +106,7 @@ func TestServerWithAuthEnabled(t *testing.T) {
106106

107107
t.Run("health_endpoints_bypass_auth", func(t *testing.T) {
108108
endpoints := []string{"/health", "/healthz", "/ready", "/live"}
109-
hc := webpkg.NewHealthChecker(nil, "test")
109+
hc := webpkg.NewHealthChecker(nil, nil, "test")
110110
srv.RegisterHealthEndpoints(hc)
111111

112112
for _, ep := range endpoints {

0 commit comments

Comments
 (0)