hermes-agent/tests/hermes_cli/test_plugin_hook_failure_reporting.py

"""A plugin hook that fails identically on every call is reported once, not once per call.

A callback whose signature names a parameter the hook never sends (``tool_data`` instead of
``tool_name``/``args``) raises the same ``TypeError`` on every tool call; before the fix core
logged a WARNING each time — ~1700 lines an hour in the report that motivated this (#111922).
"""

import logging

import pytest

from hermes_cli.plugins import PluginManager


@pytest.fixture()
def manager(tmp_path, monkeypatch):
    monkeypatch.setenv("HERMES_HOME", str(tmp_path / "hermes_home"))
    return PluginManager()


def test_identical_hook_failure_warns_once_then_debug(manager, caplog):
    def on_pre_tool(tool_data):  # core sends tool_name/args, never tool_data
        return None

    manager._hooks.setdefault("pre_tool_call", []).append(on_pre_tool)
    with caplog.at_level(logging.DEBUG, logger="hermes_cli.plugins"):
        for i in range(5):
            manager.invoke_hook("pre_tool_call", tool_name="read_file", args={"path": f"/p{i}"})

    warnings = [r for r in caplog.records if r.levelno == logging.WARNING and "on_pre_tool" in r.getMessage()]
    debugs = [r for r in caplog.records if r.levelno == logging.DEBUG and "on_pre_tool" in r.getMessage()]
    assert len(warnings) == 1
    assert len(debugs) == 4
    # The one warning tells the author what the hook actually provides.
    assert "tool_data" in warnings[0].getMessage()
    assert "tool_name" in warnings[0].getMessage()


def test_distinct_hook_failures_each_warn(manager, caplog):
    """Deduplication is per distinct error: a callback failing in a new way still warns."""
    calls = []

    def flaky(**kwargs):
        calls.append(1)
        raise RuntimeError(f"failure #{len(calls)}")

    manager._hooks.setdefault("post_tool_call", []).append(flaky)
    with caplog.at_level(logging.DEBUG, logger="hermes_cli.plugins"):
        for _ in range(3):
            manager.invoke_hook("post_tool_call", tool_name="x", args={}, result="ok")

    warnings = [r for r in caplog.records if r.levelno == logging.WARNING and "flaky" in r.getMessage()]
    assert len(warnings) == 3


def test_middleware_failure_warns_once_and_unload_forgets_it(manager, caplog):
    """Middleware runs once per tool call like a hook, so it dedupes the same way; a plugin
    reload (unload-all) forgets the reported failures so the reloaded callback's first failure
    warns again."""
    def on_exec(tool_data):  # core sends tool_name/args, never tool_data
        return None

    manager._middleware.setdefault("agent_tool_execution", []).append(on_exec)
    with caplog.at_level(logging.DEBUG, logger="hermes_cli.plugins"):
        for i in range(3):
            manager.invoke_middleware("agent_tool_execution", tool_name="x", args={"path": f"/p{i}"})
        manager._reset_after_unload_all([])
        assert not manager._hook_failures_reported
        manager._middleware.setdefault("agent_tool_execution", []).append(on_exec)
        manager.invoke_middleware("agent_tool_execution", tool_name="x", args={})

    warnings = [r for r in caplog.records if r.levelno == logging.WARNING and "on_exec" in r.getMessage()]
    assert len(warnings) == 2
    assert "Middleware 'agent_tool_execution'" in warnings[0].getMessage()


def test_execution_chain_middleware_failure_warns_once(manager, caplog, monkeypatch):
    """The execution chain (``tool_execution``/``llm_execution``, one frame per tool or LLM call)
    reports a mis-declared callback through the same warn-once path as hooks — and still skips the
    frame and runs the tool."""
    from hermes_cli import middleware as mw

    monkeypatch.setattr("hermes_cli.plugins._plugin_manager", manager)

    def on_exec(tool_data, next_call):  # core sends tool_name/args, never tool_data
        return next_call()

    manager._middleware.setdefault(mw.TOOL_EXECUTION_MIDDLEWARE, []).append(on_exec)
    with caplog.at_level(logging.DEBUG):
        results = [
            mw.run_tool_execution_middleware("read_file", {"path": f"/p{i}"}, lambda args: "ran")
            for i in range(4)
        ]

    assert results == ["ran"] * 4
    warnings = [r for r in caplog.records if r.levelno == logging.WARNING and "on_exec" in r.getMessage()]
    debugs = [r for r in caplog.records if r.levelno == logging.DEBUG and "on_exec" in r.getMessage()]
    assert len(warnings) == 1
    assert len(debugs) == 3
    assert "Middleware 'tool_execution'" in warnings[0].getMessage()


def test_stream_observer_hook_failure_warns_once(manager, caplog, monkeypatch):
    """Stream observer hooks fire once per streaming delta (far more often than per tool call);
    the per-consumer worker reports a mis-declared callback through the same warn-once path."""
    from agent import plugin_stream_hooks as psh

    monkeypatch.setattr("hermes_cli.plugins._plugin_manager", manager)

    def on_stream_delta(tool_data, **kwargs):  # core sends delta, never tool_data
        return None

    monkeypatch.setattr(psh, "_registered_callbacks", lambda name: (on_stream_delta,))
    psh.shutdown_plugin_stream_hook_dispatcher()
    try:
        with caplog.at_level(logging.DEBUG):
            for i in range(20):
                assert psh.enqueue_plugin_stream_hook("on_stream_delta", delta=f"d{i}")
            for dispatcher in psh._dispatchers_for("on_stream_delta"):
                dispatcher.events.join()
    finally:
        psh.shutdown_plugin_stream_hook_dispatcher()

    warnings = [r for r in caplog.records if r.levelno == logging.WARNING and "on_stream_delta" in r.getMessage()]
    debugs = [r for r in caplog.records if r.levelno == logging.DEBUG and "on_stream_delta" in r.getMessage()]
    assert len(warnings) == 1
    assert len(debugs) == 19
    assert "Hook 'on_stream_delta'" in warnings[0].getMessage()
    assert "delta" in warnings[0].getMessage()


def test_event_subscriber_failure_warns_once(manager, caplog):
    """Plugin event subscribers deliver on the host worker; one that raises identically on every
    emit is reported once with the ``Event`` surface label."""
    manager._discovered = True

    def on_event(tool_data, **kwargs):  # the emitter sends its own payload, never tool_data
        return None

    manager._subscribe_event("listener", "emitter:tick", on_event)
    with caplog.at_level(logging.DEBUG, logger="hermes_cli.plugins"):
        for i in range(4):
            assert manager._dispatch_event("emitter:tick", {"n": i}) == 1
        assert manager._wait_for_event_dispatch(timeout=2.0)

    warnings = [r for r in caplog.records if r.levelno == logging.WARNING and "on_event" in r.getMessage()]
    debugs = [r for r in caplog.records if r.levelno == logging.DEBUG and "on_event" in r.getMessage()]
    assert len(warnings) == 1
    assert len(debugs) == 3
    assert "Event 'emitter:tick'" in warnings[0].getMessage()