Merge pull request #59 from dgenio/copilot/add-structured-logging-kernel

feat: Add structured logging at kernel decision points

Author: dgenio

src/agent_kernel/firewall/transform.py

@@ -4,6 +4,7 @@
 
 import datetime
 import json
+import logging
 from typing import Any
 
 from ..models import (
@@ -17,6 +18,8 @@
 from .redaction import redact
 from .summarize import summarize
 
+logger = logging.getLogger(__name__)
+
 
 class Firewall:
     """Transforms :class:`RawResult` objects into LLM-safe :class:`Frame` objects.
@@ -90,18 +93,49 @@ def transform(
             data, redact_warnings = redact(data, max_depth=self._budgets.max_depth)
             warnings.extend(redact_warnings)
 
+        logger.debug(
+            "firewall_redaction",
+            extra={
+                "action_id": action_id,
+                "capability_id": raw.capability_id,
+                "principal_id": principal_id,
+                "redaction_warnings": len(redact_warnings),
+                "needs_redaction": needs_redaction,
+            },
+        )
+
         # ── Raw mode (admin only) ──────────────────────────────────────────────
         if response_mode == "raw":
             if "admin" not in principal_roles:
                 warnings.append("raw mode requires admin role; falling back to summary.")
                 response_mode = "summary"
+                logger.debug(
+                    "firewall_mode_fallback",
+                    extra={
+                        "action_id": action_id,
+                        "capability_id": raw.capability_id,
+                        "requested_mode": "raw",
+                        "effective_mode": "summary",
+                        "reason": "principal lacks admin role",
+                    },
+                )
             else:
                 raw_size = len(json.dumps(data, default=str))
                 if raw_size > self._budgets.max_chars:
                     warnings.append(
                         f"raw output ({raw_size} chars) exceeds budget "
                         f"({self._budgets.max_chars} chars); data returned untruncated."
                     )
+                logger.debug(
+                    "firewall_transform",
+                    extra={
+                        "action_id": action_id,
+                        "capability_id": raw.capability_id,
+                        "response_mode": "raw",
+                        "raw_size_chars": raw_size,
+                        "budget_chars": self._budgets.max_chars,
+                    },
+                )
                 return Frame(
                     action_id=action_id,
                     capability_id=raw.capability_id,
@@ -114,6 +148,14 @@ def transform(
 
         # ── Handle only ───────────────────────────────────────────────────────
         if response_mode == "handle_only":
+            logger.debug(
+                "firewall_transform",
+                extra={
+                    "action_id": action_id,
+                    "capability_id": raw.capability_id,
+                    "response_mode": "handle_only",
+                },
+            )
             return Frame(
                 action_id=action_id,
                 capability_id=raw.capability_id,
@@ -126,6 +168,16 @@ def transform(
         # ── Table mode ────────────────────────────────────────────────────────
         if response_mode == "table":
             table_preview = self._make_table(data, max_rows=max_rows)
+            logger.debug(
+                "firewall_transform",
+                extra={
+                    "action_id": action_id,
+                    "capability_id": raw.capability_id,
+                    "response_mode": "table",
+                    "rows_returned": len(table_preview),
+                    "max_rows": max_rows,
+                },
+            )
             return Frame(
                 action_id=action_id,
                 capability_id=raw.capability_id,
@@ -140,6 +192,16 @@ def transform(
         facts = summarize(data, max_facts=20)
         # Enforce char budget across all facts
         facts = _cap_facts(facts, self._budgets.max_chars)
+        logger.debug(
+            "firewall_transform",
+            extra={
+                "action_id": action_id,
+                "capability_id": raw.capability_id,
+                "response_mode": "summary",
+                "facts_count": len(facts),
+                "budget_chars": self._budgets.max_chars,
+            },
+        )
         return Frame(
             action_id=action_id,
             capability_id=raw.capability_id,

src/agent_kernel/kernel.py

@@ -3,6 +3,7 @@
 from __future__ import annotations
 
 import datetime
+import logging
 import uuid
 from typing import Any
 
@@ -26,6 +27,8 @@
 from .tokens import CapabilityToken, HMACTokenProvider, TokenProvider
 from .trace import TraceStore
 
+logger = logging.getLogger(__name__)
+
 
 class Kernel:
     """The central orchestrator for capability-based AI agent security.
@@ -91,7 +94,15 @@ def request_capabilities(
         Returns:
             An ordered list of :class:`CapabilityRequest` objects (best match first).
         """
-        return self._registry.search(goal)
+        results = self._registry.search(goal)
+        logger.debug(
+            "request_capabilities",
+            extra={
+                "goal": goal,
+                "matches": len(results),
+            },
+        )
+        return results
 
     def grant_capability(
         self,
@@ -125,6 +136,16 @@ def grant_capability(
             constraints=decision.constraints,
             audit_id=audit_id,
         )
+        logger.info(
+            "grant_capability",
+            extra={
+                "principal_id": principal.principal_id,
+                "capability_id": capability.capability_id,
+                "safety_class": capability.safety_class.value,
+                "audit_id": audit_id,
+                "token_id": token.token_id,
+            },
+        )
         return CapabilityGrant(
             request=request,
             principal=principal,
@@ -188,6 +209,16 @@ async def invoke(
         self._registry.get(token.capability_id)  # validate capability exists
         plan: RoutePlan = self._router.route(token.capability_id)
 
+        _log_ctx = {
+            "action_id": action_id,
+            "principal_id": principal.principal_id,
+            "capability_id": token.capability_id,
+        }
+        logger.info(
+            "invoke_start",
+            extra={**_log_ctx, "token_id": token.token_id, "response_mode": response_mode},
+        )
+
         # ── Execute with fallback ─────────────────────────────────────────────
         raw_result = None
         used_driver_id = ""
@@ -207,13 +238,19 @@ async def invoke(
             try:
                 raw_result = await driver.execute(ctx)
                 used_driver_id = driver_id
+                logger.debug("driver_success", extra={**_log_ctx, "driver_id": driver_id})
                 break
             except DriverError as exc:
+                logger.warning(
+                    "driver_failure",
+                    extra={**_log_ctx, "driver_id": driver_id, "error": str(exc)},
+                )
                 last_error = exc
                 continue
 
         if raw_result is None:
             err_msg = str(last_error) if last_error else "No drivers available."
+            logger.warning("invoke_failure", extra={**_log_ctx, "error": err_msg})
             trace = ActionTrace(
                 action_id=action_id,
                 capability_id=token.capability_id,
@@ -263,6 +300,10 @@ async def invoke(
         )
         self._trace_store.record(trace)
 
+        logger.info(
+            "invoke_success",
+            extra={**_log_ctx, "response_mode": frame.response_mode, "driver_id": used_driver_id},
+        )
         return frame
 
     def expand(self, handle: Handle, *, query: dict[str, Any]) -> Frame:
@@ -279,6 +320,13 @@ def expand(self, handle: Handle, *, query: dict[str, Any]) -> Frame:
             HandleNotFound: If the handle is unknown.
             HandleExpired: If the handle has expired.
         """
+        logger.info(
+            "expand",
+            extra={
+                "handle_id": handle.handle_id,
+                "capability_id": handle.capability_id,
+            },
+        )
         return self._handle_store.expand(handle, query=query)
 
     def explain(self, action_id: str) -> ActionTrace:
@@ -293,4 +341,10 @@ def explain(self, action_id: str) -> ActionTrace:
         Raises:
             AgentKernelError: If no trace exists for that action ID.
         """
+        logger.info(
+            "explain",
+            extra={
+                "action_id": action_id,
+            },
+        )
         return self._trace_store.get(action_id)