Expand plugin lifecycle logging

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

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 "<none>",
+    )
     return count

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):