LEDMatrix/test/test_plugin_hang_containment.py

"""One hung plugin must not stop every other plugin from updating.

The update worker is a single thread. It took each plugin's lock with a
blocking ``acquire()``, and the render thread holds that same lock while it
runs the plugin's display(). A display() that never returned -- or a first
frame that outlived PluginExecutor's timeout and kept running on its lingering
thread -- parked the worker on that acquire for good, and from then on no
plugin updated at all: scores, weather and clocks all froze while the panel
kept scrolling stale data.

Now:
- the worker waits PLUGIN_LOCK_TIMEOUT at most and skips the busy plugin. The
  skip is report-only (a busy skip in health): the holder may be a healthy
  Vegas prefetch render, so it never counts toward the circuit breaker;
- display() calls are timed, slow ones recorded, overlong ones counted as
  hangs; update() past the executor timeout is a hang too. Only hangs open
  the breaker;
- on_config_change runs under the plugin's lock, deferred to the worker if the
  lock stays busy, so it never interleaves with update().

Timeouts here are fractions of a second so the suite stays fast.
"""

import copy
import threading
import time
import types
from unittest.mock import MagicMock

import pytest

from src.plugin_system.plugin_health import CircuitState, PluginHealthTracker
from src.plugin_system.plugin_manager import PluginManager
from src.plugin_system.plugin_state import PluginState


class _Cache:
    """Serialising stand-in for CacheManager; counts writes."""

    def __init__(self):
        self.store = {}
        self.writes = 0

    def set(self, key, data, ttl=None, **kwargs):
        self.writes += 1
        self.store[key] = copy.deepcopy(data)

    def get(self, key, max_age=None, memory_ttl=None, **kwargs):
        return copy.deepcopy(self.store.get(key))


class _Plugin:
    """Counts update() calls; display() can be made to block on an Event."""

    def __init__(self, plugin_id, update_seconds=0.0):
        self.plugin_id = plugin_id
        self.enabled = True
        self.update_seconds = update_seconds
        self.update_calls = 0
        self.in_update = False
        self.display_gate = None  # threading.Event: display() blocks on it
        self.config_changes = []
        self.overlap = False
        self.events = []

    def update(self):
        self.in_update = True
        self.update_calls += 1
        self.events.append('update')
        time.sleep(self.update_seconds)
        self.in_update = False

    def display(self, force_clear=False):
        if self.display_gate is not None:
            self.display_gate.wait(timeout=10)
        return True

    def on_config_change(self, new_config):
        if self.in_update:
            self.overlap = True
        self.events.append('config')
        self.config_changes.append(new_config)


@pytest.fixture
def pm(tmp_path):
    manager = PluginManager(plugins_dir=str(tmp_path), config_manager=None,
                            display_manager=None, cache_manager=None)
    manager.PLUGIN_LOCK_TIMEOUT = 0.15
    yield manager
    manager.stop_update_worker()


@pytest.fixture
def tracker(pm):
    t = PluginHealthTracker(cache_manager=_Cache())
    pm.health_tracker = t
    return t


def _install(pm, plugin, interval=0.01):
    pm.plugins[plugin.plugin_id] = plugin
    pm._update_interval_cache[plugin.plugin_id] = interval
    pm.state_manager.set_state(plugin.plugin_id, PluginState.ENABLED)
    return plugin.plugin_id


def _hang_display(pm, plugin):
    """Run the plugin's display() the way the render loop does, on its own
    thread, holding the plugin's lock while display() blocks on its gate."""
    plugin.display_gate = threading.Event()
    entered = threading.Event()

    def render():
        lock = pm.get_plugin_lock(plugin.plugin_id)
        with lock:
            entered.set()
            plugin.display()

    thread = threading.Thread(target=render, daemon=True)
    thread.start()
    assert entered.wait(timeout=2)
    return plugin.display_gate, thread


def _wait_for(predicate, timeout=3.0):
    deadline = time.monotonic() + timeout
    while time.monotonic() < deadline:
        if predicate():
            return True
        time.sleep(0.01)
    return predicate()


