Tracing and logging AI requests

Why this matters

When a traditional API returns a wrong result, you look at the database query and the request payload. When an LLM feature returns a bad response, you need to reconstruct the entire call: what was in the prompt, what context was retrieved, what the model returned, how long it took, and how many tokens it used. Without structured tracing, this reconstruction is guesswork.

The engineering reality: 80% of AI debugging sessions are about understanding what the model actually received, not what you intended to send. Tracing closes that gap. It also gives you the data you need for cost attribution, quality monitoring, and anomaly detection.

Core concepts

Structured traces vs. flat logs. A flat log line like INFO: LLM call completed in 1.2s is nearly useless for debugging. A structured trace captures the event as a typed object with named fields that can be queried, aggregated, and correlated.

Span-based tracing. Borrowed from distributed systems (OpenTelemetry), spans represent units of work with a start time, end time, and attributes. A single LLM feature request might span:

request_span (root)
  |- retrieval_span (vector search + re-ranking)
  |- prompt_assembly_span (context injection, token counting)
  |- llm_call_span (provider API call)
  |- post_processing_span (parsing, validation)

Each span records its own latency, so you can see where time is actually spent.

What to log in an LLM trace:

Field	Why
trace_id	Correlate across spans and services
model	Know which model version was used
prompt_tokens	Cost attribution
completion_tokens	Cost attribution
total_latency_ms	SLO monitoring
finish_reason	Detect max_tokens truncation
feature_name	Which product feature made this call
user_id (hashed)	Per-user analysis without PII in logs

What NOT to log by default:

• Raw user messages: may contain PII or sensitive business data
• Full system prompts: may contain trade secrets or security-relevant instructions
• Complete responses: may contain personal information echoed from user input

Log these only with explicit opt-in, appropriate redaction, and retention controls.

Privacy-preserving tracing. Design your trace schema with a log_level field: minimal (metadata only), standard (truncated prompts), and debug (full content, retention-limited). Never log full content by default in production.

Trace correlation. Attach a trace_id at the edge of your system and propagate it through every downstream call. OpenTelemetry provides standard headers (traceparent) for this propagation.

Working example

A complete structured tracing implementation:

import time
import uuid
from contextlib import contextmanager
from dataclasses import dataclass, field
from typing import Generator


@dataclass
class Span:
    span_id: str
    trace_id: str
    name: str
    start_ms: int
    end_ms: int = 0
    latency_ms: int = 0
    attributes: dict = field(default_factory=dict)

    def set(self, key: str, value) -> None:
        self.attributes[key] = value

    def to_dict(self) -> dict:
        return {'span_id': self.span_id, 'trace_id': self.trace_id, 'name': self.name,
                'start_ms': self.start_ms, 'end_ms': self.end_ms,
                'latency_ms': self.latency_ms, **self.attributes}


class Tracer:
    def __init__(self, trace_id: str | None = None, feature_name: str = ''):
        self.trace_id = trace_id or str(uuid.uuid4())
        self.feature_name = feature_name
        self._spans: list[Span] = []

    @contextmanager
    def span(self, name: str, **attributes) -> Generator[Span, None, None]:
        s = Span(span_id=str(uuid.uuid4()), trace_id=self.trace_id, name=name,
                 start_ms=int(time.time() * 1000), attributes={**attributes})
        try:
            yield s
        finally:
            s.end_ms = int(time.time() * 1000)
            s.latency_ms = s.end_ms - s.start_ms
            self._spans.append(s)

    def export(self) -> list[dict]:
        return sorted([s.to_dict() for s in self._spans], key=lambda d: d['start_ms'])


# Usage in a feature handler
def handle_qa_request(question: str, trace_id: str) -> dict:
    tracer = Tracer(trace_id=trace_id, feature_name='document_qa')

    with tracer.span('retrieval', index='docs_v2') as ret_span:
        chunks = retrieve_chunks(question)
        ret_span.set('num_results', len(chunks))

    with tracer.span('llm_call', model='claude-3-5-sonnet-20241022') as llm_span:
        response = call_llm(question, chunks)
        llm_span.set('prompt_tokens', response.usage.input_tokens)
        llm_span.set('completion_tokens', response.usage.output_tokens)

    write_to_observability_store(tracer.export())
    return {'answer': response.content[0].text, 'trace_id': tracer.trace_id}

The try/finally in the context manager is the critical detail: end_ms and latency_ms are always set even if the body raises an exception. Error spans have accurate timing, which is important for diagnosing slow failures.

Common mistakes

1. Logging full prompts to general application logs. System prompts and user messages often contain sensitive data. Use a separate, access-controlled store for prompt content.

2. Not propagating trace IDs. If the trace ID does not flow from the HTTP layer to the LLM call, you cannot reconstruct a request after the fact.

3. No token tracking. Token counts are the primary cost driver. If you cannot query 'which feature used the most tokens last week,' you are flying blind on cost.

4. Truncating responses to zero. Logging no response content makes debugging impossible. A 200-character preview is usually enough to spot the failure without significant privacy risk.

5. Missing finish_reason logging. When finish_reason is max_tokens, the model's output was cut short -- a silent quality failure that looks like a normal response without this field.

Try it yourself

Implement a ContextualTrace class that wraps a function call and automatically records span start time, end time, latency, and any exception. It should work as a context manager:

with ContextualTrace(collector, span_type='llm_call', model='gpt-4o') as span:
    response = openai_client.chat.completions.create(...)
    span.record_response(response)

On exit, the span should be automatically recorded to the collector whether or not an exception occurred. If an exception occurred, capture the error message and re-raise.