fix(update): keep the rollback's pip retries inside the unit time limit

The health check reinstalled the previous requirements by trying the
next bash path after any failure, including a 600 s pip timeout. Two
files, two paths: up to 40 minutes of pip alone, while systemd stops
ledmatrix-update-verify.service at TimeoutStartSec=30min -- killing the
rollback half-way and leaving the update 'verifying' until the web UI
calls it lost.

- Like permission_utils.install_requirements_file, only a sudo refusal
  moves on to the next bash; a pip that ran and failed or timed out is
  not repeated. The refusal wording is one list
  (permission_utils.SUDO_REFUSAL_PHRASES), mirrored in the stdlib-only
  verifier and pinned equal by a test.
- All reinstalls in one rollback share a 600 s budget.
- WORST_CASE_SECONDS adds up every timeout on the longest path (27.5
  min); a test holds it under the unit's TimeoutStartSec and that under
  the web UI's VERIFY_LOST_SECONDS.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>

scripts/utils/auto_update_verify.py

@@ -42,10 +42,30 @@ HEALTH_TIMEOUT_SECONDS = 180
 #: loop look healthy between attempts, so a single "is-active" proves nothing.
 STABLE_SECONDS = 45
 POLL_SECONDS = 5
+WEB_CHECK_TIMEOUT_SECONDS = 5
+SYSTEMCTL_QUERY_TIMEOUT_SECONDS = 10
+RESTART_TIMEOUT_SECONDS = 90
+GIT_TIMEOUT_SECONDS = 60
+GIT_RESET_TIMEOUT_SECONDS = 120
 PIP_TIMEOUT_SECONDS = 600
+#: All of a rollback's dependency reinstalls together. A pip that times out
+#: or fails is not retried: systemd stops this unit at TimeoutStartSec, and a
+#: rollback killed half-way leaves the update reported as still verifying.
+PIP_BUDGET_SECONDS = 600
 #: sudoers matches the exact command line, so bash is named by path, the same
-#: candidates src/common/permission_utils.install_requirements_file tries.
+#: candidates src/common/permission_utils.install_requirements_file tries...
 BASH_CANDIDATES = ('/usr/bin/bash', '/bin/bash')
+#: ...and, like it, moves to the next one only when sudo refused the command
+#: line (permission_utils.SUDO_REFUSAL_PHRASES), never after pip itself ran.
+SUDO_REFUSAL_PHRASES = ('a password is required', 'is not allowed to run', 'no tty present')
+
+#: The longest one health check can take: restart and wait, roll back
+#: (diff, reset, reinstalls), restart and wait again. A wait's last poll can
+#: start just before its deadline and run every query to its timeout.
+_WAIT_WORST_SECONDS = (HEALTH_TIMEOUT_SECONDS + STABLE_SECONDS + WEB_CHECK_TIMEOUT_SECONDS
+                       + 2 * SYSTEMCTL_QUERY_TIMEOUT_SECONDS + POLL_SECONDS)
+WORST_CASE_SECONDS = (2 * (2 * RESTART_TIMEOUT_SECONDS + _WAIT_WORST_SECONDS)
+                      + GIT_TIMEOUT_SECONDS + GIT_RESET_TIMEOUT_SECONDS + PIP_BUDGET_SECONDS)
 
 #: What a command that could not run at all reports: its callers only read
 #: these three fields, the same ones a completed subprocess has.
@@ -83,7 +103,7 @@ def write_pending(path, data):
 
 def _web_responds(url=WEB_HEALTH_URL):
     try:
-        with urllib.request.urlopen(url, timeout=5) as resp:  # nosec B310 - fixed loopback URL
+        with urllib.request.urlopen(url, timeout=WEB_CHECK_TIMEOUT_SECONDS) as resp:  # nosec B310 - fixed loopback URL
             return resp.status == 200
     except (urllib.error.URLError, OSError, ValueError):
         return False
@@ -104,7 +124,7 @@ class Verifier:
         self.web_responds = web_responds
         self.log = log or (lambda msg: print(f'[auto-update-verify] {msg}', flush=True))
 
-    def _run(self, args, timeout=60):
+    def _run(self, args, timeout=GIT_TIMEOUT_SECONDS):
         try:
             return self.run(args, cwd=str(self.project_root), capture_output=True,
                             text=True, timeout=timeout)
@@ -114,15 +134,17 @@ class Verifier:
     # -- services ---------------------------------------------------------
 
     def service_active(self, unit):
-        return self._run(['systemctl', 'is-active', unit], timeout=10).stdout.strip() == 'active'
+        return self._run(['systemctl', 'is-active', unit],
+                         timeout=SYSTEMCTL_QUERY_TIMEOUT_SECONDS).stdout.strip() == 'active'
 
     def restart_count(self, unit):
         out = self._run(['systemctl', 'show', '-p', 'NRestarts', '--value', unit],
-                        timeout=10).stdout.strip()
+                        timeout=SYSTEMCTL_QUERY_TIMEOUT_SECONDS).stdout.strip()
         return int(out) if out.isdigit() else None
 
     def restart(self, unit):