class TestHungDisplayDoesNotStallTheWorker:
    def test_other_plugins_keep_updating_on_schedule(self, pm):
        hung = _Plugin('hung')
        healthy = _Plugin('healthy')
        _install(pm, hung)
        _install(pm, healthy)
        gate, render_thread = _hang_display(pm, hung)
        try:
            # 'hung' is dict-ordered first, so its item is dequeued ahead of
            # 'healthy' every round. With a blocking acquire the worker parks
            # on it forever and 'healthy' never updates.
            for _ in range(8):
                pm.run_scheduled_updates()
                time.sleep(0.05)
            assert _wait_for(lambda: healthy.update_calls >= 2), (
                f"healthy plugin updated {healthy.update_calls} time(s) while "
                "another plugin's display() was hung")
            assert hung.update_calls == 0
            assert pm._update_worker.is_alive()
        finally:
            gate.set()
            render_thread.join(timeout=2)

    def test_hung_plugin_is_retried_once_its_display_returns(self, pm):
        plugin = _Plugin('hung')
        _install(pm, plugin)
        gate, render_thread = _hang_display(pm, plugin)
        pm.run_scheduled_updates()
        # Skipped, and handed back rather than left RUNNING.
        assert _wait_for(lambda: pm.state_manager.can_execute('hung'))
        assert 'hung' not in pm._pending_updates
        gate.set()
        render_thread.join(timeout=2)
        pm.plugin_last_update.pop('hung', None)  # due again now
        pm.run_scheduled_updates()
        assert _wait_for(lambda: plugin.update_calls == 1)


