textmachine/platform/internal/runner/stop_systemd_test.go

package runner

import (
	"context"
	"os"
	"os/exec"
	"path/filepath"
	"strconv"
	"strings"
	"testing"
	"time"
)

// The sweep re-issues the stop of any live run it finds with an intent on file, and the comment above
// that line calls it «free and idempotent». That is a property of systemd rather than of Go, it is
// not in any manual page, and until it was measured nothing in this repository had asked it. This
// file asks it.

// signalLog is a stand-in for the engine: it catches SIGTERM, does NOT exit, and writes a line for
// every signal it receives plus a heartbeat — so a test can tell «still running» from «killed» by
// something the PROCESS said rather than by what systemd reports about it.
func signalLog(t *testing.T, dir string) string {
	t.Helper()
	if _, err := exec.LookPath("python3"); err != nil {
		t.Skip("no python3: the signal fixture cannot run on this host")
	}
	path := filepath.Join(dir, "hold.py")
	body := `import signal, sys, time
log = open(sys.argv[1], "a", buffering=1)
def note(sig, frm):
    log.write("%.3f SIGNAL\n" % time.time())
signal.signal(signal.SIGTERM, note)
signal.signal(signal.SIGINT, note)
log.write("%.3f START\n" % time.time())
while True:
    log.write("%.3f ALIVE\n" % time.time())
    time.sleep(0.25)
`
	if err := os.WriteFile(path, []byte(body), 0o600); err != nil {
		t.Fatal(err)
	}
	return path
}

// readLog counts what the fixture actually received and when it last spoke.
func readLog(t *testing.T, path string) (signals int, lastAlive time.Time) {
	t.Helper()
	raw, err := os.ReadFile(path)
	if err != nil {
		return 0, time.Time{}
	}
	for line := range strings.SplitSeq(string(raw), "\n") {
		f := strings.Fields(line)
		if len(f) != 2 {
			continue
		}
		secs, err := strconv.ParseFloat(f[0], 64)
		if err != nil {
			continue
		}
		switch f[1] {
		case "SIGNAL":
			signals++
		case "ALIVE":
			lastAlive = time.UnixMilli(int64(secs * 1000))
		}
	}
	return signals, lastAlive
}

func unitState(t *testing.T, unit string) string {
	t.Helper()
	out, err := exec.CommandContext(t.Context(), "systemctl", "--user", "show", unit+".service",
		"--property=ActiveState", "--value").CombinedOutput()
	if err != nil {
		return ""
	}
	return strings.TrimSpace(string(out))
}

// killUnit is the cleanup this fixture needs and the only shape it can take. SIGKILL rather than a
// stop, because the fixture ignores SIGTERM by design and a polite cleanup would wait out the very
// grace under test; and on a context of its OWN, because a cleanup runs after the test's context has
// been cancelled — on that one every command would refuse to start and the unit would be left behind
// in the user's manager, where it outlives the process that made it.
func killUnit(unit string) {
	ctx, cancel := context.WithTimeout(context.Background(), 10*time.Second)
	defer cancel()
	_ = exec.CommandContext(ctx, "systemctl", "--user", "kill", "--signal=SIGKILL", unit+".service").Run()
	_ = exec.CommandContext(ctx, "systemctl", "--user", "stop", "--no-block", unit+".service").Run()
}