-        result = self._run(['sudo', '-n', 'systemctl', 'restart', f'{unit}.service'], timeout=90)
+        result = self._run(['sudo', '-n', 'systemctl', 'restart', f'{unit}.service'],
+                           timeout=RESTART_TIMEOUT_SECONDS)
         if result.returncode != 0:
             self.log(f'restarting {unit} failed: {(result.stderr or "").strip()}')
         return result.returncode == 0
@@ -173,16 +195,27 @@ class Verifier:
         changed = set(result.stdout.split()) if result.returncode == 0 else set(REQUIREMENT_FILES)
         return [rel for rel in REQUIREMENT_FILES if rel in changed]
 
-    def install_requirements(self, rel):
+    def install_requirements(self, rel, deadline=None):
+        """Install one requirements file through the root wrapper, by ``deadline``."""
         wrapper = self.project_root / 'scripts' / 'fix_perms' / 'safe_pip_install.sh'
         req = self.project_root / rel
         if not req.exists():
             return True
         for bash in BASH_CANDIDATES:
-            result = self._run(['sudo', '-n', bash, str(wrapper), str(req)],
+            timeout = PIP_TIMEOUT_SECONDS
-                               timeout=PIP_TIMEOUT_SECONDS)
+            if deadline is not None:
+                timeout = min(timeout, deadline - self.clock())
+                if timeout <= 0:
+                    self.log(f'no time left to reinstall {rel}')
+                    return False
+            result = self._run(['sudo', '-n', bash, str(wrapper), str(req)], timeout=timeout)
             if result.returncode == 0:
                 return True
+            # Only a refused command line is worth the next candidate. A pip
+            # that ran and failed, or timed out, would just do it again.
+            if not any(phrase in (result.stderr or '') for phrase in SUDO_REFUSAL_PHRASES):
+                self.log(f'reinstalling {rel} failed: {(result.stderr or "").strip()[-300:]}')
+                return False
         return False
 
     def rollback(self, pending):
@@ -196,11 +229,12 @@ class Verifier:
         # plugin folders the only thing this discards is the update. Edits
         # under plugins/ and plugin-repos/, which that check leaves to the
         # pull's --autostash, are reset along with it.
-        result = self._run(['git', 'reset', '--hard', old], timeout=120)
+        result = self._run(['git', 'reset', '--hard', old], timeout=GIT_RESET_TIMEOUT_SECONDS)
         if result.returncode != 0:
             return False, (f'"git reset --hard {old}" failed: '
                            f'{(result.stderr or result.stdout or "").strip()}')
-        failed = [rel for rel in requirements if not self.install_requirements(rel)]
+        deadline = self.clock() + PIP_BUDGET_SECONDS
+        failed = [rel for rel in requirements if not self.install_requirements(rel, deadline)]
         if failed:
             return True, ('reinstalling the previous dependencies from ' + ', '.join(failed)
                           + ' failed; run Install Base Requirements from the Tools tab')

src/common/permission_utils.py

@@ -373,6 +373,14 @@ def sudo_remove_directory(path: Path, allowed_bases: Optional[list] = None) -> b
         return False
 
 