class TestLockTimeoutIsReportOnly:
    def test_skip_lands_in_health_and_state_as_a_busy_skip(self, pm, tracker):
        plugin = _Plugin('hung')
        _install(pm, plugin)
        gate, render_thread = _hang_display(pm, plugin)
        try:
            pm.run_scheduled_updates()
            assert _wait_for(lambda: tracker.get_health_summary('hung')['busy_skip_count'] == 1)
            summary = tracker.get_health_summary('hung')
            assert summary['last_busy_skip']['operation'] == 'update lock wait'
            assert summary['last_busy_skip']['seconds'] >= pm.PLUGIN_LOCK_TIMEOUT - 0.01
            # Reporting only: no failure, no hang, no error, breaker closed.
            assert summary['consecutive_failures'] == 0
            assert summary['total_failures'] == 0
            assert summary['hang_count'] == 0
            assert summary['last_error'] is None
            assert summary['circuit_state'] == CircuitState.CLOSED.value
            # Still visible in the plugin's state for the web UI.
            error_info = pm.state_manager.get_error_info('hung')
            assert error_info['error_type'] == 'PluginBusyError'
            # Stamped like any failed update, so the retry waits an interval.
            assert pm.plugin_last_update.get('hung', 0) > 0
        finally:
            gate.set()
            render_thread.join(timeout=2)

    def test_repeated_busy_skips_never_open_the_circuit_breaker(self, pm, tracker):
        """A Vegas prefetch render can hold a healthy plugin's lock past the
        bound on every update; that must not pull it from rotation."""
        plugin = _Plugin('busy')
        _install(pm, plugin)
        gate, render_thread = _hang_display(pm, plugin)
        skips = tracker.failure_threshold * 3
        try:
            for attempt in range(1, skips + 1):
                pm.run_scheduled_updates()
                assert _wait_for(
                    lambda: pm.state_manager.can_execute('busy')
                    and tracker.get_health_summary('busy')['busy_skip_count'] == attempt)
                time.sleep(0.02)  # past the 0.01s interval
            summary = tracker.get_health_summary('busy')
            assert summary['busy_skip_count'] == skips
            assert summary['consecutive_failures'] == 0
            assert summary['hang_count'] == 0
            assert summary['circuit_state'] == CircuitState.CLOSED.value
            assert tracker.should_skip_plugin('busy') is False
        finally:
            gate.set()
            render_thread.join(timeout=2)
        # Once the lock frees the plugin updates normally.
        pm.plugin_last_update.pop('busy', None)
        pm.run_scheduled_updates()
        assert _wait_for(lambda: plugin.update_calls == 1)

    def test_busy_skips_do_not_add_to_a_real_hang_streak(self, pm, tracker):
        plugin = _Plugin('p')
        _install(pm, plugin)
        tracker.record_hang('p', 'display', 31.0)
        gate, render_thread = _hang_display(pm, plugin)
        try:
            for attempt in range(1, tracker.failure_threshold + 2):
                pm.run_scheduled_updates()
                assert _wait_for(
                    lambda: pm.state_manager.can_execute('p')
                    and tracker.get_health_summary('p')['busy_skip_count'] == attempt)
                time.sleep(0.02)
        finally:
            gate.set()
            render_thread.join(timeout=2)
        summary = tracker.get_health_summary('p')
        assert summary['consecutive_failures'] == 1
        assert summary['hang_count'] == 1
        assert summary['circuit_state'] == CircuitState.CLOSED.value

    def test_repeated_real_hangs_still_open_the_circuit_breaker(self, pm, tracker):
        """display() past the executor timeout is a real hang: the breaker
        opens after failure_threshold of them, busy skips in between or not."""
        plugin = _Plugin('hung')
        _install(pm, plugin)
        gate, render_thread = _hang_display(pm, plugin)
        too_long = pm.plugin_executor.default_timeout + 1
        try:
            for attempt in range(1, tracker.failure_threshold + 1):
                pm.run_scheduled_updates()
                assert _wait_for(
                    lambda: pm.state_manager.can_execute('hung')
                    and tracker.get_health_summary('hung')['busy_skip_count'] == attempt)
                assert tracker.get_health_summary('hung')['circuit_state'] ==                     CircuitState.CLOSED.value
                pm.note_display_duration('hung', too_long)
                time.sleep(0.02)  # past the 0.01s interval
            summary = tracker.get_health_summary('hung')
            assert summary['hang_count'] == tracker.failure_threshold
            assert summary['busy_skip_count'] == tracker.failure_threshold
            assert summary['circuit_state'] == CircuitState.OPEN.value
            assert tracker.should_skip_plugin('hung') is True
            # Circuit open: the scheduler no longer queues it at all.
            pm.run_scheduled_updates()
            assert 'hung' not in pm._pending_updates
        finally:
            gate.set()
            render_thread.join(timeout=2)

    def test_skip_is_logged_once_per_interval(self, pm):
        pm.logger = MagicMock()
        plugin = _Plugin('hung')
        _install(pm, plugin)
        gate, render_thread = _hang_display(pm, plugin)
        try:
            for _ in range(3):
                pm.run_scheduled_updates()
                assert _wait_for(lambda: pm.state_manager.can_execute('hung'))
                time.sleep(0.02)
        finally:
            gate.set()
            render_thread.join(timeout=2)
        busy_warnings = [c for c in pm.logger.warning.call_args_list
                         if 'update skipped' in c.args[0]]
        assert len(busy_warnings) == 1

    def test_unloaded_while_waiting_is_not_resurrected(self, pm, tracker):
        plugin = _Plugin('hung')
        _install(pm, plugin)
        gate, render_thread = _hang_display(pm, plugin)
        try:
            pm.PLUGIN_LOCK_TIMEOUT = 0.3
            pm.UNLOAD_LOCK_TIMEOUT = 0.05
            pm.run_scheduled_updates()
            time.sleep(0.05)  # worker is now waiting on the lock
            assert pm.unload_plugin('hung') is True
            assert _wait_for(lambda: 'hung' not in pm._pending_updates)
            time.sleep(0.35)
            assert pm.state_manager.get_state('hung') == PluginState.UNLOADED
            summary = tracker.get_health_summary('hung')
            assert summary['hang_count'] == 0
            assert summary['busy_skip_count'] == 0
        finally:
            gate.set()
            render_thread.join(timeout=2)


class TestUpdateOutlivingTheExecutorTimeout:
    def test_recorded_as_a_hang_then_cleared_when_it_returns(self, pm, tracker):
        plugin = _Plugin('slow', update_seconds=0.4)
        _install(pm, plugin)
        pm.plugin_executor.default_timeout = 0.05
        pm.run_scheduled_updates()
        assert _wait_for(lambda: tracker.get_health_summary('slow')['hang_count'] == 1)
        summary = tracker.get_health_summary('slow')
        assert summary['last_hang']['operation'] == 'update'
        assert summary['consecutive_failures'] == 1
        # The real update() then returns: success resets the streak.
        assert _wait_for(lambda: pm.state_manager.can_execute('slow'))
        assert _wait_for(lambda: tracker.get_health_summary('slow')['consecutive_failures'] == 0)


