Kiwy-Signage/windows/test_watchdog.py

"""Verifies windows/watchdog.ps1 actually recovers the player.

Three scenarios, each with a real player process:

  1. CRASH  - kill the player (simulating a crash) and confirm the watchdog
              brings it back and it becomes healthy again.
  2. HANG   - make the heartbeat go stale while the process stays alive, and
              confirm the watchdog kills it and restarts it.
  3. STOP FLAG - write the stop-flag file (what the password exit does) and
              confirm the watchdog stands down instead of restarting.
              Then confirm a fresh watchdog run CLEARS the flag (new session).

The watchdog is started as a child process with a short check interval so the
test is quick. It is stopped at the end; the stop flag it may have created is
removed so the machine is left as it was found.

Run:  windows\\venv\\Scripts\\python.exe windows\\test_watchdog.py
Exit code 0 = PASS.
"""

import subprocess
import sys
import time
from pathlib import Path

WIN = Path(__file__).resolve().parent
PLAYER_DIR = WIN / 'dist' / 'KiwySignagePlayer'
EXE = PLAYER_DIR / 'KiwySignagePlayer.exe'
HEARTBEAT = PLAYER_DIR / '.player_heartbeat'
STOP_FLAG = PLAYER_DIR / '.player_stop_requested'
WATCHDOG = WIN / 'watchdog.ps1'
LOG = PLAYER_DIR / 'logs' / 'watchdog.log'

PS = ['powershell', '-NoProfile', '-ExecutionPolicy', 'Bypass', '-File']

# Fast timings so the test finishes in a reasonable time.
FAST = ['-HealthCheckIntervalSec', '3', '-HeartbeatStaleSec', '10',
        '-StartupGraceSec', '45', '-RestartDelaySec', '2',
        '-CrashLoopMaxFailures', '50', '-CrashLoopBackoffMin', '1']


def kill_players():
    subprocess.run(['taskkill', '/F', '/T', '/IM', 'KiwySignagePlayer.exe'],
                   capture_output=True, text=True)


def player_count():
    out = subprocess.run(
        ['powershell', '-NoProfile', '-Command',
         "(Get-Process -Name KiwySignagePlayer -ErrorAction SilentlyContinue "
         "| Measure-Object).Count"],
        capture_output=True, text=True)
    try:
        return int((out.stdout or '0').strip() or 0)
    except ValueError:
        return 0


def hb_age():
    if not HEARTBEAT.is_file():
        return -1
    return time.time() - HEARTBEAT.stat().st_mtime


def get_root_pid():
    """Return the pid of the player process that owns the window.

    The packaged player is TWO processes (PyInstaller bootloader + child).
    """
    out = subprocess.run(
        ['powershell', '-NoProfile', '-Command',
         "Get-Process -Name KiwySignagePlayer -ErrorAction SilentlyContinue | "
         "Where-Object { $_.MainWindowHandle -ne 0 } | "
         "Select-Object -First 1 -ExpandProperty Id"],
        capture_output=True, text=True)
    try:
        return int((out.stdout or '').strip())
    except ValueError:
        # Fall back to any player process.
        out = subprocess.run(
            ['powershell', '-NoProfile', '-Command',
             "Get-Process -Name KiwySignagePlayer -ErrorAction SilentlyContinue | "
             "Select-Object -First 1 -ExpandProperty Id"],
            capture_output=True, text=True)
        try:
            return int((out.stdout or '').strip())
        except ValueError:
            return None


# ── Exclusive file lock (real Windows share-mode lock) ───────────────
# msvcrt.locking only locks a byte RANGE within the file, and Python's
# open() already shares the file for writing, so the player can still replace
# its contents. Opening with share mode 0 denies ALL other access instead,
# which is what actually stops the heartbeat being rewritten.
import ctypes  # noqa: E402
import ctypes.wintypes as wintypes  # noqa: E402

GENERIC_READ = 0x80000000
GENERIC_WRITE = 0x40000000
OPEN_EXISTING = 3
FILE_ATTRIBUTE_NORMAL = 0x80
INVALID_HANDLE_VALUE = ctypes.c_void_p(-1).value

_kernel32 = ctypes.WinDLL('kernel32', use_last_error=True)
_kernel32.CreateFileW.restype = ctypes.c_void_p
_kernel32.CreateFileW.argtypes = [
    ctypes.c_wchar_p, wintypes.DWORD, wintypes.DWORD, ctypes.c_void_p,
    wintypes.DWORD, wintypes.DWORD, ctypes.c_void_p,
]
_kernel32.CloseHandle.argtypes = [ctypes.c_void_p]


def lock_file_exclusive(path):
    """Open ``path`` denying all sharing. Returns the handle, or None."""
    handle = _kernel32.CreateFileW(
        str(path),
        GENERIC_READ | GENERIC_WRITE,
        0,                      # share mode 0: nobody else may touch it
        None,
        OPEN_EXISTING,
        FILE_ATTRIBUTE_NORMAL,
        None,
    )
    if handle in (None, INVALID_HANDLE_VALUE):
        err = ctypes.get_last_error()
        print(f'  note: CreateFileW failed (winerror={err})')
        return None
    return handle


