Background compiles give way to the lander: the Logbook statistics and the results refresher wait while [logbook] lander_lock is fresh (under 60 min); the statistics tools run below normal priority and a timeout ends the whole tree (an orphaned cl.exe went on compiling main at normal priority); a retried statistics run no longer relogs the same commits

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)

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,
+    # below normal priority (cl.exe inherits it), so the lander's and the agents' compiles go first; a timeout ends
-                                       capture_output=True, text=True, encoding="utf-8", errors="replace", timeout=900)
+    # 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)

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":
+    lander_gate.kill_tree(pid)
-        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
 
 
 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:

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."""

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 = {}