class TestDisplayTiming:
    def test_fast_frames_record_nothing(self, pm, tracker):
        pm.logger = MagicMock()
        for _ in range(100):
            pm.note_display_duration('p', 0.004)
        assert tracker.get_health_summary('p')['slow_call_count'] == 0
        pm.logger.warning.assert_not_called()

    def test_slow_display_is_recorded_and_warned_once(self, pm, tracker):
        pm.logger = MagicMock()
        for _ in range(5):
            pm.note_display_duration('p', 2.5)
        summary = tracker.get_health_summary('p')
        assert summary['slow_call_count'] == 5
        assert summary['last_slow_call']['operation'] == 'display'
        assert summary['last_slow_call']['seconds'] == 2.5
        # Slow is not failing: the circuit breaker is untouched.
        assert summary['consecutive_failures'] == 0
        assert summary['circuit_state'] == CircuitState.CLOSED.value
        assert pm.logger.warning.call_count == 1

    def test_suppressed_repeats_are_counted_in_the_next_warning(self, pm):
        pm.logger = MagicMock()
        for _ in range(4):
            pm.note_display_duration('p', 2.5)
        pm.HANG_LOG_INTERVAL = 0.0
        pm.note_display_duration('p', 2.5)
        assert pm.logger.warning.call_count == 2
        last = pm.logger.warning.call_args
        assert '3 more since the last warning' in (last.args[0] % last.args[1:])

    def test_display_past_the_executor_timeout_is_a_hang(self, pm, tracker):
        pm.plugin_executor.default_timeout = 3.0
        for _ in range(tracker.failure_threshold):
            pm.note_display_duration('p', 3.5)
        summary = tracker.get_health_summary('p')
        assert summary['hang_count'] == tracker.failure_threshold
        assert summary['last_hang']['operation'] == 'display'
        assert summary['circuit_state'] == CircuitState.OPEN.value

    def test_render_loop_times_each_frame(self, monkeypatch, emulator_mode):
        """DisplayController._display_once hands every frame's duration on."""
        from src import display_controller as dc_module
        ticks = iter([100.0, 103.25])
        monkeypatch.setattr(dc_module, 'time', types.SimpleNamespace(
            monotonic=lambda: next(ticks)))
        controller = dc_module.DisplayController.__new__(dc_module.DisplayController)
        controller.plugin_manager = MagicMock()
        lock = threading.Lock()
        controller.plugin_manager.get_plugin_lock.return_value = lock
        plugin = _Plugin('ticker')

        assert controller._display_once(plugin, 'ticker', False) is True

        controller.plugin_manager.note_display_duration.assert_called_once_with('ticker', 3.25)
        assert not lock.locked()

    def test_skipped_frame_is_not_timed(self, emulator_mode):
        from src import display_controller as dc_module
        controller = dc_module.DisplayController.__new__(dc_module.DisplayController)
        controller.plugin_manager = MagicMock()
        lock = threading.Lock()
        lock.acquire()  # update() in flight
        controller.plugin_manager.get_plugin_lock.return_value = lock
        try:
            assert controller._display_once(_Plugin('ticker'), 'ticker', False) is True
        finally:
            lock.release()
        controller.plugin_manager.note_display_duration.assert_not_called()


