LEDMatrix/test/test_plugin_reload_off_render_thread.py

"""A ``plugin.reload`` never stalls the render thread (#720 follow-up).

On ledpi a reload of football-scoreboard (a store update, 3.17.0 to 3.18.1)
arrived while Vegas mode was running, and the panel froze for 3.0 s
("Render stall over: no frame for 3043ms"). Vegas yielded at once, but the
reload ran on the render thread, and its first step, unload_plugin(), waited
for the plugin's lock. The strip's prefetch thread held that lock: it was
rebuilding the old instance's Vegas content, which takes seconds for a
scoreboard. The new instance was then loaded on the render thread too
(0.47 s on ledpi).

Now the render thread only takes the plugin out of the rotation and out of
the plugin manager (detach_plugin), and a plugin-reload thread waits for the
lock, tears the old instance down and loads the new one. The new instance
joins the rotation between two frames.

* Real threads, real PluginManager and PluginAdapter: frames keep coming
  (no gap over 100 ms) while a slow Vegas render holds the old instance's
  lock, and the reload still reports the real outcome. Before the fix the
  gap was the whole render.
* The fake-clock run loop (test/_run_loop_harness.py): Vegas frames flow
  through a reload whose thread takes 3 s, the ticker never leaves, and
  the reload is answered when the new instance joins.
* Thread safety: the old instance is torn down only after its render let
  go of the lock, is never asked for content again, and never gets an
  update() once the reload starts; the new one is loaded once.
* The other reload cases still answer as before: a plugin that is on
  screen, one that is not, one that fails to load, and a second reload of
  a plugin that is still loading.
"""

import json
import os
import threading
import time
from types import SimpleNamespace
from unittest.mock import MagicMock

import pytest
from PIL import Image

os.environ.setdefault("EMULATOR", "true")

from src.ipc.contract import Command, ErrorCode, PluginReloadArgs  # noqa: E402
from src.ipc.server import CommandOutcome, QueuedCommand  # noqa: E402
from src.plugin_system.base_plugin import BasePlugin  # noqa: E402
from src.plugin_system.plugin_manager import PluginManager  # noqa: E402
from src.vegas_mode.config import VegasModeConfig  # noqa: E402
from src.vegas_mode.plugin_adapter import PluginAdapter  # noqa: E402
from test._run_loop_harness import FakePlugin, RunLoopHarness  # noqa: E402
from test.test_vegas_elements_api import _DM  # noqa: E402

#: How long the old instance's Vegas render holds its lock. ledpi's was 3 s
#: (scripts in the PR body measure that); the gap scales with it.
RENDER_SECONDS = 1.5
FRAME = 0.008
#: "A frame or two", with room for a slow CI runner.
MAX_GAP = 0.1


def _reload(plugin_id, request_id="r1"):
    return QueuedCommand(request_id=request_id, cmd=Command.PLUGIN_RELOAD,
                         args=PluginReloadArgs(plugin_id), received_at=time.time(),
                         outcome=CommandOutcome())


class _Server:
    """The ControlServer surface the controller drains."""

    def __init__(self):
        self.commands = []

    @property
    def has_pending(self):
        return bool(self.commands)

    def drain(self):
        out, self.commands = self.commands, []
        return out

    def close(self):
        pass