// holdingUnit starts a transient unit whose process catches SIGTERM and never exits, under the grace
// the test names. It carries the properties this package sets on a run — KillSignal, KillMode,
// TimeoutStopSec — and the grace is a parameter because the test is ABOUT the grace's clock.
func holdingUnit(t *testing.T, grace time.Duration) (unit, log string) {
	t.Helper()
	systemdOrSkip(t)
	dir := t.TempDir()
	log = filepath.Join(dir, "signals.log")
	script := signalLog(t, dir)
	unit = testUnit(t)
	t.Cleanup(func() { killUnit(unit) })
	out, err := exec.CommandContext(t.Context(), "systemd-run", "--user", "--unit="+unit, "--collect", "--quiet",
		"--property=Slice="+Slice,
		"--property=KillSignal=SIGTERM",
		"--property=KillMode=mixed",
		"--property=TimeoutStopSec="+strconv.Itoa(int(grace.Seconds())),
		"--", "/usr/bin/env", "python3", script, log).CombinedOutput()
	if err != nil {
		t.Fatalf("could not start the holding unit: %v: %s", err, out)
	}
	// The fixture has to be running before anything is asked of it, or the test measures a race with
	// its own start instead of the property it is about.
	for deadline := time.Now().Add(15 * time.Second); time.Now().Before(deadline); {
		if _, alive := readLog(t, log); !alive.IsZero() {
			return unit, log
		}
		time.Sleep(20 * time.Millisecond)
	}
	t.Fatalf("the holding unit never started writing")
	return "", ""
}

// ⛔ WHAT THIS PINS IS AN ASSERTION THE RECONCILER ALREADY MAKES AND NOTHING CHECKED.
//
// `runs.reconcile` re-issues the stop of a live run whose intent is on file — deliberately, because
// that is the only thing that closes «the platform died between committing the intent and asking
// systemd». The comment there calls the re-issue «free and idempotent», and both words are claims
// about systemd's behaviour on a unit that is ALREADY stopping. Neither is documented.
//
//   - «free» — a second `stop` must not deliver a second signal. If it did, the sweep would signal a
//     stopping run again on every pass.
//   - «idempotent» — it must not restart TimeoutStopSec. If it did, the SIGKILL backstop would recede
//     by one pass every pass, and an engine that has wedged would hold its book's project lock for
//     good while the sweep politely asked it to stop, forever.
//
// ⚠ THE TWO ASSERTIONS ARE EACH OTHER'S CONTROL, so there is no separate one to run and no way for
// this test to pass by failing to look. «One signal» is not read as an absence: the same log proves
// the fixture DOES receive signals, because the first stop delivered one. And the unit is not merely
// «not killed early» — it IS killed, and the assertion is on WHICH clock: the first stop's, at t+6 s,
// where a restarted timer would give t+10 s.
func TestARepeatedStopNeitherSignalsNorExtendsTheGrace(t *testing.T) {
	const grace = 6 * time.Second
	unit, log := holdingUnit(t, grace)
	r := New(nil)

	start := time.Now()
	if err := r.Stop(t.Context(), unit); err != nil {
		t.Fatal(err)
	}
	for _, at := range []time.Duration{2 * time.Second, 4 * time.Second} {
		time.Sleep(time.Until(start.Add(at)))
		if err := r.Stop(t.Context(), unit); err != nil {
			t.Fatal(err)
		}
	}
	var died time.Duration
	for deadline := start.Add(grace * 3); time.Now().Before(deadline); {
		switch unitState(t, unit) {
		case "inactive", "failed", "":
			died = time.Since(start)
		}
		if died != 0 {
			break
		}
		time.Sleep(50 * time.Millisecond)
	}
	signals, _ := readLog(t, log)
	if died == 0 {
		t.Fatalf("the unit was still not gone %s after the first stop, having received %d signal(s)", grace*3, signals)
	}
	t.Logf("three stops at t+0s, t+2s, t+4s against a %s grace: the process received %d signal(s) and the unit was gone at t+%.2fs",
		grace, signals, died.Seconds())
	if signals != 1 {
		t.Errorf("the process received %d signals from three stops, want exactly 1 — zero would mean the fixture "+
			"never hears anything and this test measures nothing, and more than one means the sweep re-signals a "+
			"run on every pass", signals)
	}
	if died > grace+2*time.Second {
		t.Errorf("the unit died at t+%.2fs against a %s grace: a repeated stop restarted the stop timeout, so the "+
			"SIGKILL backstop moves further away on every sweep pass and a wedged engine keeps its project lock",
			died.Seconds(), grace)
	}
}