diff --git a/cmd/felhom-agent/main.go b/cmd/felhom-agent/main.go index 4021080..f4daa04 100644 --- a/cmd/felhom-agent/main.go +++ b/cmd/felhom-agent/main.go @@ -870,11 +870,10 @@ func runDaemon(cfg config.Config, logger *slog.Logger, logRing *applog.Ring) int "interval_s", hcfg.PollSeconds) // hub key intentionally not logged // R-868 (v0.144.0): an OS pass whose agent was killed kept its report on disk — send it now (a pass that starts // first sends it itself; the pass lock keeps the two apart). - go func() { - if n := osLeg.SendUnsent(ctx); n > 0 { - logger.Info("osupdate: sent kept report(s) at start", "count", n) - } - }() + // v0.144.1: and again every 5 minutes — the wrapper of a killed pass can finish AFTER the restart (measured). + go osLeg.SendUnsentLoop(ctx, 5*time.Minute, func(n int) { + logger.Info("osupdate: sent kept report(s)", "count", n) + }) // Reconcile (slice 4) runs alongside the hub loop, sharing the per-guest queue // (doc 03 §10). At slice 4 the desired-state provider is empty (no hub serving diff --git a/configs/felhom-os-apply b/configs/felhom-os-apply index 1a410c0..e44b3dd 100755 --- a/configs/felhom-os-apply +++ b/configs/felhom-os-apply @@ -263,7 +263,14 @@ class Runner: os.replace(tmp, NONCE_FILE) def log(self, line): - print(line, file=sys.stderr, flush=True) + # R-868 (v0.144.1): the agent that reads stderr may be GONE (killed mid-pass, measured live on demo-hp + # 2026-10-05): the write then raises BrokenPipeError, and v0.144.0 died right there — after apt had installed + # everything, before the report copy was saved. A dead reader must never stop the pass; the journal still + # gets every line. Pinned by AgentDiesMidPass. + try: + print(line, file=sys.stderr, flush=True) + except OSError: + pass try: subprocess.run(["logger", "-t", "felhom-os-apply", line], timeout=10) except Exception: @@ -1453,7 +1460,11 @@ def main(argv, runner=None, environ=None): r.save_report(argv[2], a.report) except Exception as e: r.log(f"os-apply: the report copy could not be saved (the run is unaffected): {e}") - print("OSAPPLY-REPORT " + json.dumps(a.report, sort_keys=True)) + try: + print("OSAPPLY-REPORT " + json.dumps(a.report, sort_keys=True), flush=True) + except OSError: + # R-868: nobody reads stdout any more (the agent was killed); the copy above carries the report. + sys.stdout = open(os.devnull, "w") return rc diff --git a/configs/test_felhom_os_apply.py b/configs/test_felhom_os_apply.py index 2e96ce1..6228f8b 100644 --- a/configs/test_felhom_os_apply.py +++ b/configs/test_felhom_os_apply.py @@ -1077,3 +1077,49 @@ class SaveReportOnDisk(unittest.TestCase): with self.assertRaises(OSError): self.r.save_report(os.path.join(link, "plan-r3-guest-apply.json"), {"mode": "apply"}) self.assertEqual(os.listdir(real), []) + + +class AgentDiesMidPass(unittest.TestCase): + """R-868, MEASURED LIVE 2026-10-05 05:45 UTC on demo-hp (agent v0.144.0): the agent was kill -9-ed while apt-get + ran; apt finished all 13 packages, but the wrapper's next log line went to a stderr pipe nobody reads any more -> + BrokenPipeError -> the wrapper died before save_report: no DONE in the journal, no kept copy, no report. + COMPANION RED-PROOF: let Runner.log write to stderr unguarded -> this test fails (BrokenPipeError).""" + + def test_a_dead_reader_does_not_stop_the_report_copy(self): + import io, sys, contextlib + + class DeadPipe(io.TextIOBase): + dead = False + def write(self, s): + if DeadPipe.dead: + raise BrokenPipeError(32, "Broken pipe") + return len(s) + def flush(self): + if DeadPipe.dead: + raise BrokenPipeError(32, "Broken pipe") + + class DyingFake(Fake): + def emulate(self, argv): + a = [x for x in argv if not re.match(r"^[A-Z_]+=", x) and x != "env"] + if a and a[0] == "apt-get" and "install" in a and "-s" not in a and "--print-uris" not in a: + DeadPipe.dead = True # the agent is killed while apt-get runs + return super().emulate(argv) + + f = DyingFake() + journal = [] + f.log = lambda line: osapply.Runner.log(f, line) # the REAL log(): stderr, then the journal + prev_run = osapply.subprocess.run + osapply.subprocess.run = lambda argv, *a, **kw: (journal.append(argv[-1]) if argv[0] == "logger" + else prev_run(argv, *a, **kw)) # never the real `logger` + prev_err, prev_out = sys.stderr, sys.stdout + sys.stderr, sys.stdout = DeadPipe(), DeadPipe() + try: + rc = osapply.main(["felhom-os-apply", "--plan", PLAN], runner=f) + finally: + sys.stderr, sys.stdout = prev_err, prev_out + osapply.subprocess.run = prev_run + DeadPipe.dead = False + self.assertEqual(rc, 0) + self.assertEqual(len(f.saved_reports), 1, "the kept copy is the only way this report reaches the hub") + self.assertEqual(len(f.saved_reports[0][1]["upgraded"]), 2) + self.assertTrue(any(l.startswith("os-apply: DONE") for l in journal), "the journal must still get the DONE line") diff --git a/internal/osupdate/unsent.go b/internal/osupdate/unsent.go index 2ce49b0..e476b3d 100644 --- a/internal/osupdate/unsent.go +++ b/internal/osupdate/unsent.go @@ -7,6 +7,7 @@ import ( "path/filepath" "strings" "syscall" + "time" "gitea.dooplex.hu/admin/felhom-agent/internal/hub" ) @@ -62,6 +63,24 @@ func (l *Leg) SendUnsent(ctx context.Context) int { return l.sendUnsentLocked(ctx) } +// SendUnsentLoop runs SendUnsent now and then every `every` until ctx ends (v0.144.1). MEASURED live on demo-hp +// 2026-10-05: after a kill -9 the daemon restarted in ~5 s, while the orphaned root wrapper was still installing — its +// copy appeared ~7 s AFTER the start-time sender had looked. One look at start is therefore not enough. A glob of the +// plan dir every few minutes costs nothing; the pass lock keeps it off a running pass. Pinned by +// TestR868_ACopyWrittenAfterTheStartIsSentByTheLoop. +func (l *Leg) SendUnsentLoop(ctx context.Context, every time.Duration, onSent func(int)) { + for { + if n := l.SendUnsent(ctx); n > 0 && onSent != nil { + onSent(n) + } + select { + case <-ctx.Done(): + return + case <-time.After(every): + } + } +} + func (l *Leg) sendUnsentLocked(ctx context.Context) int { if l.Hub == nil { return 0 // nobody to send to: keep the copies for a process that has the hub diff --git a/internal/osupdate/unsent_test.go b/internal/osupdate/unsent_test.go index d744235..7a70756 100644 --- a/internal/osupdate/unsent_test.go +++ b/internal/osupdate/unsent_test.go @@ -7,6 +7,7 @@ import ( "os" "path/filepath" "testing" + "time" "gitea.dooplex.hu/admin/felhom-agent/internal/hub" ) @@ -115,6 +116,29 @@ func TestR868_RunningPassKeepsTheSenderOff(t *testing.T) { } } +// v0.144.1 — THE LIVE SHAPE (demo-hp 2026-10-05 05:45 UTC): the restarted daemon looked at 05:45:09, the orphaned +// wrapper wrote its copy at ~05:45:16. The loop must still send it. +// COMPANION RED-PROOF: make SendUnsentLoop return after the first look → "the late copy was never sent". +func TestR868_ACopyWrittenAfterTheStartIsSentByTheLoop(t *testing.T) { + w := &fakeWrapper{t: t} + l, h := newLeg(t, w, nil) + ctx, cancel := context.WithCancel(context.Background()) + defer cancel() + sent := make(chan int, 4) + go l.SendUnsentLoop(ctx, 20*time.Millisecond, func(n int) { sent <- n }) + time.Sleep(50 * time.Millisecond) // the start-time look found nothing + must(t, os.WriteFile(reportFile(l.PlanDir, "late", LayerGuest, "apply"), + []byte(`{"mode":"apply","layer":"guest","run_id":"late","trigger":"debug","ring":0,"vmid":9201,"upgraded":[{"name":"openssl","version":"u3"}]}`), 0o600)) + select { + case n := <-sent: + if n != 1 || len(h.reports) != 1 || h.reports[0].RunID != "late" || h.reports[0].Outcome == "" { + t.Fatalf("sent %d: %+v", n, h.reports) + } + case <-time.After(3 * time.Second): + t.Fatal("the late copy was never sent") + } +} + func must(t *testing.T, err error) { t.Helper() if err != nil {