Practice: Setting Up Basic Logging for Tool Usage

This practical session guides you through setting up basic logging for a custom tool. Effective logging is a fundamental aspect of maintaining reliable and observable LLM agent systems. By recording key information about tool invocations, you can significantly simplify debugging, monitor tool health, and gain insights into how your agent utilizes its capabilities. This directly contributes to the dependability and long-term sustainability of your tool-augmented agents, building upon the principles discussed earlier in this chapter.

Why Log Tool Usage?

Before we write any code, let's briefly revisit why logging tool activity is so important. When an LLM agent uses a tool, several things happen: the agent decides to use the tool, it provides inputs, the tool executes, and it returns an output (or an error). Logging these events helps you:

• Debug Failures: When a tool misbehaves or an agent doesn't get the expected outcome, logs provide a trail of what happened, including the exact inputs that led to the issue.
• Monitor Performance: You can track how often tools are called, how long they take to execute, and their success/failure rates. This information is valuable for identifying bottlenecks or unreliable tools.
• Understand Agent Behavior: Logs can reveal patterns in how an agent selects and uses tools, which can be useful for evaluating the agent's reasoning process or the effectiveness of tool descriptions.
• Audit and Compliance: In some applications, maintaining a record of tool actions might be necessary for auditing or compliance purposes.

Introducing Python's logging Module

Python's built-in logging module is a flexible and powerful framework for emitting log messages from your applications. It's the standard choice for most Python projects, including the tools we build for LLM agents.

The logging module allows you to categorize messages by severity using different levels:

• DEBUG: Detailed information, typically of interest only when diagnosing problems.
• INFO: Confirmation that things are working as expected. This is often used for tracking general tool invocations and successful outcomes.
• WARNING: An indication that something unexpected happened, or a potential problem in the near future (e.g., ‘disk space low’). The software is still working as expected.
• ERROR: Due to a more serious problem, the software has not been able to perform some function. This is appropriate for logging exceptions during tool execution.
• CRITICAL: A very serious error, indicating that the program itself may be unable to continue running.

For tool logging, INFO is generally suitable for successful invocations and their outcomes, while ERROR is used for exceptions or failures within the tool.

Designing Your Log Messages

To make your logs useful, you need to decide what information to include. For LLM agent tools, common elements are:

• Timestamp: When the tool was called.
• Tool Name: Which tool was executed.
• Input Arguments: The parameters passed to the tool. Be cautious here: if tools handle sensitive information, you might need to mask or omit certain inputs from logs.
• Output/Result: What the tool returned. For large outputs, consider logging a summary or a success indicator.
• Execution Status: Whether the tool execution was successful or failed.
• Error Details: If an error occurred, log the error message and ideally a stack trace.
• Execution Duration: How long the tool took to run (useful for performance monitoring).
• Correlation ID: If your agent system uses correlation IDs (e.g., a session ID or request ID), including this in logs can help trace a single agent interaction across multiple tool calls.

Hands-on: Implementing Logging for a Sample Tool

Let's implement logging for a simple tool. We'll create a basic "weather lookup" tool that, for this exercise, will just return a mock response.

First, ensure you have Python's logging module ready (it's part of the standard library, so no installation is needed).

1. Configure Basic Logging

We'll start by setting up a basic logging configuration. This tells Python where to send log messages (e.g., to the console), what the minimum severity level to display is, and how to format the messages. Add this at the beginning of your Python script or in an initialization module:

import logging
import time
from functools import wraps

# Configure basic logging
# This setup logs messages of INFO level and above to the console.
# The format includes timestamp, logger name, log level, and the message.
logging.basicConfig(
    level=logging.INFO,
    format='%(asctime)s - %(name)s - %(levelname)s - %(message)s',
    handlers=[logging.StreamHandler()] # Ensure logs go to console
)

# Get a logger instance for our tools module
# Using __name__ is a common practice, it sets the logger name to the module's name.
logger = logging.getLogger(__name__)

This configuration sends logs to the standard output (your console) and formats them clearly.

2. Create a Sample Tool

Let's define a simple tool. This tool will simulate fetching weather information.