def unlock_file(handle):
    if handle:
        try:
            _kernel32.CloseHandle(handle)
        except Exception:
            pass


def tail_log(n=14):
    if not LOG.is_file():
        return []
    lines = LOG.read_text(encoding='utf-8', errors='replace').splitlines()
    return lines[-n:]


def main():
    # Tee stdout to a UTF-8 report file: the console in this environment
    # mangles encoding between processes, so the file is the reliable record.
    report_path = WIN / 'watchdog_test_report.txt'

    class _Tee:
        def __init__(self, stream, path):
            self._stream = stream
            self._path = path

        def write(self, text):
            self._stream.write(text)
            try:
                with open(self._path, 'a', encoding='utf-8') as fh:
                    fh.write(text)
            except Exception:
                pass

        def flush(self):
            try:
                self._stream.flush()
            except Exception:
                pass

    try:
        report_path.unlink()
    except Exception:
        pass
    sys.stdout = _Tee(sys.__stdout__, report_path)

    print('=' * 70)
    print(' Watchdog recovery test')
    print('=' * 70)

    if not EXE.is_file():
        print(f'FAIL: player exe not found at {EXE}')
        return 1
    if not WATCHDOG.is_file():
        print(f'FAIL: watchdog not found at {WATCHDOG}')
        return 1

    ok = True
    watchdog = None

    # Clean slate: no player, no leftover stop flag.
    kill_players()
    if STOP_FLAG.exists():
        STOP_FLAG.unlink()
    time.sleep(2)

    try:
        # ---------------------------------------------------------------
        # Start the watchdog; it should launch the player itself.
        # ---------------------------------------------------------------
        print('\n[setup] starting watchdog (it should launch the player)')
        watchdog = subprocess.Popen(
            PS + [str(WATCHDOG)] + FAST,
            cwd=str(WIN),
            creationflags=getattr(subprocess, 'CREATE_NEW_CONSOLE', 0),
        )

        # Wait for the player to come up and report a heartbeat.
        deadline = time.time() + 90
        healthy = False
        while time.time() < deadline:
            time.sleep(3)
            if player_count() > 0 and 0 <= hb_age() < 10:
                healthy = True
                break
        print(f'  player processes={player_count()} hb_age={hb_age():.0f}s')
        if not healthy:
            print('  FAIL: player never became healthy under the watchdog')
            ok = False
        else:
            print('  OK: watchdog launched the player and it is healthy')

        # ---------------------------------------------------------------
        # 1. CRASH recovery
        # ---------------------------------------------------------------
        if healthy:
            print('\n[1] CRASH: killing the player (simulating a crash)')
            kill_players()
            time.sleep(2)
            print(f'  after kill: processes={player_count()}')

            recovered = False
            deadline = time.time() + 150
            while time.time() < deadline:
                time.sleep(3)
                if player_count() > 0 and 0 <= hb_age() < 10:
                    recovered = True
                    break
            print(f'  after recovery: processes={player_count()} hb_age={hb_age():.0f}s')
            if recovered:
                print('  OK: watchdog restarted the player after the crash')
            else:
                print('  FAIL: watchdog did not restore a healthy player')
                ok = False

            # -----------------------------------------------------------
            # 2. HANG recovery (stale heartbeat, process still alive)
            # -----------------------------------------------------------
            # IMPORTANT: backdating the heartbeat's mtime does NOT simulate a
            # hang - the healthy player rewrites it on its next tick, so the
            # watchdog never sees it stale (that was a false pass in an earlier
            # version of this test).
            #
            # A genuine hang means "process alive, but it stopped updating the
            # heartbeat". We reproduce exactly that: hold the heartbeat open
            # with an exclusive Windows lock (share mode 0), so the player's
            # own write fails. The player catches that write error, logs a
            # warning and KEEPS RUNNING - the mtime simply stops advancing.
            # That is precisely the condition the watchdog tests for.
            print('\n[2] HANG: freezing the heartbeat (player stays alive)')
            pid_before = get_root_pid()
            if pid_before is None:
                print('  FAIL: could not find the player process')
                ok = False
            else:
                handle = lock_file_exclusive(HEARTBEAT)
                if handle is None:
                    print('  FAIL: could not lock the heartbeat file')
                    ok = False
                else:
                    print(f'  holding an exclusive lock on the heartbeat; '
                          f'player pid={pid_before} should stay alive')

                    # Wait for the heartbeat to go stale while the process lives.
                    stale_seen = False
                    deadline = time.time() + 90
                    while time.time() < deadline:
                        time.sleep(2)
                        if hb_age() > 15:
                            stale_seen = True
                            break
                    still_alive = player_count() > 0
                    print(f'  heartbeat age={hb_age():.0f}s stale={stale_seen}; '
                          f'player still running={still_alive}')
                    if not (stale_seen and still_alive):
                        print('  FAIL: could not create a genuine stale-heartbeat hang')
                        ok = False

                    # The watchdog should kill the frozen player...
                    old_killed = False
                    deadline = time.time() + 90
                    while time.time() < deadline:
                        time.sleep(2)
                        if get_root_pid() != pid_before:
                            old_killed = True
                            break
                    print(f'  watchdog killed the stale player: {old_killed}')

                    # ...release the lock so the replacement can write...
                    unlock_file(handle)

                    # ...and confirm a fresh, healthy player is now running.
                    restarted = False
                    deadline = time.time() + 150
                    while time.time() < deadline:
                        time.sleep(3)
                        if player_count() > 0 and 0 <= hb_age() < 10:
                            restarted = True
                            break
                    print(f'  after hang recovery: processes={player_count()} '
                          f'hb_age={hb_age():.0f}s')
                    if old_killed and restarted:
                        print('  OK: watchdog detected the hang and restarted the player')
                    else:
                        print('  FAIL: watchdog did not recover from the hang')
                        ok = False

        # ---------------------------------------------------------------
        # 3. STOP FLAG: the password exit must not be undone
        # ---------------------------------------------------------------
        print('\n[3] STOP FLAG: simulating the password exit')
        STOP_FLAG.write_text('User requested exit via password', encoding='utf-8')
        print('  wrote the stop flag')

        # The player is running; give the watchdog time to notice and stand down.
        stood_down = False
        deadline = time.time() + 90
        while time.time() < deadline:
            time.sleep(3)
            if watchdog.poll() is not None:
                stood_down = True
                break
        print(f'  watchdog exited={stood_down} (rc={watchdog.poll()})')
        if stood_down:
            print('  OK: watchdog stood down instead of restarting')
        else:
            print('  FAIL: watchdog did not stand down on the stop flag')
            ok = False

        # Confirm it really stops restarting: kill the player and verify it
        # stays dead now that the watchdog is gone.
        kill_players()
        time.sleep(8)
        if player_count() == 0:
            print('  OK: player stayed stopped (no supervisor resurrecting it)')
        else:
            print('  FAIL: player was restarted despite the stop flag')
            ok = False

        # ---------------------------------------------------------------
        # 4. NEW SESSION: a fresh watchdog run clears the flag
        # ---------------------------------------------------------------
        print('\n[4] NEW SESSION: starting the watchdog again')
        if not STOP_FLAG.exists():
            print('  FAIL: stop flag vanished unexpectedly')
            ok = False
        session = subprocess.Popen(
            PS + [str(WATCHDOG), '-Status'],
            cwd=str(WIN), stdout=subprocess.PIPE, stderr=subprocess.STDOUT,
            text=True)
        # -Status must NOT clear the flag (it is read-only).
        try:
            session.wait(timeout=60)
        except subprocess.TimeoutExpired:
            session.kill()
        if STOP_FLAG.exists():
            print('  OK: -Status is read-only (flag untouched)')
        else:
            print('  FAIL: -Status cleared the flag (should be read-only)')
            ok = False

        # A real run clears it, then launches the player.
        fresh = subprocess.Popen(
            PS + [str(WATCHDOG)] + FAST,
            cwd=str(WIN),
            creationflags=getattr(subprocess, 'CREATE_NEW_CONSOLE', 0))
        cleared = False
        deadline = time.time() + 60
        while time.time() < deadline:
            time.sleep(2)
            if not STOP_FLAG.exists():
                cleared = True
                break
        print(f'  stop flag cleared by the new session: {cleared}')
        if cleared:
            print('  OK: a fresh launch starts a new session (flag cleared)')
        else:
            print('  FAIL: the new session did not clear the stop flag')
            ok = False

        # And the player comes back up.
        back_up = False
        deadline = time.time() + 120
        while time.time() < deadline:
            time.sleep(3)
            if player_count() > 0 and 0 <= hb_age() < 10:
                back_up = True
                break
        print(f'  player back up: {back_up} (processes={player_count()})')
        if back_up:
            print('  OK: player resumed supervision after the new session')
        else:
            print('  FAIL: player did not come back in the new session')
            ok = False

        fresh.terminate()

    finally:
        # ---------------------------------------------------------------
        # Leave the machine as we found it.
        # ---------------------------------------------------------------
        for p in (watchdog,):
            if p is not None and p.poll() is None:
                p.terminate()
        subprocess.run(
            ['powershell', '-NoProfile', '-Command',
             "Get-CimInstance Win32_Process -Filter \"Name='powershell.exe'\" | "
             "Where-Object { $_.CommandLine -like '*watchdog.ps1*' } | "
             "ForEach-Object { Stop-Process -Id $_.ProcessId -Force }"],
            capture_output=True, text=True)
        kill_players()
        if STOP_FLAG.exists():
            STOP_FLAG.unlink()
        print('\n[cleanup] player stopped, watchdog stopped, stop flag removed')

    print('\n=== last watchdog log lines ===')
    for line in tail_log(12):
        print('  ' + line)

    print('=' * 70)
    print(' RESULT:', 'PASS' if ok else 'FAIL')
    print('=' * 70)
    return 0 if ok else 1


if __name__ == '__main__':
    sys.exit(main())