class _Rig:
    """A real PluginManager running one slow-rendering plugin, 'slow'."""

    def __init__(self, tmp_path, render_seconds):
        self.events = []
        self.lock = threading.Lock()
        self.render_started = threading.Event()
        self.render_seconds = render_seconds
        self.generation = 0
        rig = self

        class SlowVegas(BasePlugin):
            """Draws its Vegas content slowly, as a scoreboard does on a Pi."""

            def __init__(self, generation):  # pylint: disable=super-init-not-called
                self.plugin_id = "slow"
                self.config = {"enabled": True}
                self.enabled = True
                self.modes = ["slow"]
                self.plugin_manager = None
                self.generation = generation

            def get_update_interval(self):
                return 0.05

            def update(self):
                rig.log("update", self.generation)

            def display(self, force_clear=False):
                pass

            def validate_config(self):
                return True

            def get_vegas_content(self):
                rig.log("render-start", self.generation)
                rig.render_started.set()
                time.sleep(rig.render_seconds if self.generation == 1 else 0)
                rig.log("render-end", self.generation)
                return [Image.new("RGB", (64, 16), (255, 0, 0))]

            def cleanup(self):
                rig.log("cleanup", self.generation)

            def on_enable(self):
                pass

            def on_disable(self):
                pass

        def construct(**_kw):
            rig.generation += 1
            return SlowVegas(rig.generation), None

        plugin_dir = tmp_path / "plugins" / "slow"
        plugin_dir.mkdir(parents=True)
        self.manifest_path = plugin_dir / "manifest.json"
        manifest = {"id": "slow", "version": "1.0.0", "display_modes": ["slow"]}
        self.manifest_path.write_text(json.dumps(manifest))
        pm = PluginManager(plugins_dir=str(tmp_path / "plugins"))
        pm.plugin_manifests["slow"] = manifest
        pm.schema_manager = MagicMock()
        pm.schema_manager.get_schema_path.return_value = None
        pm.schema_manager.prepare_plugin_config.side_effect = (
            lambda pid, cfg, schema=None, changed_paths=None: cfg)
        pm.plugin_loader = MagicMock()
        pm.plugin_loader.find_plugin_directory.return_value = plugin_dir
        pm.plugin_loader.load_plugin.side_effect = construct
        assert pm.load_plugin("slow")
        self.pm = pm
        self.adapter = PluginAdapter(_DM(), VegasModeConfig(), plugin_manager=pm)
        self.prefetched = []

    def log(self, kind, generation):
        with self.lock:
            self.events.append((kind, generation))

    def index(self, kind, generation):
        return self.events.index((kind, generation))

    def start_vegas_render(self):
        """The strip's prefetch thread rebuilding the old instance's content."""
        plugin = self.pm.plugins["slow"]

        def fetch():
            self.prefetched.append(self.adapter.get_content(plugin, "slow", offscreen_only=True))
        thread = threading.Thread(target=fetch, name="vegas-strip-prefetch", daemon=True)
        thread.start()
        assert self.render_started.wait(2)
        return thread


@pytest.fixture
def dc(test_display_controller):
    c = test_display_controller
    c.display_manager.set_brightness = MagicMock(return_value=True)
    c.display_manager.update_display = MagicMock()
    c.config = {"timezone": "UTC", "display": {"hardware": {"brightness": 90}}}
    c._normal_brightness = 90
    c.current_brightness = 90
    c.is_display_active = True
    c._tz = None
    c.vegas_coordinator = MagicMock()
    return c


def _with_rig(dc, tmp_path, render_seconds=None):
    rig = _Rig(tmp_path, RENDER_SECONDS if render_seconds is None else render_seconds)
    clock = SimpleNamespace(modes=["clock"])
    dc.plugin_manager = rig.pm
    dc.plugin_display_modes = {"clock": ["clock"]}
    dc.available_modes = ["clock"]
    dc.plugin_modes = {"clock": clock}
    dc.mode_to_plugin_id = {"clock": "clock"}
    dc._register_loaded_plugin("slow")
    dc.current_mode_index = 0
    dc.current_display_mode = "clock"
    dc._control_server = _Server()
    return rig


def _render_frames(dc, rig, until, limit):
    """What the render thread does while Vegas runs: one frame every 8 ms,
    servicing pending changes between frames (Vegas's interrupt check) and,
    when a screen-ending command is pending, the top of the loop pass.
    Returns the frame times."""
    frames = [time.perf_counter()]
    deadline = frames[0] + limit
    while not until():
        dc._service_pending_changes()
        if dc._plugin_reload_pending:
            dc._apply_pending_plugin_reloads()     # Vegas yields; resumes next pass
        if len(frames) % 5 == 0:
            rig.pm.run_scheduled_updates()          # the update tick
        time.sleep(FRAME)
        frames.append(time.perf_counter())
        assert frames[-1] < deadline, "the reload never finished"
    return frames


def _max_gap(frames):
    return max(b - a for a, b in zip(frames, frames[1:]))