def get_current_weather(location: str, unit: str = "celsius") -> str:
    """
    Simulates fetching the current weather for a given location.
    """
    logger.info(f"Tool 'get_current_weather' called. Location: {location}, Unit: {unit}")
    try:
        if not isinstance(location, str) or not location.strip():
            logger.error("Location must be a non-empty string.")
            raise ValueError("Location cannot be empty.")

        # Simulate API call delay
        time.sleep(0.5)

        if location.lower() == "errorland":
            logger.error(f"Simulated error fetching weather for {location}.")
            raise RuntimeError(f"Could not retrieve weather for {location}")

        # Mock response
        weather_report = f"The weather in {location} is 22°{unit.upper()[0]} and sunny."
        logger.info(f"Tool 'get_current_weather' successfully returned: {weather_report}")
        return weather_report
    except Exception as e:
        # The exc_info=True flag adds exception information (like a stack trace) to the log.
        logger.error(f"Exception in 'get_current_weather': {str(e)}", exc_info=True)
        # It's good practice to re-raise the exception or return an error indicator
        # so the agent framework can handle it.
        raise

In this version, we've directly embedded logger.info() and logger.error() calls within the get_current_weather tool. This is straightforward for simple tools.

3. Enhancing Logging with a Decorator (Recommended)

For more complex scenarios or when you have many tools, adding logging statements directly into each tool can become repetitive and clutter the core logic. A Python decorator is an elegant way to add logging functionality consistently.

Here's an example of a logging decorator:

def tool_logger_decorator(tool_function):
    @wraps(tool_function) # Preserves metadata of the original function
    def wrapper(*args, **kwargs):
        tool_name = tool_function.__name__
        # Create a representation of arguments for logging
        # Be mindful of sensitive data in a real application
        arg_str_parts = [f"{arg!r}" for arg in args]
        kwarg_str_parts = [f"{key}={value!r}" for key, value in kwargs.items()]
        all_args_str = ", ".join(arg_str_parts + kwarg_str_parts)

        logger.info(f"Tool '{tool_name}' called. Args: ({all_args_str})")
        start_time = time.time()
        try:
            result = tool_function(*args, **kwargs)
            end_time = time.time()
            duration = end_time - start_time
            logger.info(f"Tool '{tool_name}' completed successfully in {duration:.4f}s. Result: {str(result)[:100]}{'...' if len(str(result)) > 100 else ''}")
            return result
        except Exception as e:
            end_time = time.time()
            duration = end_time - start_time
            logger.error(
                f"Tool '{tool_name}' failed after {duration:.4f}s. Args: ({all_args_str}). Error: {str(e)}",
                exc_info=True # Adds stack trace
            )
            raise # Re-raise the exception
    return wrapper

Now, you can apply this decorator to your tools:

@tool_logger_decorator
def get_current_weather_decorated(location: str, unit: str = "celsius") -> str:
    """
    Simulates fetching the current weather for a given location (decorator version).
    """
    # Note: No direct logging calls inside the tool's core logic now!
    if not isinstance(location, str) or not location.strip():
        raise ValueError("Location cannot be empty.")

    time.sleep(0.5) # Simulate work

    if location.lower() == "errorland":
        raise RuntimeError(f"Could not retrieve weather for {location}")

    return f"The weather in {location} is 22°{unit.upper()[0]} and sunny."

@tool_logger_decorator
def calculate_sum(a: int, b: int) -> int:
    """A simple tool to calculate the sum of two integers."""
    time.sleep(0.1) # Simulate work
    if not (isinstance(a, int) and isinstance(b, int)):
        raise TypeError("Both inputs must be integers.")
    return a + b

Using the decorator keeps your tool functions cleaner and focused on their primary task, while the logging concerns are handled centrally.

4. Simulating Tool Usage and Observing Logs

Let's call our decorated tools and see the log output:

if __name__ == "__main__":
    print("--- Testing get_current_weather_decorated (Success) ---")
    try:
        weather = get_current_weather_decorated("London", unit="C")
        # print(f"Report: {weather}") # Optional: print result to console
    except Exception as e:
        # print(f"Caught exception: {e}") # Optional
        pass # Logging decorator handles log output

    print("\n--- Testing get_current_weather_decorated (Input Validation Error) ---")
    try:
        get_current_weather_decorated("") # Invalid input
    except ValueError as e:
        # print(f"Caught expected ValueError: {e}") # Optional
        pass

    print("\n--- Testing get_current_weather_decorated (Simulated Runtime Error) ---")
    try:
        get_current_weather_decorated("Errorland")
    except RuntimeError as e:
        # print(f"Caught expected RuntimeError: {e}") # Optional
        pass

    print("\n--- Testing calculate_sum (Success) ---")
    try:
        total = calculate_sum(5, 7)
        # print(f"Sum: {total}") # Optional
    except Exception as e:
        # print(f"Caught exception: {e}") # Optional
        pass

    print("\n--- Testing calculate_sum (Type Error) ---")
    try:
        calculate_sum(10, "20") # Invalid type for 'b'
    except TypeError as e:
        # print(f"Caught expected TypeError: {e}") # Optional
        pass

