From 286865dfa751f43e0ab547966223ac4251db4df4 Mon Sep 17 00:00:00 2001 From: jochen Date: Fri, 2 Oct 2026 18:16:24 +0200 Subject: [PATCH] A service the mesh asked to run is still running a moment later (hq ADR 0184) The read-back raced the failure: a service manager returns when it has started the process, and a daemon that refuses its configuration exits a fraction of a second later, so one look saw it alive. fail2ban took 221ms on the control node and the apply reported "restarted" onto a dead daemon while both public machines kept no bans at all. The host looks again, after that moment. A unit still starting is accepted at both looks; a service asked to stop is not waited on. --- internal/apply/apply.go | 39 +++++++++++- internal/apply/stayed_running_test.go | 91 +++++++++++++++++++++++++++ 2 files changed, 128 insertions(+), 2 deletions(-) create mode 100644 internal/apply/stayed_running_test.go diff --git a/internal/apply/apply.go b/internal/apply/apply.go index 09c3fcd..976f0d8 100644 --- a/internal/apply/apply.go +++ b/internal/apply/apply.go @@ -1041,6 +1041,38 @@ type unitReloader interface { ReloadUnits(ctx context.Context, run system.Runner) error } +// serviceSettle is how long the host waits before looking at a unit a second time. A test sets it +// to nothing; on a machine it is the window in which a daemon that refuses its configuration dies. +var serviceSettle = 2 * time.Second + +// stayedRunning is the state of a unit the host has just asked to run, read twice. +// +// **Because the first read races the failure.** A service manager returns when it has started the +// process, and the unit is "activating" or "active" at that instant whatever the process is about +// to do. A daemon that reads its configuration, refuses it and exits does so a fraction of a second +// later — fail2ban took 221 milliseconds the day this was written — so a single read back says +// running about a machine whose daemon is already gone, and the apply reports "restarted" for a +// service that is dead. Every ban on both public machines was lost that way while every check +// passed (novox/hq ADR 0184), which is the one shape of failure this host exists to refuse. +// +// So it looks again, after the moment in which that happens. It does not wait for a slow unit to +// finish starting: a unit still coming up reads as running both times and is accepted, as before. +// What this catches is a unit that was running and is not any more. +func stayedRunning(ctx context.Context, sys system.System, run Runner, unit string) (string, error) { + state, err := sys.ServiceState(ctx, run, unit) + if err != nil || state != "running" { + return state, err + } + timer := time.NewTimer(serviceSettle) + defer timer.Stop() + select { + case <-ctx.Done(): + return state, ctx.Err() + case <-timer.C: + } + return sys.ServiceState(ctx, run, unit) +} + func applyService(ctx context.Context, sys system.System, r *declaration.Service, run Runner, changed map[string]bool, previous store.Applied) (Outcome, error) { if r.Stateless() { @@ -1120,6 +1152,9 @@ func applyService(ctx context.Context, sys system.System, r *declaration.Service // Read back. A service manager accepting a command says the transaction was accepted, // not that the unit is running — one that starts and immediately dies satisfies it. after, err := sys.ServiceState(ctx, run, r.Unit) + if err == nil && r.State == "running" { + after, err = stayedRunning(ctx, sys, run, r.Unit) + } if err != nil { return out, err } @@ -1140,7 +1175,7 @@ func applyService(ctx context.Context, sys system.System, r *declaration.Service } // Read back, for the same reason as above: a unit that starts and immediately dies // satisfies a service manager and nothing else. - after, err := sys.ServiceState(ctx, run, r.Unit) + after, err := stayedRunning(ctx, sys, run, r.Unit) if err != nil { return out, err } @@ -1230,7 +1265,7 @@ func reflectOnly(ctx context.Context, sys system.System, r *declaration.Service, } // Read back: it was running, and a restart or reload that left it otherwise is a failure — // the machine's network manager down is not a change to report and move past. - after, err := sys.ServiceState(ctx, run, r.Unit) + after, err := stayedRunning(ctx, sys, run, r.Unit) if err != nil { return out, err } diff --git a/internal/apply/stayed_running_test.go b/internal/apply/stayed_running_test.go new file mode 100644 index 0000000..9ea13f3 --- /dev/null +++ b/internal/apply/stayed_running_test.go @@ -0,0 +1,91 @@ +package apply + +import ( + "context" + "strings" + "testing" + + "github.com/novox/mesh-host/internal/store" +) + +// A daemon that reads a configuration it refuses dies a fraction of a second after the service +// manager has reported it started — fail2ban took 221 milliseconds on the control node the day this +// was written. One read back catches nothing: the unit is active at that instant. The mesh reported +// the service "restarted" while every ban on two public machines was gone, and every check passed +// (novox/hq ADR 0184). The host looks again, after the moment in which that happens. +func TestAServiceThatDiesJustAfterItsRestartIsNotReportedRestarted(t *testing.T) { + serviceSettle = 0 + // Alive at the first look after starting, dead at the second — the shape of a daemon that + // refuses what it was just given. + started, looks := false, 0 + run := func(ctx context.Context, name string, args ...string) (string, error) { + if args[0] == "show" { + state := "active" + if started { + if looks++; looks >= 2 { + state = "failed" + } + } + return "LoadState=loaded\nActiveState=" + state + "\n", nil + } + if args[0] == "start" { + started = true + } + return "", nil + } + dir := t.TempDir() + d := parse(t, `{"declaration":1,"resources":[ + {"id":"conf","type":"file","path":"`+dir+`/jail.conf","content":"[sshd]\n","mode":"0644"}, + {"id":"run","type":"service","unit":"fail2ban.service","state":"running","restart-on":["conf"]} + ]}`) + _, _, err := Apply(context.Background(), archHost(t), d, store.State{}, store.OriginCarried, run, nil, nil) + if err == nil { + t.Fatal("a service that died just after being restarted was reported as restarted") + } + if !strings.Contains(err.Error(), "fail2ban.service") || !strings.Contains(err.Error(), "is stopped") { + t.Errorf("the failure does not name the unit and what it is now: %v", err) + } + if looks < 2 { + t.Errorf("the host looked at the unit %d time(s) after starting it; it must look again", looks) + } +} + +// A unit still coming up reads as running at both looks and is accepted: the second look is for a +// unit that WAS running and is not any more, never a wait for a slow one to finish starting. +func TestAUnitStillStartingIsNotAFailure(t *testing.T) { + serviceSettle = 0 + run := func(ctx context.Context, name string, args ...string) (string, error) { + if args[0] == "show" { + return "LoadState=loaded\nActiveState=activating\n", nil + } + return "", nil + } + d := parse(t, `{"declaration":1,"resources":[ + {"id":"s","type":"service","unit":"slow.service","state":"running"} + ]}`) + if _, _, err := Apply(context.Background(), archHost(t), d, store.State{}, store.OriginCarried, run, nil, nil); err != nil { + t.Fatalf("a unit still starting was reported as a failure: %v", err) + } +} + +// And a service the declaration asks to be stopped is not waited on at all. +func TestAServiceAskedToStopIsNotWaitedOn(t *testing.T) { + serviceSettle = 0 + shows := 0 + run := func(ctx context.Context, name string, args ...string) (string, error) { + if args[0] == "show" { + shows++ + if shows == 1 { + return "LoadState=loaded\nActiveState=active\n", nil + } + return "LoadState=loaded\nActiveState=inactive\n", nil + } + return "", nil + } + d := parse(t, `{"declaration":1,"resources":[ + {"id":"s","type":"service","unit":"off.service","state":"stopped"} + ]}`) + if _, _, err := Apply(context.Background(), archHost(t), d, store.State{}, store.OriginCarried, run, nil, nil); err != nil { + t.Fatalf("stopping a service was reported as a failure: %v", err) + } +}