class TestFramesKeepFlowing:
    def test_a_reload_during_a_slow_vegas_render(self, dc, tmp_path):
        rig = _with_rig(dc, tmp_path)
        old = rig.pm.plugins["slow"]
        prefetch = rig.start_vegas_render()
        rig.manifest_path.write_text(json.dumps(
            {"id": "slow", "version": "2.0.0", "display_modes": ["slow"]}))

        command = _reload("slow")
        posted = time.perf_counter()
        dc._control_server.commands.append(command)
        frames = _render_frames(dc, rig, lambda: command.outcome.done, limit=10)
        answered = time.perf_counter() - posted
        prefetch.join(2)
        rig.pm.stop_update_worker()

        gap = _max_gap(frames)
        print(f"\nlongest frame gap {gap * 1000:.0f} ms, answered after {answered:.2f} s "
              f"(the old instance's render held its lock {RENDER_SECONDS:.1f} s)")
        assert gap < MAX_GAP
        # The real outcome, once the new instance is in the rotation.
        assert command.outcome.result == {"plugin_id": "slow", "reloaded": True,
                                          "version": "2.0.0", "modes": ["slow"]}
        new = rig.pm.plugins["slow"]
        assert new is not old and new.generation == 2
        assert dc.plugin_modes["slow"] is new
        assert dc.available_modes == ["clock", "slow"]
        assert dc.current_display_mode == "clock"
        dc.vegas_coordinator.mark_plugin_updated.assert_called_once_with("slow")
        # The old instance finished its render before it was torn down, and
        # the strip got that render.
        assert rig.index("render-end", 1) < rig.index("cleanup", 1)
        assert rig.prefetched and rig.prefetched[0]
        # Loaded once; no update() of the old instance once it was torn
        # down, and none of the new one before.
        assert rig.generation == 2
        cleanup = rig.index("cleanup", 1)
        assert all(i < cleanup for i, e in enumerate(rig.events) if e == ("update", 1))
        assert all(i > cleanup for i, e in enumerate(rig.events) if e == ("update", 2))

    def test_a_fetch_that_waited_out_the_reload_skips_the_old_instance(self, tmp_path):
        """A Vegas fetch that looked the old instance up before the reload,
        and got its lock only after the teardown, does not run it."""
        rig = _Rig(tmp_path, 0)
        old = rig.pm.detach_plugin("slow")
        assert rig.adapter.get_content(old, "slow", offscreen_only=True) is None
        rig.pm.unload_detached_plugin("slow", old)
        assert rig.pm.reload_plugin("slow")
        assert rig.adapter.get_content(old, "slow", offscreen_only=True) is None
        assert ("render-start", 1) not in rig.events
        # The new instance is fetched as usual.
        assert rig.adapter.get_content(rig.pm.plugins["slow"], "slow", offscreen_only=True)
        assert ("render-start", 2) in rig.events


class TestPluginManagerDetach:
    def test_teardown_waits_for_the_lock_and_leaves_plugins_alone(self, tmp_path):
        rig = _Rig(tmp_path, 0)
        pm = rig.pm
        old = pm.detach_plugin("slow")
        assert "slow" not in pm.plugins and old.generation == 1
        lock = pm.get_plugin_lock("slow")
        lock.acquire()
        done = threading.Event()
        threading.Thread(target=lambda: (pm.unload_detached_plugin("slow", old), done.set()),
                         daemon=True).start()
        assert not done.wait(0.2)            # a render of the old instance holds it
        assert ("cleanup", 1) not in rig.events
        lock.release()
        assert done.wait(5)
        assert ("cleanup", 1) in rig.events
        assert pm.reload_plugin("slow")
        assert pm.plugins["slow"].generation == 2

    def test_teardown_is_refused_while_the_lock_stays_held(self, tmp_path):
        """A Vegas call that took the lock before the detach may still be
        running in the old instance: never tear it down from under it."""
        rig = _Rig(tmp_path, 0)
        pm = rig.pm
        pm.DETACHED_UNLOAD_LOCK_TIMEOUT = 0.2
        old = pm.detach_plugin("slow")
        lock = pm.get_plugin_lock("slow")
        lock.acquire()
        try:
            assert pm.unload_detached_plugin("slow", old) is False
            assert ("cleanup", 1) not in rig.events
        finally:
            lock.release()

    def test_detached_teardown_outwaits_the_ordinary_unload_bound(self):
        # A Vegas build of the old instance held the lock 5.9 s on ledpi.
        from src.plugin_system.plugin_manager import PluginManager
        assert PluginManager.DETACHED_UNLOAD_LOCK_TIMEOUT > 2 * PluginManager.UNLOAD_LOCK_TIMEOUT

    def test_detaching_a_plugin_that_is_not_loaded(self, tmp_path):
        pm = _Rig(tmp_path, 0).pm
        assert pm.detach_plugin("nope") is None


# -- the run loop on the fake clock ----------------------------------------

POSTED = 10.3


