diff --git a/harbor/lander_gate.py b/harbor/lander_gate.py new file mode 100644 index 0000000..632472a --- /dev/null +++ b/harbor/lander_gate.py @@ -0,0 +1,69 @@ +"""The server's background compiles (the Logbook's statistics, the whole-program check, the emulator run) give way to +the lander: its gates (a full readable check of every file) are what land work on main, and a second compile of main +beside them roughly quadruples their time. + +Two parts: + lander_busy(project) while [logbook] lander_lock names a file that exists and was written in the last + STALE_MINUTES, the lander is running its gates: background jobs do not start. The lander + creates the file before its gates and removes it after the push; an older file is a lander + that died, and is ignored. + run_low(...) subprocess.run at BELOW_NORMAL priority (children such as cl.exe inherit it) that, on a + timeout, ends the whole process tree instead of leaving the compiler running orphaned. + +Configured per project in the [logbook] table: + lander_lock = 'R:/Workspace/Data/lander-busy.lock' unset or "": never wait""" +import os +import subprocess +import time +from pathlib import Path + +STALE_MINUTES = 60 +BELOW_NORMAL = getattr(subprocess, "BELOW_NORMAL_PRIORITY_CLASS", 0) +IDLE = getattr(subprocess, "IDLE_PRIORITY_CLASS", 0) +NO_WINDOW = getattr(subprocess, "CREATE_NO_WINDOW", 0) + + +def lock_path(project): + path = ((getattr(project, "logbook", None) or {}).get("lander_lock") or "").strip() + return Path(path) if path else None + + +def lander_busy(project, now=None): + """Why background work should wait (the lander's lock is fresh), or None.""" + path = lock_path(project) + if path is None: + return None + try: + written = path.stat().st_mtime + except OSError: + return None + age = (time.time() if now is None else now) - written + if age >= STALE_MINUTES * 60: + return None + return f"the lander is running its gates ({path.name}, {max(0, int(age // 60))} min old)" + + +def kill_tree(pid): + if os.name == "nt": + subprocess.run(["taskkill", "/PID", str(pid), "/T", "/F"], capture_output=True, creationflags=NO_WINDOW) + else: + try: + os.kill(pid, 9) + except OSError: + pass + + +def run_low(argv, timeout, priority=BELOW_NORMAL, **kwargs): + """subprocess.run(argv, capture_output=True, text=True, ...) at a lower priority class; on a timeout the whole + tree (cmd.exe, cl.exe) is ended before TimeoutExpired is raised.""" + flags = kwargs.pop("creationflags", 0) | (priority | NO_WINDOW if os.name == "nt" else 0) + with subprocess.Popen(argv, stdin=subprocess.DEVNULL, stdout=subprocess.PIPE, stderr=subprocess.PIPE, + text=True, creationflags=flags, **kwargs) as proc: + try: + stdout, stderr = proc.communicate(timeout=timeout) + except subprocess.TimeoutExpired: + kill_tree(proc.pid) + proc.kill() + proc.communicate() + raise subprocess.TimeoutExpired(argv, timeout) from None + return subprocess.CompletedProcess(argv, proc.returncode, stdout, stderr) diff --git a/harbor/logbook_auto.py b/harbor/logbook_auto.py index 1589d83..bdd1cf7 100644 --- a/harbor/logbook_auto.py +++ b/harbor/logbook_auto.py @@ -9,6 +9,8 @@ Configured per project in a [logbook] table: decomp = 'R:/.../open-seas-decomp' the repository whose main branch is followed stats_repo = 'R:/.../stats-work/repo' a scratch copy of open-seas holding tools/progress/*.py interval_minutes = 10 how often the server looks (default 10) + lander_lock = 'R:/.../lander-busy.lock' wait while the lander runs its gates (harbor.lander_gate) +The progress tools run below normal priority. Milestones and narrative entries stay with people: they need judgement. State (the last commit seen) is kept in the logbook folder as auto.json.""" @@ -22,9 +24,10 @@ import time import traceback from pathlib import Path -from . import logbook +from . import lander_gate, logbook MAX_ENTRIES = 25 +STATS_TIMEOUT = 1800 # each progress tool; sync_decomp compiles every readable file, below normal priority def _git(repo, *args): @@ -88,8 +91,10 @@ def rebuild_stats(project, repo, stats_repo, head): installer = r"C:\Program Files (x86)\Microsoft Visual Studio\Installer" if os.path.isdir(installer) and installer.lower() not in env.get("PATH", "").lower(): env["PATH"] = installer + os.pathsep + env.get("PATH", "") - run = lambda *argv: subprocess.run([sys.executable, "-B", *map(str, argv)], cwd=str(stats_repo), env=env, - capture_output=True, text=True, encoding="utf-8", errors="replace", timeout=900) + # below normal priority (cl.exe inherits it), so the lander's and the agents' compiles go first; a timeout ends + # the whole tree, not only python (an orphaned cl.exe went on compiling all of main at normal priority) + run = lambda *argv: lander_gate.run_low([sys.executable, "-B", *map(str, argv)], STATS_TIMEOUT, + cwd=str(stats_repo), env=env, encoding="utf-8", errors="replace") sync = run(tools / "sync_decomp.py", "--decomp", repo) if sync.returncode != 0: raise RuntimeError("sync_decomp: " + (sync.stdout + sync.stderr).strip()[-400:]) @@ -134,12 +139,20 @@ def refresh(project, force=False): state = _state(project) if state.get("last_head") == head and not force: return {"changed": False, "head": head[:8]} + busy = None if force else lander_gate.lander_busy(project) + if busy: # its gates compile all of main: look again next time + return {"changed": False, "head": head[:8], "waiting": busy} out = {"changed": True, "head": head[:8]} - if state.get("last_head"): + # last_head is where the statistics are; logged_head where the ship's log is (a failed statistics run is retried, + # and must not log the same commits twice) + logged = state.get("logged_head") or state.get("last_head") + if logged and logged != head: try: - out["entries"] = len(log_commits(project, repo, state["last_head"], head)) + out["entries"] = len(log_commits(project, repo, logged, head)) except RuntimeError as error: # e.g. the old commit vanished after a rewrite out["log_error"] = str(error) + if logged: + state["logged_head"] = head if stats_repo: try: out["stats"] = rebuild_stats(project, snapshot_at(config, repo, head), stats_repo, head) diff --git a/harbor/results_refresh.py b/harbor/results_refresh.py index 05bbb9b..2b86a5d 100644 --- a/harbor/results_refresh.py +++ b/harbor/results_refresh.py @@ -13,6 +13,7 @@ Configured per project in the [logbook] table (main is [logbook] decomp): behaviour_every_hours = 12 behaviour_window = "01-06" from 01:00 to 06:00 local time; "" for any hour +No run starts while the lander runs its gates ([logbook] lander_lock, harbor.lander_gate). One run at a time (the server runs one thread for every project), at the lowest process priority, into a .partial file that replaces the results only once it is complete. The match run holds the same per-checkout lock as re_match_program, so it waits its turn behind any other whole-program build of main. @@ -31,7 +32,7 @@ import time import traceback from pathlib import Path -from . import logbook +from . import lander_gate, logbook JOBS = ("match", "behaviour") RESULTS_KEY = {"match": "match_results", "behaviour": "diffrun_results"} @@ -180,14 +181,7 @@ def _spawn(argv, cwd, stdout, stderr): def _kill_tree(pid): - if os.name == "nt": - subprocess.run(["taskkill", "/PID", str(pid), "/T", "/F"], capture_output=True, - creationflags=getattr(subprocess, "CREATE_NO_WINDOW", 0)) - else: - try: - os.kill(pid, 9) - except OSError: - pass + lander_gate.kill_tree(pid) def _alive(pid): @@ -315,6 +309,9 @@ def tick(project, now=None, hour=None): job, why = choose(settings(project), state, head, now, hour, requested, available) if not job: return {"idle": why, "head": head[:8]} + busy = lander_gate.lander_busy(project, now) + if busy: # a request is kept for the next look + return {"waiting": busy, "job": job} if job == "match": from .util import HarborError try: diff --git a/tests/test_logbook.py b/tests/test_logbook.py index d201fc4..9a20c5f 100644 --- a/tests/test_logbook.py +++ b/tests/test_logbook.py @@ -58,6 +58,54 @@ class LogbookAuto(HarborCase): self.assertTrue(entry["at"].endswith("Z")) self.assertFalse(logbook_auto.refresh(self.h.project)["changed"]) + def test_waits_for_the_lander_and_a_failed_stats_run_logs_nothing_twice(self): + import os + import time + from unittest import mock + logbook_auto._save_state(self.h.project, {"last_head": self.first}) + lock = self.dir / "lander-busy.lock" + lock.write_text("x", encoding="utf-8") + self.h.project.logbook.update(lander_lock=str(lock), stats_repo=str(self.dir / "stats")) + out = logbook_auto.refresh(self.h.project) + self.assertFalse(out["changed"]) + self.assertIn("lander", out["waiting"]) + self.assertEqual(logbook.read_all(self.h.project)["log"], []) + old = time.time() - 61 * 60 + os.utime(lock, (old, old)) # stale: ignored + with mock.patch.object(logbook_auto, "rebuild_stats", side_effect=RuntimeError("timed out")): + out = logbook_auto.refresh(self.h.project) + self.assertEqual((out["entries"], out["stats_error"]), (1, "timed out")) + again = logbook_auto.refresh(self.h.project) # the statistics are retried ... + self.assertIn("stats_error", again) + self.assertNotIn("entries", again) # ... but the commit is not relogged + self.assertEqual(len(logbook.read_all(self.h.project)["log"]), 1) + + +class LanderGate(unittest.TestCase): + def test_run_low_lowers_priority_and_ends_the_tree_on_timeout(self): + import os + import sys + import time + from harbor import lander_gate + script = "import subprocess, sys, time; subprocess.Popen([sys.executable, '-c', 'import time; time.sleep(60)']);" \ + " print('ok', flush=True); time.sleep(60)" + from unittest import mock + seen = {} + real = subprocess.Popen + + def popen(argv, **kw): + seen.update(kw) + return real([sys.executable, "-c", "pass"], stdout=subprocess.PIPE, stderr=subprocess.PIPE, text=True) + + with mock.patch.object(lander_gate.subprocess, "Popen", popen): + self.assertEqual(lander_gate.run_low(["x"], 60).returncode, 0) + if os.name == "nt": + self.assertTrue(seen["creationflags"] & subprocess.BELOW_NORMAL_PRIORITY_CLASS) + start = time.monotonic() + with self.assertRaises(subprocess.TimeoutExpired): + lander_gate.run_low([sys.executable, "-c", script], 3) + self.assertLess(time.monotonic() - start, 45) # the grandchild did not hold the pipes + class ProgressMapTests(HarborCase): """GET /api/logbook/progress-map: units, tiers and the headline, by the Logbook's own definitions.""" diff --git a/tests/test_results_refresh.py b/tests/test_results_refresh.py index 20e6070..7ea3b58 100644 --- a/tests/test_results_refresh.py +++ b/tests/test_results_refresh.py @@ -208,6 +208,19 @@ class Refresher(HarborCase): rr.save_state(self.h.project, st) self.assertIsNone(rr.freshness(self.h.project)["match"]["sha"]) + def test_waits_while_the_lander_runs_its_gates(self): + lock = self.dir / "lander-busy.lock" + self.h.project.logbook["lander_lock"] = str(lock) + lock.write_text("lander", encoding="utf-8") + os.utime(lock, (T0 - 300, T0 - 300)) + rr.request(self.h.project, "match") + out = rr.tick(self.h.project, now=T0, hour=12) + self.assertIn("lander", out["waiting"]) + self.assertEqual(self.calls, []) + self.assertEqual(rr._requested(self.h.project), {"match"}) # kept for the next look + self.assertTrue(rr.tick(self.h.project, now=T0 + 61 * 60, hour=12)["ok"]) # a lock over an hour old is stale + self.assertEqual(len(self.calls), 1) + def test_runs_at_idle_priority(self): seen = {}