diff --git a/README.md b/README.md index 312c418..e6b0b61 100644 --- a/README.md +++ b/README.md @@ -49,8 +49,10 @@ the same boilerplate. `hermes-plugin-kit` makes them structurally impossible: an error that *names the argument and its example*. - **Explicit tool namespacing** — build names with `tool_name(namespace, verb, noun)` and reject Hermes agent-loop names such as `memory`. -- **Logging** — `WARNING` on a rejected call (arguments truncated, secret-looking - values redacted), `INFO` on success, under your plugin's own logger. +- **Logging** — `DEBUG` when a tool is invoked, `WARNING` on rejected calls and + exceptions (including tracebacks), and `INFO` on success with elapsed time and + result mode. Arguments are truncated and nested secret-looking values are + recursively redacted. `register_all` also logs the registered tool inventory. - **Envelope + safety** — return a plain `dict` (or raise); the kit encodes the JSON string, catches exceptions, and always returns `str` from an `(args, **kwargs)` handler. @@ -154,6 +156,24 @@ A handler returns a `dict` (becomes the success `data`), or raises (becomes a to error), or returns a `str` as an escape hatch (treated as already-encoded JSON). It must accept `(args, **kwargs)` — runtime keys like `task_id`/`session_id` arrive as kwargs. +## Logging contract + +The kit logs under the decorated handler's module logger, so each plugin can +control verbosity with normal Python logging configuration. Tool lifecycle logs +include: + +- `DEBUG`: invocation with truncated, recursively redacted arguments and safe + `session_id`/`task_id` context when supplied by Hermes. +- `WARNING`: required-argument rejection or a handler exception. Exceptions use + `logger.exception`, preserving the traceback for runtime diagnosis. +- `INFO`: successful completion with `elapsed_ms` and whether the handler returned + a dictionary-like result or an already-encoded string. +- `INFO`: a registration summary from `register_all`, including count and names. + +The kit never logs handler result payloads. Keys containing `token`, `secret`, +`password`, `passwd`, `api_key`, `apikey`, or `auth` are replaced with `***` at +any nesting depth before arguments are logged. + ## Development Uses [uv](https://docs.astral.sh/uv/). Install it with `brew install uv` (macOS) or diff --git a/hermes_plugin_kit/__init__.py b/hermes_plugin_kit/__init__.py index 2748dd3..b3dbf4b 100644 --- a/hermes_plugin_kit/__init__.py +++ b/hermes_plugin_kit/__init__.py @@ -11,8 +11,9 @@ to the tool description, the one field a model always sees. - **Validation + instructive errors** — a missing/blank required argument returns an error that names the argument and its example, and logs a WARNING. -- **Logging** — WARNING on a rejected call (args truncated, secret-looking values - redacted), INFO on success, under the plugin's own logger namespace. +- **Logging** — DEBUG on invocation, WARNING on rejected/failed calls with + tracebacks for exceptions, and INFO on success with elapsed time. Arguments + are truncated and secret-looking values are recursively redacted. - **Envelope + safety** — a handler returns a plain ``dict`` (or raises); the kit encodes the JSON string, wraps exceptions, and always returns ``str`` from an ``(args, **kwargs)`` signature, exactly as the registry requires. @@ -48,6 +49,7 @@ def register(ctx): import logging import re import sys +import time from typing import Any, Callable __all__ = [ @@ -213,11 +215,23 @@ def build_schema(name: str, description: str, params: dict | None) -> dict: # Logging helpers # --------------------------------------------------------------------------- +def _redacted_value(value: Any) -> Any: + if isinstance(value, dict): + return { + key: ( + "***" + if any(hint in str(key).lower() for hint in _REDACT_HINTS) + else _redacted_value(item) + ) + for key, item in value.items() + } + if isinstance(value, (list, tuple)): + return [_redacted_value(item) for item in value] + return value + + def _redacted_args(args: dict) -> dict: - out: dict[str, Any] = {} - for key, value in (args or {}).items(): - out[key] = "***" if any(hint in key.lower() for hint in _REDACT_HINTS) else value - return out + return _redacted_value(args or {}) def _truncate(value: Any) -> str: @@ -264,6 +278,19 @@ def decorate(fn: Callable) -> Callable: @functools.wraps(fn) def wrapper(args: dict, **kwargs: Any) -> str: args = args or {} + started = time.perf_counter() + safe_args = _truncate(_redacted_args(args)) + context = { + key: kwargs[key] + for key in ("session_id", "task_id") + if kwargs.get(key) is not None + } + log.debug( + "%s: invoked; args=%s; context=%s", + tool_name, + safe_args, + _truncate(context), + ) for key in required: value = args.get(key) if value is None or (isinstance(value, str) and not value.strip()): @@ -272,23 +299,39 @@ def wrapper(args: dict, **kwargs: Any) -> str: f" (e.g. {example!r})" if example is not None else "" ) log.warning( - "%s: rejected call, missing %s; args=%s", + "%s: rejected call, missing %s; elapsed_ms=%.2f; args=%s", tool_name, key, - _truncate(_redacted_args(args)), + (time.perf_counter() - started) * 1000, + safe_args, ) return json.dumps({"success": False, "error": message}, ensure_ascii=False) try: result = fn(args, **kwargs) except Exception as exc: # noqa: BLE001 — tool errors stay in-band - log.warning("%s: handler raised: %s", tool_name, exc) + log.exception( + "%s: handler raised; elapsed_ms=%.2f; error=%s", + tool_name, + (time.perf_counter() - started) * 1000, + exc, + ) return json.dumps( {"success": False, "error": f"{tool_name} failed: {exc}"}, ensure_ascii=False, ) if isinstance(result, str): + log.info( + "%s: ok; elapsed_ms=%.2f; result=encoded_string", + tool_name, + (time.perf_counter() - started) * 1000, + ) return result - log.info("%s: ok", tool_name) + log.info( + "%s: ok; elapsed_ms=%.2f; result=%s", + tool_name, + (time.perf_counter() - started) * 1000, + type(result).__name__, + ) return json.dumps({"success": True, "data": result}, ensure_ascii=False) setattr( @@ -319,6 +362,7 @@ def register_all(ctx: Any, module: Any) -> int: """ if isinstance(module, str): module = sys.modules[module] + log = logging.getLogger(getattr(module, "__name__", "hermes_plugin_kit")) count = 0 seen: set[str] = set() for _, obj in inspect.getmembers(module): @@ -336,4 +380,9 @@ def register_all(ctx: Any, module: Any) -> int: emoji=spec["emoji"], ) count += 1 + log.info( + "hermes_plugin_kit: registered %d tool(s); names=%s", + count, + ",".join(sorted(seen)) or "", + ) return count diff --git a/tests/test_kit.py b/tests/test_kit.py index 7105e33..8c52a61 100644 --- a/tests/test_kit.py +++ b/tests/test_kit.py @@ -65,10 +65,16 @@ def test_description_self_documents_required_arg_and_example(self) -> None: class HandlerBehaviorTests(unittest.TestCase): def test_success_envelope_and_tolerates_runtime_kwargs(self) -> None: - out = json.loads(sample_read({"thread_id_or_url": "999"}, task_id="t", session_id="s")) + with self.assertLogs(level="DEBUG") as cap: + out = json.loads(sample_read({"thread_id_or_url": "999"}, task_id="t", session_id="s")) self.assertTrue(out["success"]) self.assertEqual(out["data"]["thread"], "999") self.assertEqual(out["data"]["kwargs"], ["session_id", "task_id"]) + joined = "\n".join(cap.output) + self.assertIn("sample_read_thread: invoked", joined) + self.assertIn('"session_id": "s"', joined) + self.assertRegex(joined, r"elapsed_ms=\d+\.\d{2}") + self.assertIn("result=dict", joined) def test_missing_required_returns_instructive_error_and_warns(self) -> None: with self.assertLogs(level="WARNING") as cap: @@ -83,10 +89,14 @@ def test_blank_string_counts_as_missing(self) -> None: self.assertFalse(out["success"]) def test_exception_caught_in_band(self) -> None: - with self.assertLogs(level="WARNING"): + with self.assertLogs(level="WARNING") as cap: out = json.loads(sample_boom({"q": "x"})) self.assertFalse(out["success"]) self.assertIn("sample_boom failed", out["error"]) + joined = "\n".join(cap.output) + self.assertIn("Traceback (most recent call last)", joined) + self.assertIn("RuntimeError: kaboom", joined) + self.assertRegex(joined, r"elapsed_ms=\d+\.\d{2}") def test_reserved_agent_loop_tool_name_rejected(self) -> None: with self.assertRaisesRegex(ValueError, "reserved"): @@ -120,19 +130,42 @@ def needs_id(args, **kwargs): self.assertIn("***", joined) self.assertNotIn("supersecret", joined) + def test_nested_secret_looking_values_redacted_in_logs(self) -> None: + @hpk.tool(toolset="x") + def nested(args, **kwargs): + """Accept nested configuration.""" + return {} + + with self.assertLogs(level="DEBUG") as cap: + nested( + { + "config": { + "api_key": "nested-secret", + "headers": [{"authorization": "Bearer hidden"}], + } + } + ) + joined = "\n".join(cap.output) + self.assertNotIn("nested-secret", joined) + self.assertNotIn("Bearer hidden", joined) + self.assertGreaterEqual(joined.count("***"), 2) + def test_string_return_is_passthrough(self) -> None: @hpk.tool(toolset="x") def already_json(args, **kwargs): """Returns its own JSON.""" return '{"raw": true}' - self.assertEqual(already_json({}), '{"raw": true}') + with self.assertLogs(level="INFO") as cap: + self.assertEqual(already_json({}), '{"raw": true}') + self.assertIn("result=encoded_string", "\n".join(cap.output)) class RegisterAllTests(unittest.TestCase): def test_registers_every_decorated_tool_with_convention(self) -> None: ctx = FakeCtx() - count = hpk.register_all(ctx, __name__) + with self.assertLogs(level="INFO") as cap: + count = hpk.register_all(ctx, __name__) self.assertGreaterEqual(count, 2) by_name = {tool["name"]: tool for tool in ctx.tools} self.assertIn("sample_read_thread", by_name) @@ -142,6 +175,9 @@ def test_registers_every_decorated_tool_with_convention(self) -> None: self.assertEqual(sample["emoji"], "🧵") self.assertIn("parameters", sample["schema"]) self.assertTrue(callable(sample["handler"])) + joined = "\n".join(cap.output) + self.assertIn(f"registered {count} tool(s)", joined) + self.assertIn("sample_read_thread", joined) def test_description_requires_a_docstring(self) -> None: with self.assertRaises(ValueError):