Merge pull request 'A service the mesh asked to run is still running a moment later (hq ADR 0184)' (#75) from fix/a-service-asked-to-run-is-still-running into main

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
 	}

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)
+	}
+}