def _with_reloadable(h, version="2.0.0", loads=True):
    new = FakePlugin("clock", ["clock"], duration=30)

    def reload_plugin(plugin_id):
        h.log("reload", plugin_id)
        if not loads:
            return False
        new._h = h
        h.pm.plugins[plugin_id] = new
        h.pm.plugin_manifests[plugin_id] = {"version": version, "display_modes": ["clock"]}
        return True

    h.pm.reload_plugin = reload_plugin
    return new


def _vegas(h):
    h.add_plugin(FakePlugin("clock", ["clock"], duration=30))
    h.add_plugin(FakePlugin("weather", ["weather"], duration=30))
    h.enable_vegas(cycle=30)


def _hold_lock(h, plugin_id, seconds):
    """A Vegas render of ``plugin_id`` holds its lock for ``seconds`` from
    when the reload is asked for: the render thread would block that long in
    unload_plugin(), and the plugin-reload thread does instead."""
    real_unload = h.pm.unload_plugin

    def unload_plugin(pid):
        if pid == plugin_id:
            h.clock.sleep(max(0.0, POSTED + seconds - h.clock.rel()))
        return real_unload(pid)
    h.pm.unload_plugin = unload_plugin
    h.reload_seconds = seconds


def _vegas_frame_gaps(h):
    times = [e[0] for e in h.events if e[1] == "vegas-frame"]
    return max(b - a for a, b in zip(times, times[1:]))


def test_vegas_keeps_scrolling_through_a_slow_reload(tmp_path):
    h = RunLoopHarness(tmp_path, horizon=40)
    _vegas(h)
    new = _with_reloadable(h)
    _hold_lock(h, "clock", 3.0)
    command = h.control_socket().post(POSTED, Command.PLUGIN_RELOAD, {"plugin_id": "clock"})
    trace = h.run()

    # Frames every 8 ms throughout: before the fix, none for 3 s.
    assert _vegas_frame_gaps(h) <= 0.1
    # The new instance loaded 3 s later, on its own thread, and joined then.
    reload_at = next(e[0] for e in h.events if e[1] == "reload")
    assert reload_at == pytest.approx(POSTED + 3.0, abs=0.01)
    assert command.outcome.result == {"plugin_id": "clock", "reloaded": True,
                                      "version": "2.0.0", "modes": ["clock"]}
    assert h.controller.plugin_modes["clock"] is new
    assert h.controller.available_modes == ["clock", "weather"]
    # Only the start of the reload ended a Vegas iteration; the ticker
    # carried on through it.
    assert all(r[1] == "<vegas>" for r in trace["screens"] if r[0] >= POSTED)


def test_a_reload_while_on_screen_lets_the_rotation_carry_on(tmp_path):
    h = RunLoopHarness(tmp_path, horizon=70)
    h.add_plugin(FakePlugin("clock", ["clock"], duration=30))
    h.add_plugin(FakePlugin("weather", ["weather"], duration=30))
    new = _with_reloadable(h)
    _hold_lock(h, "clock", 3.0)
    command = h.control_socket().post(POSTED, Command.PLUGIN_RELOAD, {"plugin_id": "clock"})
    trace = h.run()

    # The clock screen ends when the reload is asked for, weather shows
    # while the clock loads, and the reloaded clock comes round next.
    assert trace["screens"][0][:3] == [0.0, "clock", POSTED]
    assert trace["screens"][1][:2] == [POSTED, "weather"]
    assert trace["screens"][2][1] == "clock"
    assert command.outcome.result["reloaded"] is True
    assert h.controller.plugin_modes["clock"] is new


def test_a_reload_of_a_plugin_not_on_screen_keeps_its_place(tmp_path):
    h = RunLoopHarness(tmp_path, horizon=70)
    h.add_plugin(FakePlugin("clock", ["clock"], duration=30))
    h.add_plugin(FakePlugin("weather", ["weather"], duration=30))
    h.add_plugin(FakePlugin("news", ["news"], duration=30))
    new_weather = FakePlugin("weather", ["weather"], duration=30)

    def reload_plugin(plugin_id):
        h.log("reload", plugin_id)
        new_weather._h = h
        h.pm.plugins[plugin_id] = new_weather
        h.pm.plugin_manifests[plugin_id] = {"version": "2.0.0"}
        return True
    h.pm.reload_plugin = reload_plugin
    h.reload_seconds = 3.0
    command = h.control_socket().post(POSTED, Command.PLUGIN_RELOAD, {"plugin_id": "weather"})
    h.run()

    assert command.outcome.result["reloaded"] is True
    assert h.controller.available_modes == ["clock", "weather", "news"]
    assert h.controller.plugin_modes["weather"] is new_weather


