diff --git a/README.md b/README.md index 24fe048..bef55a4 100644 --- a/README.md +++ b/README.md @@ -73,6 +73,7 @@ During that window, with ALARMS on, the panel fixes a problem by itself once it - At most 2 tries per problem, 90 s apart; then it is yours to hold. - It waits while the network is having a blip, and does nothing to Dante when several devices vanish at once (that is NA Ingest's view or the Dante network, not the Macs). - Never automatic: restarting a running ProPresenter, Bible app, ProdCom (or DVS on NA Ingest, which restarts ProdCom), captions or the bridge, power-cycling a switch port, or turning on a connection someone switched off. `load_config` refuses an auto fix that closes a program. +- **Daily log:** everything auto-fix does is written as it happens to `~/Desktop/Auto-Fix Logs/ Auto-Fix.log` on NA Ingest (e.g. `2026-10-11 Sunday Auto-Fix.log`): the problem, what it did, whether it worked, when the fault cleared, when it gave up or held back. Double-click it to open it in Console, which shows new lines live. - Press ALARMS to mute the panel for maintenance: that also stops auto-fix. The window and the list are `"auto_fix"` in `config.json`. ## Restart page (page 20) diff --git a/status_panel.py b/status_panel.py index 555e8b7..cc21c35 100644 --- a/status_panel.py +++ b/status_panel.py @@ -580,6 +580,37 @@ class Tracker: DAYS = ["mon", "tue", "wed", "thu", "fri", "sat", "sun"] +class AutoLog: + """One plain-text file per day of everything auto-fix does, written line by line as it happens, + e.g. "~/Desktop/Auto-Fix Logs/2026-10-11 Sunday Auto-Fix.log" (a .log opens in Console, which + shows new lines live).""" + + def __init__(self, directory): + self.dir = os.path.expanduser(directory) + self.lock = threading.Lock() + + def path(self, now): + return os.path.join(self.dir, datetime.fromtimestamp(now).strftime("%Y-%m-%d %A") + " Auto-Fix.log") + + def write(self, now, button, text): + dt = datetime.fromtimestamp(now) + line = "%s %-8s %s\n" % (dt.strftime("%H:%M:%S"), button, text.replace("\n", " ")) + try: + with self.lock: + os.makedirs(self.dir, exist_ok=True) + path = self.path(now) + new = not os.path.exists(path) + with open(path, "a", encoding="utf-8") as f: + if new: + f.write("Status panel auto-fixes - %s\n" + "(NA Ingest fixes these by itself on Sundays 06:30-13:30; anything that closes a\n" + " running program stays a hold. Newest lines at the bottom.)\n\n" + % dt.strftime("%A %-d %B %Y")) + f.write(line) + except OSError as e: + log.warning("auto-fix log %s: %s", self.dir, e) + + def in_windows(windows, now): """Is `now` inside one of [{"days": [...], "start": "HH:MM", "end": "HH:MM"}]?""" dt = datetime.fromtimestamp(now) @@ -665,6 +696,10 @@ class Engine: self.auto = cfg.get("auto_fix") or {} self.auto_tries = {} # fix identity -> [tries, last try time] for the fault now going on self.auto_seen = {} # fix identity -> last time it was in an auto plan + self.autolog = AutoLog(self.auto.get("log_dir", "~/Desktop/Auto-Fix Logs")) if self.auto else None + self.auto_watch = {} # "BUTTON FAULT" auto-fix went after -> when (to log when it clears) + self.auto_paused = False + self.auto_on = False # inside the window (for the "auto-fix on" line) self.auto_last = 0.0 self.deck_ips = {} # HyperDeck connection -> last address Companion reported self.now = 0.0 @@ -766,7 +801,12 @@ class Engine: if event == "fault": self.events.append(("FAULT", "%s %s" % (self.tiles[tile_id]["label"], res.msg))) elif event == "clear": - self.events.append(("CLEAR", "%s %s" % (self.tiles[tile_id]["label"], tr.last_fault_msg))) + text = "%s %s" % (self.tiles[tile_id]["label"], tr.last_fault_msg) + self.events.append(("CLEAR", text)) + fixed_at = self.auto_watch.pop(text, None) + if fixed_at is not None and self.autolog: + self.autolog.write(now, self.tiles[tile_id]["label"], + "OK again: %s (%d s after the auto-fix)" % (tr.last_fault_msg, now - fixed_at)) # A check may stop reporting a fault instead of reporting it OK: a Shure or PSM check says # "conn" while its connection is down and per channel once it is back (2026-10-08). Such a # fault is over - clear it, or it lingers unseen and a hold would still try to fix it. @@ -947,7 +987,7 @@ class Engine: return plan return self.run_plan(tile_id, plan, snap, comp, now, cooldown) - def run_plan(self, tile_id, plan, snap, comp, now, cooldown=60, auto=False): + def run_plan(self, tile_id, plan, snap, comp, now, cooldown=60, auto=False, on_done=None): """Carry out fix_plan() items for one button (a hold, or auto-fix during service).""" started, names, waited, midi = [], [], False, [] for ident, kind, what, chk in plan: @@ -993,6 +1033,8 @@ class Engine: summary = names[0] if len(set(names)) == 1 else "%d FIXES" % len(names) if not started: # only Companion reconnects: quick self.note(tile_id, "CHECKING\n" + summary, "fixing", now, 15) + if on_done: + on_done("asked Companion to reconnect") return plan self.note(tile_id, ("AUTO-FIXING\n" if auto else "FIXING\n") + summary, "fixing", now, 180) results = [] @@ -1008,12 +1050,18 @@ class Engine: done = time.time() if WAKING in results: self.note(tile_id, "WAKING PC\n" + summary, "fixing", done, 120) + outcome = "the PC was off: sent Wake-on-LAN" elif said: # the fix says what to do next self.note(tile_id, said[0], "failed", done, 60) + outcome = "did not work: " + said[0] elif all(r is not False for r in results): self.note(tile_id, "CHECKING\n" + summary, "fixing", done, 20) + outcome = "done, checking it comes back" else: self.note(tile_id, "FIX FAILED\n" + summary, "failed", done, 20) + outcome = "the fix command failed" + if on_done: + on_done(outcome) said = [] for fn, args, short in started: threading.Thread(target=work, args=(fn, args, short), daemon=True).start() @@ -1030,14 +1078,28 @@ class Engine: return [] self.auto_last = now if not in_windows(a.get("windows", []), now) or not self.service.on(now): + if self.auto_on and self.autolog: + self.autolog.write(now, "PANEL", "auto-fix off (%s)" % ("ALARMS muted" if in_windows( + a.get("windows", []), now) else "end of the window")) + self.auto_on = False self.auto_tries.clear() self.auto_seen.clear() return [] + if not self.auto_on and self.autolog: # opens today's file, so it can be watched from the start + ends = [w["end"] for w in a.get("windows", []) if in_windows([w], now)] + self.autolog.write(now, "PANEL", "auto-fix on%s" % (" until " + ends[0] if ends else "")) + self.auto_on = True net_down = any(self.trackers.get("net:" + k) and self.trackers["net:" + k].confirmed and self.trackers["net:" + k].result.level == ERR for k in ("link", "gateway")) if net_down or (self.burst and (self.burst["cleared"] is None or now - self.burst["cleared"] < a.get("pause_after_network_seconds", 60))): + if not self.auto_paused and self.autolog: + self.autolog.write(now, "NET", "network problem: no auto-fixes until it settles") + self.auto_paused = True return [] # everything looks broken at once: wait it out + if self.auto_paused and self.autolog: + self.autolog.write(now, "NET", "network settled: auto-fix is back on") + self.auto_paused = False gentle = set(a.get("fixes", [])) done = [] for t in self.cfg["tiles"]: @@ -1051,6 +1113,9 @@ class Engine: if self.auto_seen.get(("dante-wide", t["id"]), 0) < now - 600: log.info("AUTO %s: %d Dante devices gone at once - not touching them, hold DANTE if needed", t["id"], len(gone)) + if self.autolog: + self.autolog.write(now, t["label"], "left alone: %d Dante devices gone at once (NA Ingest's " + "view of Dante or the Dante network) - hold DANTE if needed" % len(gone)) self.auto_seen[("dante-wide", t["id"])] = now continue plan = [] @@ -1062,6 +1127,9 @@ class Engine: if tries >= a.get("max_tries", 2): if tries == a.get("max_tries", 2): log.info("AUTO %s: gave up on %s %s after %d tries - hold it to try again", t["id"], kind, what, tries) + if self.autolog: + self.autolog.write(now, t["label"], "gave up after %d tries: %s - hold %s to try again" + % (tries, self.describe(kind, what), t["label"])) self.auto_tries[ident] = (tries + 1, last) continue if now - last < a.get("retry_seconds", 90) or now - self.fix_last.get(ident, 0) < 60: @@ -1069,9 +1137,20 @@ class Engine: self.auto_tries[ident] = (tries + 1, now) plan.append((ident, kind, what, chk)) if plan: - log.info("AUTO %s: fixing %s (try %d)", t["id"], ", ".join("%s %s" % (k, w) for _, k, w, _ in plan), - max(self.auto_tries[i][0] for i, _, _, _ in plan)) - self.run_plan(t["id"], plan, snap, comp, now, auto=True) + try_no = max(self.auto_tries[i][0] for i, _, _, _ in plan) + log.info("AUTO %s: fixing %s (try %d)", t["id"], ", ".join("%s %s" % (k, w) for _, k, w, _ in plan), try_no) + faults = [r.msg for k in self.keys_for(t["id"]) for r in [self.trackers[k].result] + if self.trackers[k].confirmed and r.level == ERR] + for f in faults: + self.auto_watch["%s %s" % (t["label"], f)] = now + label = t["label"] + if self.autolog: + self.autolog.write(now, label, "problem: %s - fixing: %s (try %d of %d)" % ( + ", ".join(faults) or "?", "; ".join(self.describe(k, w) for _, k, w, _ in plan), + try_no, a.get("max_tries", 2))) + self.run_plan(t["id"], plan, snap, comp, now, auto=True, + on_done=(lambda outcome, label=label: self.autolog.write(time.time(), label, "-> " + outcome)) + if self.autolog else None) done.append(t["id"]) forget = a.get("forget_seconds", 600) for ident in list(self.auto_tries): @@ -1081,6 +1160,14 @@ class Engine: del self.auto_tries[ident] return done + def describe(self, kind, what): + """A plan item in words, for the auto-fix log.""" + if kind == "restart": + return "reconnect Companion's %s connection" % what + if kind == "fix": + return self.cfg["fixes"][what].get("label", what) + return "%s %s" % (kind, what) + def run_force(self, key_id, snap, comp, now, cooldown=60, fix_id=None, chk=None): """Run one fix whatever the status says: a Restart page key, or a button's "hold_always". Shares the 60 s guard with holds, so a hold and a restart key never double up.""" diff --git a/tests/test_status_panel.py b/tests/test_status_panel.py index bdf64b5..35dffb1 100644 --- a/tests/test_status_panel.py +++ b/tests/test_status_panel.py @@ -29,6 +29,7 @@ CONFIG["service_windows"] = [{"days": ["sun"], "start": "07:00", "end": "12:30"} CONFIG["tiles"] = [dict(t, label="SERVICE") if t["id"] == "service" else t for t in CONFIG["tiles"]] # A Sunday 08:00 (inside the service window) and a Wednesday 15:00 (outside it). SUNDAY = datetime(2026, 10, 11, 8, 0).timestamp() +CONFIG["auto_fix"]["log_dir"] = tempfile.mkdtemp(prefix="sp-autolog-") # never the real Desktop WEDNESDAY = datetime(2026, 10, 7, 15, 0).timestamp() @@ -585,8 +586,9 @@ class TestFixes(unittest.TestCase): def setUp(self): self.snap = healthy_snapshot(SUNDAY) self.engine = sp.Engine(CONFIG) - # Safety net: a hold in these tests must never reach a real machine. + # Safety net: a hold in these tests must never reach a real machine (or write a real log). self.engine.executor = self.engine.poe_executor = lambda *a: True + self.engine.autolog = sp.AutoLog(tempfile.mkdtemp()) def plan(self, tile): run_steps(self.engine, self.snap, SUNDAY, 4) @@ -699,6 +701,27 @@ class TestFixes(unittest.TestCase): self.assertEqual(self.engine.notes["apps"]["text"], "AUTO-FIXING\nABLETON") gate.set() + def test_auto_fix_writes_a_daily_log(self): + ran, comp = self.auto_setup() + t = SUNDAY + self.snap.remote["tracks\0pgrep -xq Live"] = False + run_steps(self.engine, self.snap, t, 25) + self.engine.auto_fix(self.snap, comp, t + 25) + time.sleep(0.2) + self.snap.remote["tracks\0pgrep -xq Live"] = True # Ableton is back + run_steps(self.engine, self.snap, t + 40, 1) + path = self.engine.autolog.path(t) + self.assertTrue(path.endswith("2026-10-11 Sunday Auto-Fix.log")) + lines = open(path).read().splitlines() + self.assertTrue(lines[0].startswith("Status panel auto-fixes - Sunday 11 October 2026")) + body = [l for l in lines if l[:2].isdigit()] + self.assertIn("PANEL auto-fix on until 13:30", body.pop(0)) + self.assertEqual(body[0][:8], "08:00:25") + self.assertIn("APPS problem: ABLETON NOT RUNNING - fixing: start Ableton", body[0]) + self.assertIn("(try 1 of 2)", body[0]) + self.assertIn("-> done, checking it comes back", body[1]) + self.assertIn("OK again: ABLETON NOT RUNNING (15 s after the auto-fix)", body[2]) + def test_auto_fix_tries_twice_then_leaves_it_to_you(self): ran, comp = self.auto_setup() self.snap.remote["tracks\0pgrep -xq Live"] = False