+#: What sudo prints when it refuses a command line outright (not in sudoers for
+#: that exact argv, or it wants a password). Only then is another bash path
+#: worth trying: after pip itself ran, a retry just repeats the failure. The
+#: automatic update's health check keeps its own copy of this list
+#: (scripts/utils/auto_update_verify.py runs without importing src/).
+SUDO_REFUSAL_PHRASES = ("a password is required", "is not allowed to run", "no tty present")
+
+
 def install_requirements_file(req_file: Path, timeout: int = 300) -> subprocess.CompletedProcess:
     """
     Install a requirements.txt file for a plugin (or the project itself).
@@ -434,10 +442,7 @@ def install_requirements_file(req_file: Path, timeout: int = 300) -> subprocess.
             # Distinguish "sudo rejected this exact command line" (worth
             # trying the next bash candidate) from "sudo ran it but pip
             # itself failed" (a real error — stop and surface it).
-            denied = any(
+            denied = any(phrase in result.stderr for phrase in SUDO_REFUSAL_PHRASES)
-                phrase in result.stderr
-                for phrase in ("a password is required", "is not allowed to run", "no tty present")
-            )
             if not denied:
                 # Deliberately don't interpolate req_file or the pip output here:
                 # this log line is scanner-visible, and a static analyzer can't

test/test_auto_update_verify.py

@@ -69,6 +69,8 @@ class FakeHost:
         self.running_head = None  # not restarted yet: still the old, healthy code
         self.restarts = []        # (unit, commit it was restarted onto)
         self.pip_installs = []
+        self.pip_timeouts = []
+        self.pip = None  # optional (args, host) -> result, or raises, instead of pip_ok
         self.now = 0.0
         self.nrestarts = 0
 
@@ -90,6 +92,9 @@ class FakeHost:
             return done(args, f'{self.nrestarts}\n')
         if args[0] == 'sudo' and any(a.endswith('safe_pip_install.sh') for a in args):
             self.pip_installs.append(args[-1])
+            self.pip_timeouts.append(kwargs.get('timeout'))
+            if self.pip:
+                return self.pip(args, self)
             return done(args, rc=0 if self.pip_ok else 1)
         if args[:4] == ['sudo', '-n', 'systemctl', 'restart']:
             if self.restart_failures:
@@ -171,6 +176,77 @@ def test_a_failed_dependency_reinstall_is_reported(tmp_path):
     assert 'Install Base Requirements' in result['detail']
 
 
+def _rollback_with_pip(tmp_path, pip, web_requirements_too=False):
+    """Roll back an update that changed the requirements, with pip faked by ``pip``."""
+    repo, old, new = updated_repo(tmp_path, new_requirements=True)
+    if web_requirements_too:
+        (repo / 'web_interface').mkdir()
+        (repo / 'web_interface' / 'requirements.txt').write_text('flask\n')
+        git(repo, 'add', '.')
+        git(repo, 'commit', '-qm', 'web reqs')
+        (repo / 'web_interface' / 'requirements.txt').write_text('flask\nnew\n')
+        (repo / 'requirements.txt').write_text('requests\nnewer\n')
+        git(repo, 'commit', '-qam', 'bump both')
+        old, new = git(repo, 'rev-parse', 'HEAD~1'), git(repo, 'rev-parse', 'HEAD')
+    host = FakeHost(repo, new)
+    host.pip = pip
+    ok, detail = host.verifier().rollback({'old_head': old, 'new_head': new})
+    return ok, detail, host
+
+
+def test_a_failed_pip_is_not_run_again_with_the_other_bash(tmp_path):
+    """Retrying after pip itself ran only repeats it, and every repeat can
+    take PIP_TIMEOUT_SECONDS of the unit's time limit."""
+    ok, detail, host = _rollback_with_pip(
+        tmp_path, lambda args, h: subprocess.CompletedProcess(args, 1, '', 'ERROR: No matching distribution'))
+    assert ok and 'requirements.txt' in detail
+    assert len(host.pip_installs) == 1
+
+
+def test_a_pip_timeout_is_not_retried(tmp_path):
+    def slow(args, h):
+        h.now += h.pip_timeouts[-1]
+        raise subprocess.TimeoutExpired(args, h.pip_timeouts[-1])
+    ok, detail, host = _rollback_with_pip(tmp_path, slow)
+    assert ok and 'Install Base Requirements' in detail
+    assert len(host.pip_installs) == 1
+
+
+def test_a_sudo_refusal_tries_the_next_bash(tmp_path):
+    def refused_once(args, h):
+        if len(h.pip_installs) == 1:
+            return subprocess.CompletedProcess(args, 1, '', 'sudo: a password is required')
+        return done(args)
+    ok, detail, host = _rollback_with_pip(tmp_path, refused_once)
+    assert ok and detail == ''
+    assert len(host.pip_installs) == 2
+
+
+def test_reinstalls_share_one_time_budget(tmp_path):
+    def hangs(args, h):
+        h.now += h.pip_timeouts[-1]
+        raise subprocess.TimeoutExpired(args, h.pip_timeouts[-1])
+    ok, detail, host = _rollback_with_pip(tmp_path, hangs, web_requirements_too=True)
+    assert ok and 'requirements.txt' in detail and 'web_interface/requirements.txt' in detail
+    assert sum(host.pip_timeouts) <= av.PIP_BUDGET_SECONDS
+    assert len(host.pip_installs) == 1, "the first file used the whole budget"
+
+
+def test_the_worst_case_fits_the_unit_time_limit():
+    """systemd kills the check at TimeoutStartSec, mid-rollback, and the update
+    then sits in "verifying" until the web interface calls it lost."""
+    from web_interface import auto_update as au
+    service = (ROOT / 'systemd' / 'ledmatrix-update-verify.service').read_text(encoding='utf-8')
+    minutes = int(re.search(r'^TimeoutStartSec=(\d+)min$', service, re.M).group(1))
+    assert av.WORST_CASE_SECONDS < minutes * 60
+    assert minutes * 60 < au.VERIFY_LOST_SECONDS, "the web UI must not call a running check lost"
+
+
+def test_sudo_refusal_wording_matches_permission_utils():
+    from src.common import permission_utils
+    assert set(av.SUDO_REFUSAL_PHRASES) == set(permission_utils.SUDO_REFUSAL_PHRASES)
+
+
 def test_still_broken_after_rolling_back_is_rollback_failed(tmp_path):
     code, result, host, head, old, new = check(tmp_path, 'always')
     assert code == 1 and result['status'] == 'rollback_failed'