diff --git a/CHANGELOG.md b/CHANGELOG.md index 9dd7243d..02687de2 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -96,6 +96,13 @@ to for one release are gone. draw still passes `force_clear=True`; later ones pass nothing. A redraw that finds the plugin's `update()` holding its lock is skipped; the pause carries on. +- Update Code no longer fails forever with `fatal: Unable to create + '.../.git/index.lock': File exists`. A git killed mid-command (a pull or + checkout that hit its timeout is SIGKILLed; a power cut does the same) + leaves that lock behind. Update Code and the automatic update's rollback + now remove it when no git process is running in the checkout and the + file is more than a few seconds old (new `web_interface/git_index_lock.py`); + while another git is running, Update Code says so instead of failing. ## 3.8.7 diff --git a/test/test_auto_update.py b/test/test_auto_update.py index 0f52baa4..840b00f6 100644 --- a/test/test_auto_update.py +++ b/test/test_auto_update.py @@ -9,9 +9,11 @@ Git runs for real against a throwaway origin/device clone pair; systemd, sudo and the health check service are faked. """ import json +import os import shutil import subprocess import sys +import time from datetime import datetime, timezone from pathlib import Path from unittest.mock import MagicMock, patch @@ -579,6 +581,27 @@ class TestUpdateIsVerified: assert repo.head() == old assert 'rolled back' in result['core_message'] + @pytest.mark.skipif(not Path('/proc/self/comm').exists(), reason='needs /proc') + def test_a_pull_killed_by_its_timeout_is_still_rolled_back(self, tmp_path): + """subprocess.run SIGKILLs a timed-out git, which leaves .git/index.lock + behind; the rollback's reset would fail on it.""" + repo = Repo(tmp_path) + old = repo.head() + repo.publish() + pull = real_pull(repo.device) + lock = repo.device / '.git' / 'index.lock' + + def killed(**kwargs): + pull() + lock.write_text('') + stale = time.time() - 60 + os.utime(lock, (stale, stale)) + raise subprocess.TimeoutExpired(['git', 'pull'], 60) + result = Harness(tmp_path, repo, core_update=killed).updater.run() + assert repo.head() == old + assert 'rolled back' in result['core_message'] + assert not lock.exists() + @pytest.mark.parametrize('how', ['partial_pull', 'check_never_started']) def test_a_failed_rollback_leaves_plugins_and_the_display_alone(self, tmp_path, how): """update_core returns rollback_failed itself on two paths. The device diff --git a/test/test_git_index_lock.py b/test/test_git_index_lock.py new file mode 100644 index 00000000..d49d337b --- /dev/null +++ b/test/test_git_index_lock.py @@ -0,0 +1,200 @@ +"""A stale .git/index.lock must not block Update Code forever. + +subprocess.run's timeout SIGKILLs git, and a killed git cannot remove its +index.lock. Every later update then failed with "Unable to create +'.../.git/index.lock': File exists" until someone removed the file over SSH. +The update now removes the lock when no git process can still own it. +""" +import os +import shutil +import subprocess +import sys +import time +from pathlib import Path +from unittest.mock import patch + +import pytest +from flask import Flask + +sys.path.insert(0, str(Path(__file__).resolve().parent.parent)) + +from web_interface import git_index_lock as gil # noqa: E402 +from web_interface.blueprints import api_v3 as mod # noqa: E402 +from web_interface.blueprints.api_v3 import api_v3 # noqa: E402 + +needs_git = pytest.mark.skipif(shutil.which('git') is None, reason='git not installed') + +OLD = 1_000_000.0 + + +def _checkout(tmp_path, lock_age=None): + repo = tmp_path / 'LEDMatrix' + (repo / '.git').mkdir(parents=True) + if lock_age is not None: + lock = repo / '.git' / 'index.lock' + lock.write_text('') + os.utime(lock, (OLD, OLD)) + return repo + + +def _proc(tmp_path, *procs): + """A fake /proc: ``procs`` are (comm, cwd[, argv]); cwd None means unreadable.""" + root = tmp_path / 'proc' + root.mkdir() + (root / 'self').mkdir() # non-numeric entries are skipped + for pid, (comm, cwd, *argv) in enumerate(procs, start=100): + entry = root / str(pid) + entry.mkdir() + (entry / 'comm').write_text(comm + '\n') + (entry / 'cmdline').write_bytes(b'\0'.join(a.encode() for a in [comm, *argv]) + b'\0') + if cwd is not None: + (entry / 'cwd').symlink_to(cwd) + else: + (entry / 'cwd').mkdir() # readlink on a directory fails: unreadable + return root + + +class TestClearStaleIndexLock: + def test_no_lock_is_left_alone(self, tmp_path): + repo = _checkout(tmp_path) + assert gil.clear_stale_index_lock(repo, proc_root=_proc(tmp_path)) == gil.ABSENT + + def test_a_stale_lock_is_removed(self, tmp_path): + repo = _checkout(tmp_path, lock_age=60) + proc = _proc(tmp_path, ('python3', str(repo)), ('git', str(tmp_path / 'elsewhere'))) + assert gil.clear_stale_index_lock(repo, proc_root=proc, now=OLD + 60) == gil.REMOVED + assert not (repo / '.git' / 'index.lock').exists() + + @pytest.mark.parametrize('comm', ['git', 'git-remote-http']) + def test_a_lock_held_by_a_running_git_is_kept(self, tmp_path, comm): + repo = _checkout(tmp_path, lock_age=60) + proc = _proc(tmp_path, (comm, str(repo / 'src'))) + assert gil.clear_stale_index_lock(repo, proc_root=proc, now=OLD + 60) == gil.IN_USE + assert (repo / '.git' / 'index.lock').exists() + + def test_a_git_pointed_at_the_checkout_from_elsewhere_is_running(self, tmp_path): + repo = _checkout(tmp_path, lock_age=60) + proc = _proc(tmp_path, ('git', str(tmp_path), f'--git-dir={repo.resolve()}/.git', + f'--work-tree={repo.resolve()}', 'checkout', 'v3.8.7')) + assert gil.clear_stale_index_lock(repo, proc_root=proc, now=OLD + 60) == gil.IN_USE + assert (repo / '.git' / 'index.lock').exists() + + @pytest.mark.parametrize('argv', [['-C', 'LEDMatrix', 'status'], + ['--git-dir=LEDMatrix/.git', '--work-tree=LEDMatrix', 'add', '.']]) + def test_a_git_pointed_at_the_checkout_by_a_relative_path_is_running(self, tmp_path, argv): + repo = _checkout(tmp_path, lock_age=60) + proc = _proc(tmp_path, ('git', str(repo.resolve().parent), *argv)) + assert gil.clear_stale_index_lock(repo, proc_root=proc, now=OLD + 60) == gil.IN_USE + + def test_a_git_working_on_another_repository_is_not(self, tmp_path): + repo = _checkout(tmp_path, lock_age=60) + proc = _proc(tmp_path, ('git', str(tmp_path), '-C', 'other', 'pull'), + ('git', str(tmp_path), '--git-dir=LEDMatrix-backup/.git', 'fetch')) + assert gil.clear_stale_index_lock(repo, proc_root=proc, now=OLD + 60) == gil.REMOVED + + def test_a_git_whose_cwd_cannot_be_read_counts_as_running(self, tmp_path): + repo = _checkout(tmp_path, lock_age=60) + proc = _proc(tmp_path, ('git', None)) + assert gil.clear_stale_index_lock(repo, proc_root=proc, now=OLD + 60) == gil.IN_USE + assert (repo / '.git' / 'index.lock').exists() + + def test_a_brand_new_lock_is_kept(self, tmp_path): + """A git may have created it between the process scan and the removal.""" + repo = _checkout(tmp_path, lock_age=0) + assert gil.clear_stale_index_lock(repo, proc_root=_proc(tmp_path), now=OLD + 1) == gil.IN_USE + assert (repo / '.git' / 'index.lock').exists() + + def test_without_proc_nothing_is_removed(self, tmp_path): + repo = _checkout(tmp_path, lock_age=60) + missing = tmp_path / 'no-proc' + assert gil.clear_stale_index_lock(repo, proc_root=missing, now=OLD + 60) == gil.UNKNOWN + assert (repo / '.git' / 'index.lock').exists() + + def test_a_checkout_without_a_git_directory_is_left_alone(self, tmp_path): + assert gil.clear_stale_index_lock(tmp_path, proc_root=_proc(tmp_path)) == gil.ABSENT + + +@needs_git +@pytest.mark.skipif(not Path('/proc/self/comm').exists(), reason='needs /proc') +def test_git_works_again_after_a_real_stale_lock_is_cleared(tmp_path): + repo = tmp_path / 'repo' + env = {**os.environ, 'GIT_AUTHOR_NAME': 't', 'GIT_AUTHOR_EMAIL': 't@t', + 'GIT_COMMITTER_NAME': 't', 'GIT_COMMITTER_EMAIL': 't@t'} + + def git(*args): + return subprocess.run(['git', *args], cwd=repo, env=env, capture_output=True, text=True) + repo.mkdir() + git('init', '-q') + (repo / 'a.txt').write_text('a') + lock = repo / '.git' / 'index.lock' + lock.write_text('') + old = time.time() - 60 + os.utime(lock, (old, old)) + assert 'index.lock' in git('add', 'a.txt').stderr + + assert gil.clear_stale_index_lock(repo) == gil.REMOVED + assert git('add', 'a.txt').returncode == 0 + + +# -- Update Code ---------------------------------------------------------------- + +@pytest.fixture +def client(): + app = Flask(__name__) + app.config['TESTING'] = True + app.register_blueprint(api_v3, url_prefix='/api/v3') + api_v3.plugin_store_manager = None + api_v3.config_manager = None + return app.test_client() + + +def _fake_git(calls, pull_rc=0, pull_err=''): + def run(args, **kwargs): + calls.append(list(args)) + if args[:2] == ['git', 'rev-parse'] and args[-1] == 'HEAD': + return subprocess.CompletedProcess(args, 0, stdout='aaa111\n', stderr='') + if 'symbolic-full-name' in args or '@{u}' in args: + return subprocess.CompletedProcess(args, 0, stdout='origin/main\n', stderr='') + if args[:2] == ['git', 'pull']: + return subprocess.CompletedProcess(args, pull_rc, stdout='', stderr=pull_err) + return subprocess.CompletedProcess(args, 0, stdout='', stderr='') + return run + + +def _update(client): + return client.post('/api/v3/system/action', json={'action': 'git_pull'}).get_json() + + +def test_update_code_clears_the_lock_before_running_git(client): + seen = [] + + def clear(project_dir): + seen.append(project_dir) + return gil.REMOVED + calls = [] + with patch.object(gil, 'clear_stale_index_lock', clear), \ + patch.object(mod.subprocess, 'run', _fake_git(calls)): + data = _update(client) + assert seen == [str(mod.PROJECT_ROOT)] + assert data['status'] == 'success' + + +def test_update_code_waits_for_a_git_that_is_still_running(client): + calls = [] + with patch.object(gil, 'clear_stale_index_lock', lambda d: gil.IN_USE), \ + patch.object(mod.subprocess, 'run', _fake_git(calls)): + data = _update(client) + assert data['status'] == 'error' + assert 'Another git command is running' in data['message'] + assert calls == [], "nothing may touch the checkout while another git owns it" + + +def test_a_lock_it_could_not_clear_gets_the_manual_fix(client): + err = "fatal: Unable to create '/home/ledpi/LEDMatrix/.git/index.lock': File exists.\n" + calls = [] + with patch.object(gil, 'clear_stale_index_lock', lambda d: gil.UNKNOWN), \ + patch.object(mod.subprocess, 'run', _fake_git(calls, pull_rc=128, pull_err=err)): + data = _update(client) + assert data['status'] == 'error' + assert data['message'].startswith('Update failed: fatal: Unable to create') + assert 'rm -f ' in data['message'] and 'index.lock' in data['message'] diff --git a/web_interface/auto_update.py b/web_interface/auto_update.py index c8022ed0..51d4e702 100644 --- a/web_interface/auto_update.py +++ b/web_interface/auto_update.py @@ -42,7 +42,7 @@ import time from datetime import datetime from pathlib import Path -from web_interface import update_channel +from web_interface import git_index_lock, update_channel logger = logging.getLogger(__name__) @@ -615,6 +615,9 @@ class AutoUpdater: if core.get('status') != 'success': message = core.get('message') or 'The LEDMatrix update failed.' if new_head and new_head != old_head: + # A pull killed by its timeout leaves .git/index.lock behind, + # and the rollback's reset would fail on it. + git_index_lock.clear_stale_index_lock(self.project_root) ok, detail = rollback() message += (' The partial update was rolled back.' if ok else f' Rolling back the partial update also failed: {detail}.') diff --git a/web_interface/blueprints/api_v3/system.py b/web_interface/blueprints/api_v3/system.py index 35375332..b5c6198e 100644 --- a/web_interface/blueprints/api_v3/system.py +++ b/web_interface/blueprints/api_v3/system.py @@ -332,7 +332,16 @@ def channel_status(project_dir=None, fetch=True): def _perform_core_update_locked(stash_local_changes=True): project_dir = str(PROJECT_ROOT) - from web_interface import update_channel + from web_interface import update_channel, git_index_lock + + # A git killed mid-command (a timed-out pull, a power cut) leaves + # .git/index.lock behind, and every later update then fails with + # "Unable to create .../index.lock: File exists". Remove it when no git + # process can still own it; refuse while one is running. + if git_index_lock.clear_stale_index_lock(project_dir) == git_index_lock.IN_USE: + return {'status': 'error', 'restart_required': False, 'dependency_failures': [], + 'message': 'Another git command is running in the LEDMatrix folder; ' + 'try again in a minute.'} # Which code to move to: the newest release (stable) or main (beta). # See web_interface/update_channel.py; it never picks an older commit. @@ -554,6 +563,8 @@ def _perform_core_update_locked(stash_local_changes=True): detail = next((ln.strip() for ln in (result.stderr or '').splitlines() if ln.strip()), '') pull_message = f"Update failed: {detail}" if detail else "Update failed; check logs for details" + if 'index.lock' in (result.stderr or ''): + pull_message = f"{pull_message} {git_index_lock.manual_fix_hint(project_dir)}" # Nothing here restarts anything: the pull replaces files on # disk while the display and web services keep running the code diff --git a/web_interface/git_index_lock.py b/web_interface/git_index_lock.py new file mode 100644 index 00000000..8ccaa05e --- /dev/null +++ b/web_interface/git_index_lock.py @@ -0,0 +1,143 @@ +"""Clear a stale ``.git/index.lock`` before Update Code touches the checkout. + +git creates ``.git/index.lock`` while it rewrites the index and removes it when +it finishes, or when it is stopped with SIGTERM/SIGINT. A git that dies any +other way leaves the file behind: ``subprocess.run(..., timeout=...)`` SIGKILLs +its child when the timeout expires (a slow pull or checkout on a Pi), and a +power cut or an OOM kill does the same. From then on every git command that +writes the index fails with:: + + fatal: Unable to create '.../.git/index.lock': File exists. + +and Update Code can never succeed again until someone removes it over SSH. + +``clear_stale_index_lock`` removes the file only when it is provably stale: no +git process is running in this checkout, and the file is old enough that no +git can have just created it. When it cannot tell (no ``/proc``), it leaves +the file alone. Standard library only. +""" +import logging +import os +import time +from pathlib import Path + +logger = logging.getLogger(__name__) + +#: A lock younger than this is left alone even when no git process is seen, +#: so a git that started between the process scan and the removal keeps it. +MIN_STALE_AGE_SECONDS = 5 + +#: ``clear_stale_index_lock`` outcomes. +ABSENT = 'absent' # no lock file: nothing to do +REMOVED = 'removed' # it was stale and has been removed +IN_USE = 'in_use' # a git process is running here (or the lock is brand new) +UNKNOWN = 'unknown' # could not tell whether git is running; left alone + +_PROC = Path('/proc') + + +def index_lock_path(project_dir): + """``/.git/index.lock``, or None when ``.git`` is not a directory.""" + git_dir = Path(project_dir) / '.git' + return git_dir / 'index.lock' if git_dir.is_dir() else None + + +def _is_within(path, root): + try: + Path(path).relative_to(root) + return True + except ValueError: + return False + + +def git_running_in(project_dir, proc_root=_PROC): + """True when a git process may be working in ``project_dir``. + + Scans ``/proc`` for processes named ``git`` or ``git-*`` (``git-remote-https`` + and friends) whose working directory is inside the checkout, or whose + arguments name a path in it (``git -C ...``, ``--git-dir=...``). A git process + whose working directory cannot be read (another user's) counts as running + here: it might be. Returns None when ``/proc`` is unavailable. + """ + proc_root = Path(proc_root) + if not proc_root.is_dir(): + return None + root = Path(project_dir).resolve() + try: + entries = list(proc_root.iterdir()) + except OSError: + return None + for entry in entries: + if not entry.name.isdigit(): + continue + try: + comm = (entry / 'comm').read_text().strip() + except OSError: + continue # exited meanwhile + if comm != 'git' and not comm.startswith('git-'): + continue + try: + cwd = os.readlink(entry / 'cwd') + except FileNotFoundError: + continue # exited meanwhile + except OSError: + return True + if _is_within(cwd, root) or _names_checkout(entry, cwd, root): + return True + return False + + +def _names_checkout(entry, cwd, root): + """True when the process's arguments name a path in the checkout + (``-C``, ``--git-dir``, ``--work-tree``, absolute or relative to its + working directory): git can work on it from anywhere. Unreadable + arguments count as naming it.""" + try: + args = os.fsdecode((entry / 'cmdline').read_bytes()).split('\0') + except FileNotFoundError: + return False # exited meanwhile + except OSError: + return True + for arg in args[1:]: + value = arg.split('=', 1)[1] if arg.startswith('--') and '=' in arg else arg + if value and _is_within(os.path.normpath(os.path.join(cwd, value)), root): + return True + return False + + +def clear_stale_index_lock(project_dir, proc_root=_PROC, now=None): + """Remove ``.git/index.lock`` when no git process can still own it. + + Returns one of ABSENT, REMOVED, IN_USE or UNKNOWN. + """ + lock = index_lock_path(project_dir) + if lock is None: + return ABSENT + try: + mtime = lock.stat().st_mtime + except FileNotFoundError: + return ABSENT + except OSError: + return UNKNOWN + running = git_running_in(project_dir, proc_root) + if running is None: + return UNKNOWN + age = (time.time() if now is None else now) - mtime + if running or age < MIN_STALE_AGE_SECONDS: + return IN_USE + try: + lock.unlink() + except FileNotFoundError: + return ABSENT # its owner finished after all + except OSError as exc: + logger.warning("Could not remove stale git lock %s: %s", lock, exc) + return UNKNOWN + logger.warning("Removed stale git lock %s (%.0fs old, no git process running); " + "a previous git command was killed before it finished", lock, age) + return REMOVED + + +def manual_fix_hint(project_dir): + """The sentence shown when a lock blocks the update and was not removed.""" + return (f"If no other git command is running, remove the stale lock with " + f"rm -f {Path(project_dir) / '.git' / 'index.lock'} and try again.")