def test_a_plugin_that_fails_to_load_after_a_slow_teardown(tmp_path):
    h = RunLoopHarness(tmp_path, horizon=40)
    _vegas(h)
    _with_reloadable(h, loads=False)
    _hold_lock(h, "clock", 3.0)
    command = h.control_socket().post(POSTED, Command.PLUGIN_RELOAD, {"plugin_id": "clock"})
    h.run()

    assert _vegas_frame_gaps(h) <= 0.1
    assert command.outcome.error_code == ErrorCode.FAILED
    assert "clock" not in h.controller.available_modes
    assert "clock" not in h.pm.plugins


def test_a_failed_teardown_stops_the_reload(tmp_path):
    """Loading over a half-unloaded plugin could reuse its old module and
    report a reload that never happened; report the failure instead."""
    h = RunLoopHarness(tmp_path, horizon=40)
    _vegas(h)
    reloads = []
    h.pm.unload_detached_plugin = lambda plugin_id, instance: False
    h.pm.reload_plugin = lambda plugin_id: reloads.append(plugin_id) or True
    command = h.control_socket().post(POSTED, Command.PLUGIN_RELOAD, {"plugin_id": "clock"})
    h.run()

    assert reloads == []
    assert command.outcome.error_code == ErrorCode.FAILED
    assert "restart the display" in command.outcome.error_message
    assert "clock" not in h.controller.available_modes
    assert _vegas_frame_gaps(h) <= 0.1


def test_a_second_reload_while_loading_runs_after_the_first(tmp_path):
    h = RunLoopHarness(tmp_path, horizon=40)
    _vegas(h)
    loads = []

    def reload_plugin(plugin_id):
        plugin = FakePlugin("clock", ["clock"], duration=30)
        plugin._h = h
        loads.append(plugin)
        h.log("reload", plugin_id)
        h.pm.plugins[plugin_id] = plugin
        h.pm.plugin_manifests[plugin_id] = {"version": f"{len(loads)}.0.0"}
        return True
    h.pm.reload_plugin = reload_plugin
    h.reload_seconds = 3.0
    server = h.control_socket()
    first = server.post(POSTED, Command.PLUGIN_RELOAD, {"plugin_id": "clock"}, "a")
    second = server.post(POSTED + 1, Command.PLUGIN_RELOAD, {"plugin_id": "clock"}, "b")
    h.run()

    # The second starts once the first has joined the rotation (within a
    # quarter second of loading), and takes its own 3 s.
    loaded = [e[0] for e in h.events if e[1] == "reload"]
    assert len(loaded) == 2
    assert loaded[0] == pytest.approx(POSTED + 3.0, abs=0.05)
    assert 3.0 <= loaded[1] - loaded[0] <= 3.5
    assert first.outcome.result["version"] == "1.0.0"
    assert second.outcome.result["version"] == "2.0.0"
    assert h.controller.plugin_modes["clock"] is loads[-1]
    assert _vegas_frame_gaps(h) <= 0.1


def test_a_reconcile_during_a_reload_does_not_load_it_twice(dc):
    """The config watcher sees an enabled plugin missing from the rotation
    while it reloads; the reconcile must not load it beside the reload."""
    pm = MagicMock()
    pm.discover_plugins.return_value = ["slow"]
    dc.plugin_manager = pm
    dc.config_service = MagicMock()
    dc.config_service.get_config.return_value = {"slow": {"enabled": True}}
    dc.plugin_display_modes = {}
    dc._plugin_reload_jobs = (SimpleNamespace(plugin_id="slow"),)
    assert dc._reconcile_enabled_plugins() is True
    pm.load_plugin.assert_not_called()
    assert not dc._enabled_plugin_not_running({"slow": {"enabled": True}})

    # Disabled while it reloads: unloaded by a reconcile after the reload.
    dc.config_service.get_config.return_value = {"slow": {"enabled": False}}
    assert dc._reconcile_enabled_plugins() is True
    pm.unload_plugin.assert_not_called()
    assert dc._reconcile_after_reload is True


def test_on_demand_for_a_reloading_plugin_is_refused(dc):
    dc._plugin_reload_jobs = (SimpleNamespace(plugin_id="slow"),)
    dc._load_plugin_for_on_demand = MagicMock()
    dc._activate_on_demand({"plugin_id": "slow"})
    dc._load_plugin_for_on_demand.assert_not_called()
    assert dc.on_demand_last_error == "plugin-reloading"