class TestConfigChangeIsSerialised:
    def test_does_not_run_concurrently_with_update(self, pm):
        pm.PLUGIN_LOCK_TIMEOUT = 2.0
        plugin = _Plugin('p', update_seconds=0.3)
        _install(pm, plugin)
        pm.run_scheduled_updates()
        assert _wait_for(lambda: plugin.in_update)

        applied = pm.apply_config_change('p', {'enabled': True, 'n': 1})

        assert applied is True
        assert plugin.overlap is False
        assert plugin.events == ['update', 'config']
        assert plugin.config_changes == [{'enabled': True, 'n': 1}]

    def test_runs_holding_the_plugin_lock(self, pm):
        plugin = _Plugin('p')
        _install(pm, plugin)
        held = {}
        plugin.on_config_change = lambda cfg: held.setdefault(
            'locked', pm.get_plugin_lock('p').locked())
        assert pm.apply_config_change('p', {}) is True
        assert held == {'locked': True}
        assert not pm.get_plugin_lock('p').locked()

    def test_busy_lock_defers_the_latest_change_to_before_the_next_update(self, pm):
        plugin = _Plugin('p')
        _install(pm, plugin)
        gate, render_thread = _hang_display(pm, plugin)
        try:
            start = time.monotonic()
            assert pm.apply_config_change('p', {'n': 1}) is False
            assert time.monotonic() - start < 1.0, "the wait must be bounded"
            assert pm.apply_config_change('p', {'n': 2}) is False
            time.sleep(0.4)  # the worker's own bounded retry also finds it busy
            assert plugin.config_changes == []
        finally:
            gate.set()
            render_thread.join(timeout=2)

        pm.run_scheduled_updates()
        assert _wait_for(lambda: plugin.update_calls == 1)
        # Only the latest parked change, applied before the update ran.
        assert plugin.config_changes == [{'n': 2}]
        assert plugin.events == ['config', 'update']
        assert plugin.overlap is False

    def test_deferred_change_applied_by_worker_once_lock_frees(self, pm):
        """No update due to piggyback on: the worker's own queued retry
        applies it. Timeline: the watcher gives up at 0.2s, the worker waits
        from 0.2s to 0.4s, the holder lets go at 0.3s."""
        pm.PLUGIN_LOCK_TIMEOUT = 0.2
        plugin = _Plugin('p')
        _install(pm, plugin, interval=3600)
        pm.plugin_last_update['p'] = time.time()  # not due
        lock = pm.get_plugin_lock('p')
        lock.acquire()
        releaser = threading.Timer(0.3, lock.release)
        releaser.start()
        try:
            assert pm.apply_config_change('p', {'n': 1}) is False
            assert _wait_for(lambda: plugin.config_changes == [{'n': 1}])
        finally:
            releaser.join(timeout=2)
        assert plugin.update_calls == 0
        assert 'p' not in pm._deferred_config_changes

    def test_stale_deferred_change_is_dropped_after_reload(self, pm):
        plugin = _Plugin('p')
        _install(pm, plugin)
        pm._deferred_config_changes['p'] = (plugin, {'n': 1})
        replacement = _Plugin('p')
        pm.plugins['p'] = replacement
        pm._apply_deferred_config_change('p')
        assert plugin.config_changes == []
        assert replacement.config_changes == []
        assert 'p' not in pm._deferred_config_changes

    def test_exceptions_still_reach_the_caller(self, pm):
        plugin = _Plugin('p')
        _install(pm, plugin)

        def boom(cfg):
            raise ValueError("bad config")

        plugin.on_config_change = boom
        with pytest.raises(ValueError):
            pm.apply_config_change('p', {})
        assert not pm.get_plugin_lock('p').locked()


class TestHealthRecords:
    def test_slow_call_persistence_is_rate_limited(self):
        cache = _Cache()
        t = PluginHealthTracker(cache_manager=cache)
        t.record_slow_call('p', 'display', 2.5)
        writes = cache.writes
        for _ in range(50):
            t.record_slow_call('p', 'display', 2.5)
        assert cache.writes == writes
        assert t.get_health_summary('p')['slow_call_count'] == 51

    def test_busy_skip_persistence_is_rate_limited_and_breaker_free(self):
        cache = _Cache()
        t = PluginHealthTracker(cache_manager=cache)
        t.record_busy_skip('p', 'update lock wait', 5.0)
        writes = cache.writes
        # The first one is saved at once, so the web process sees it.
        assert PluginHealthTracker(cache_manager=cache).get_health_summary(
            'p')['busy_skip_count'] == 1
        for _ in range(50):
            t.record_busy_skip('p', 'update lock wait', 5.0)
        assert cache.writes == writes
        summary = t.get_health_summary('p')
        assert summary['busy_skip_count'] == 51
        assert summary['consecutive_failures'] == 0
        assert summary['circuit_state'] == CircuitState.CLOSED.value
        assert t.should_skip_plugin('p') is False

    def test_hang_survives_a_restart(self):
        cache = _Cache()
        PluginHealthTracker(cache_manager=cache).record_hang('p', 'display', 31.0)
        summary = PluginHealthTracker(cache_manager=cache).get_health_summary('p')
        assert summary['hang_count'] == 1
        assert summary['last_hang']['operation'] == 'display'
        assert summary['consecutive_failures'] == 1