When you run this script, you should see output similar to this in your console (timestamps will vary):

--- Testing get_current_weather_decorated (Success) ---
2023-10-27 10:00:00,123 - __main__ - INFO - Tool 'get_current_weather_decorated' called. Args: ('London', unit='C')
2023-10-27 10:00:00,625 - __main__ - INFO - Tool 'get_current_weather_decorated' completed successfully in 0.5012s. Result: The weather in London is 22°C and sunny.

--- Testing get_current_weather_decorated (Input Validation Error) ---
2023-10-27 10:00:00,626 - __main__ - INFO - Tool 'get_current_weather_decorated' called. Args: ('',)
2023-10-27 10:00:00,627 - __main__ - ERROR - Tool 'get_current_weather_decorated' failed after 0.0001s. Args: ('',). Error: Location cannot be empty.
Traceback (most recent call last):
  ... (stack trace for ValueError) ...

--- Testing get_current_weather_decorated (Simulated Runtime Error) ---
2023-10-27 10:00:00,628 - __main__ - INFO - Tool 'get_current_weather_decorated' called. Args: ('Errorland',)
2023-10-27 10:00:01,130 - __main__ - ERROR - Tool 'get_current_weather_decorated' failed after 0.5015s. Args: ('Errorland',). Error: Could not retrieve weather for Errorland
Traceback (most recent call last):
  ... (stack trace for RuntimeError) ...

--- Testing calculate_sum (Success) ---
2023-10-27 10:00:01,131 - __main__ - INFO - Tool 'calculate_sum' called. Args: (5, 7)
2023-10-27 10:00:01,232 - __main__ - INFO - Tool 'calculate_sum' completed successfully in 0.1005s. Result: 12

--- Testing calculate_sum (Type Error) ---
2023-10-27 10:00:01,233 - __main__ - INFO - Tool 'calculate_sum' called. Args: (10, '20')
2023-10-27 10:00:01,334 - __main__ - ERROR - Tool 'calculate_sum' failed after 0.1002s. Args: (10, '20'). Error: Both inputs must be integers.
Traceback (most recent call last):
  ... (stack trace for TypeError) ...

This output clearly shows when each tool was called, the arguments it received, whether it succeeded or failed, the result (truncated if long), the duration, and a stack trace for errors.

Interpreting and Using Your Logs

The log entries you've generated provide a valuable record:

• Successful calls: INFO messages confirm the tool name, inputs, and a snippet of the output along with execution time. This is useful for verifying normal operation and for basic performance tracking.
• Failed calls: ERROR messages, along with exc_info=True, provide the tool name, inputs that led to the failure, the error message, and a full stack trace. This is indispensable for debugging. You can see exactly where in your tool's code the problem occurred.

This logging data forms the basis for more advanced monitoring. By parsing these logs, you could, for example, count the number of times each tool is called, calculate average execution times, or track the frequency of specific errors.

The following diagram illustrates the logging flow when using a decorator:

This diagram shows the sequence of operations when a decorated tool is called, highlighting how the logging decorator intercepts the call to record information before and after the tool's core logic executes.

Further Considerations for Robust Logging

While this practice sets up basic logging, here are a few points to consider as your tool system grows:

• Structured Logging: For easier automated parsing and analysis (e.g., by log management systems like Elasticsearch or Splunk), consider logging messages in a structured format like JSON. Libraries like python-json-logger can help with this.
• Logging to Files: For persistent storage, configure your logger to write to files. The logging.FileHandler class is used for this. Implement log rotation (RotatingFileHandler or TimedRotatingFileHandler) to manage log file sizes.
• Centralized Logging: In production environments, especially with multiple services or distributed agents, send logs to a centralized logging system. This allows you to search, analyze, and monitor logs from all components in one place.
• Sensitive Data: Reiterate the importance of being careful with sensitive data. Implement filtering or masking for arguments or results that should not appear in logs.
• Configuration: For more complex applications, manage logging configuration through external files (e.g., INI, YAML, or JSON) or dictionaries, rather than hardcoding it with basicConfig. Python's logging.config module supports this.

By implementing even basic logging, as demonstrated in this practice session, you've taken a significant step towards building more maintainable, observable, and ultimately more reliable tools for your LLM agents. This foundation is essential as you develop and deploy increasingly sophisticated agent systems.