|
| 1 | +"""Agent execution logging plugin. |
| 2 | +
|
| 3 | +Logs agent lifecycle events (tool calls, LLM invocations, run start/end) |
| 4 | +at INFO level for operational visibility. Controlled by the |
| 5 | +AGENT_LOGGING_DETAIL setting: |
| 6 | + - "basic": logs tool names, token counts, and lifecycle events |
| 7 | + - "detailed": also logs tool arguments and truncated results |
| 8 | +""" |
| 9 | + |
| 10 | +import logging |
| 11 | +from typing import Any |
| 12 | + |
| 13 | +from google.adk.agents.callback_context import CallbackContext |
| 14 | +from google.adk.agents.invocation_context import InvocationContext |
| 15 | +from google.adk.models.llm_request import LlmRequest |
| 16 | +from google.adk.models.llm_response import LlmResponse |
| 17 | +from google.adk.plugins.base_plugin import BasePlugin |
| 18 | +from google.adk.tools.base_tool import BaseTool |
| 19 | +from google.adk.tools.tool_context import ToolContext |
| 20 | + |
| 21 | +from lightspeed_agent.config import get_settings |
| 22 | + |
| 23 | +logger = logging.getLogger(__name__) |
| 24 | + |
| 25 | +_MAX_RESULT_LENGTH = 500 |
| 26 | + |
| 27 | + |
| 28 | +def _truncate(value: Any, max_length: int = _MAX_RESULT_LENGTH) -> str: |
| 29 | + """Return a string representation truncated to *max_length* characters.""" |
| 30 | + text = str(value) |
| 31 | + if len(text) <= max_length: |
| 32 | + return text |
| 33 | + return text[:max_length] + "...(truncated)" |
| 34 | + |
| 35 | + |
| 36 | +class AgentLoggingPlugin(BasePlugin): |
| 37 | + """ADK plugin that logs agent execution events at INFO level.""" |
| 38 | + |
| 39 | + def __init__(self) -> None: |
| 40 | + super().__init__(name="agent_logging") |
| 41 | + |
| 42 | + def _is_detailed(self) -> bool: |
| 43 | + return get_settings().agent_logging_detail == "detailed" |
| 44 | + |
| 45 | + # -- run lifecycle -------------------------------------------------------- |
| 46 | + |
| 47 | + async def before_run_callback( |
| 48 | + self, *, invocation_context: InvocationContext |
| 49 | + ) -> None: |
| 50 | + logger.info( |
| 51 | + "Agent run started (invocation_id=%s, agent=%s)", |
| 52 | + invocation_context.invocation_id, |
| 53 | + invocation_context.agent_name, # type: ignore[attr-defined] |
| 54 | + ) |
| 55 | + return None |
| 56 | + |
| 57 | + async def after_run_callback( |
| 58 | + self, *, invocation_context: InvocationContext |
| 59 | + ) -> None: |
| 60 | + logger.info( |
| 61 | + "Agent run completed (invocation_id=%s)", |
| 62 | + invocation_context.invocation_id, |
| 63 | + ) |
| 64 | + return None |
| 65 | + |
| 66 | + # -- model callbacks ------------------------------------------------------ |
| 67 | + |
| 68 | + async def before_model_callback( |
| 69 | + self, *, callback_context: CallbackContext, llm_request: LlmRequest |
| 70 | + ) -> Any | None: |
| 71 | + logger.info("LLM call started (agent=%s)", callback_context.agent_name) |
| 72 | + return None |
| 73 | + |
| 74 | + async def after_model_callback( |
| 75 | + self, |
| 76 | + *, |
| 77 | + callback_context: CallbackContext, |
| 78 | + llm_response: LlmResponse, |
| 79 | + ) -> LlmResponse | None: |
| 80 | + input_tokens = 0 |
| 81 | + output_tokens = 0 |
| 82 | + if llm_response and llm_response.usage_metadata: |
| 83 | + usage = llm_response.usage_metadata |
| 84 | + input_tokens = getattr(usage, "prompt_token_count", 0) or 0 |
| 85 | + output_tokens = getattr(usage, "candidates_token_count", 0) or 0 |
| 86 | + |
| 87 | + model_version = llm_response.model_version if llm_response else None |
| 88 | + |
| 89 | + logger.info( |
| 90 | + "LLM call completed (input_tokens=%d, output_tokens=%d, model=%s)", |
| 91 | + input_tokens, |
| 92 | + output_tokens, |
| 93 | + model_version, |
| 94 | + ) |
| 95 | + return None |
| 96 | + |
| 97 | + async def on_model_error_callback( |
| 98 | + self, *, callback_context: CallbackContext, llm_request: LlmRequest, error: Exception |
| 99 | + ) -> LlmResponse | None: |
| 100 | + logger.error("LLM call failed: %s", error) |
| 101 | + return None |
| 102 | + |
| 103 | + # -- tool callbacks ------------------------------------------------------- |
| 104 | + |
| 105 | + async def before_tool_callback( |
| 106 | + self, |
| 107 | + *, |
| 108 | + tool: BaseTool, |
| 109 | + tool_args: dict[str, Any], |
| 110 | + tool_context: ToolContext, |
| 111 | + ) -> Any | None: |
| 112 | + tool_name = getattr(tool, "name", type(tool).__name__) |
| 113 | + if self._is_detailed(): |
| 114 | + logger.info( |
| 115 | + "Tool call started (tool=%s, args=%s)", |
| 116 | + tool_name, |
| 117 | + _truncate(tool_args), |
| 118 | + ) |
| 119 | + else: |
| 120 | + logger.info("Tool call started (tool=%s)", tool_name) |
| 121 | + return None |
| 122 | + |
| 123 | + async def after_tool_callback( |
| 124 | + self, |
| 125 | + *, |
| 126 | + tool: BaseTool, |
| 127 | + tool_args: dict[str, Any], |
| 128 | + tool_context: ToolContext, |
| 129 | + result: dict[str, Any], |
| 130 | + ) -> dict[str, Any] | None: |
| 131 | + tool_name = getattr(tool, "name", type(tool).__name__) |
| 132 | + if self._is_detailed(): |
| 133 | + logger.info( |
| 134 | + "Tool call completed (tool=%s, result=%s)", |
| 135 | + tool_name, |
| 136 | + _truncate(result), |
| 137 | + ) |
| 138 | + else: |
| 139 | + logger.info("Tool call completed (tool=%s)", tool_name) |
| 140 | + return None |
| 141 | + |
| 142 | + async def on_tool_error_callback( |
| 143 | + self, |
| 144 | + *, |
| 145 | + tool: BaseTool, |
| 146 | + tool_args: dict[str, Any], |
| 147 | + tool_context: ToolContext, |
| 148 | + error: Exception, |
| 149 | + ) -> dict[str, Any] | None: |
| 150 | + tool_name = getattr(tool, "name", type(tool).__name__) |
| 151 | + logger.error("Tool call failed (tool=%s): %s", tool_name, error) |
| 152 | + return None |
0 commit comments