Lesson 21: Logging & Observability#

"The ToolCall table is this backend's entire observability stack — no external logging service, no APM, no structured log files."

Module 6: Production Mastery#

This is the first lesson of Module 6. This file previously also contained cramped one-paragraph stubs for Testing, Performance, Scalability, Security, and Deployment — those now have their own real lessons: 22, 23, 24, 25, 26, 27.

ToolCall — the Observability Contract#

CLAUDE.md states the rule directly: "Every automated/LLM step should be logged as a ToolCall ... and, when part of a chat, linked to an AgentRun via agent_run_id." The model backs this up:

class ToolCall(Base):
    __tablename__ = "tool_calls"
    agent_id = Column(Integer, ForeignKey("agents.id"), nullable=False)
    agent_run_id = Column(Integer, ForeignKey("agent_runs.id"), nullable=True)
    tool_name = Column(String(100), nullable=False)
    tool_input = Column(Text, nullable=True)
    tool_output = Column(Text, nullable=True)
    success = Column(String(10), default="true")
    error_message = Column(Text, nullable=True)
    latency_ms = Column(Integer, nullable=True)
    model_name = Column(String(100), nullable=True)
    estimated_tokens = Column(Integer, nullable=True)
    estimated_cost = Column(String(30), nullable=True)

Every LLM-touching operation in the codebase writes one of these via the log_tool_call() helper (Lesson 09a). tool_name is the closest thing to a "log category" this system has — it's how a human filtering GET /{agent_id}/tool-calls tells email analysis apart from document search apart from the multi-agent workflow's four internal steps.

What Gets Cost/Token Data, and What Doesn't#

Only chat-completion calls carry model_name, estimated_tokens, and estimated_cost — and only in some call sites. The simple POST /email/analyze endpoint calls log_tool_call() without those three fields; the multi-agent workflow endpoint calls estimate_openai_cost() explicitly and passes the result in. Embedding calls (document upload, search) never populate these fields at all — see Lesson 15. This means the dashboard's estimated_total_cost (Lesson 09a) systematically undercounts real spend — it's missing every embedding call and every plain email-analysis call.

AgentRun — the Other Half#

class AgentRun(Base):
    agent_id = Column(Integer, ForeignKey("agents.id"), nullable=False)
    input_text = Column(Text, nullable=False)
    output_text = Column(Text, nullable=True)
    latency_ms = Column(Integer, nullable=True)
    status = Column(String(30), default="success")
    error_message = Column(Text, nullable=True)

Written only by POST /{agent_id}/chat, once per chat turn — this is a per-conversation-turn record, distinct from ToolCall's per-operation record. WorkflowRun/WorkflowStep are a third, parallel observability structure specifically for the multi-agent email workflow (Lesson 12). Three different tables, three different granularities, no single unified "events" table.

No Python logging Module In Use#

grep -r "^import logging" backend/app returns nothing. There is no logger.info(...), no log file, no log level configuration anywhere in the actual source — every "log" in this system is a database row. This has a real consequence: there is no record of anything that happens outside a try/except that explicitly calls log_tool_call. A request that 404s on "agent not found," for instance, produces no row anywhere — it's visible only as an HTTP response in whatever tool made the request, gone the moment that response is received.

Timing — Always Manual#

Every latency_ms in this system is computed the same way, by hand, at each call site:

start_time = time.time()
result = some_operation()
latency_ms = int((time.time() - start_time) * 1000)

No middleware, no decorator, no context manager wraps this — it's copy-pasted at every measurement point (at least 7 times across routers/agents.py alone). A shared @timed decorator or context manager would remove the duplication; none exists currently.

What Adding Real Structured Logging Would Look Like#

import logging
logging.basicConfig(format='%(asctime)s - %(name)s - %(levelname)s - %(message)s')
logger = logging.getLogger(__name__)
logger.info("Agent created", extra={"agent_id": agent.id})

This is illustrative, not implemented — a starting point if you wanted request-level and error-level logs to exist independently of the ToolCall table (which only captures LLM-facing operations, not routing errors, startup events, or database connection issues).

Common Mistakes#

• Trusting the dashboard's estimated_total_cost as complete. It excludes every embedding call and every email/analyze call's cost, because those call sites never pass model_name/estimated_tokens/estimated_cost to log_tool_call.
• Assuming a 404 or validation error is logged anywhere. It isn't — only successful or exception-wrapped LLM operations reach ToolCall.
• Assuming latency measurement is centralized. It's manual, duplicated time.time() bracketing at each call site.

Exercises#

1. Add model_name/estimated_tokens/estimated_cost to the email/analyze endpoint's log_tool_call call, using estimate_openai_cost() the same way the workflow endpoint already does. Confirm the dashboard total changes after analyzing one email.
2. Write a @timed decorator that wraps a function, measures latency_ms, and returns (result, latency_ms) — then replace one of the seven manual time.time() blocks in routers/agents.py with it.
3. Add Python's logging module for one category of event this system currently has zero visibility into (e.g., every HTTPException(404, ...) raised), and explain what operational question that new log line would let you answer that ToolCall alone cannot.

Key Takeaways#

🎯 ToolCall, AgentRun, and WorkflowRun/WorkflowStep are three separate, differently-grained observability tables — there's no single unified events log. 🎯 Cost/token tracking is inconsistently populated — embeddings and plain email analysis are invisible to the cost dashboard. 🎯 No Python logging module is used anywhere — every "log" is a database write, and only for explicitly-instrumented LLM operations. 🎯 Latency timing is manual and duplicated at every measurement site, not centralized.

Next Steps#

👉 Lesson 22: Exception Handling →

Module 6 · Production Mastery