AI System Full-Link Logging Troubleshooting Guide: How to Use TraceID to Track the Lifeline of a Request

When building AI systems, there is a type of problem that is particularly tormenting:

• Users say: "That request just now was very slow", "Voice suddenly didn't return", "AI cut off halfway through the answer", "Page shows success but there is actually no result".
• You open the logs and see that every module seems to have no obvious error:
  • API layer has request logs.
  • Model calling layer has latency logs.
  • WebSocket layer has connection logs.
  • Task queue also has consumption records.

But these logs are like fragments scattered on the ground, making it very difficult to piece together a complete workflow.

Especially in AI systems, this problem is further amplified. Because a user request is usually not a simple HTTP call, but rather passes through multiple physical and asynchronous boundaries:

More troublesome is that AI requests naturally possess uncertainty:

1. Unstable model response time: Highly affected by network, load, and Token quantity.
2. Streaming output can fail halfway: Network jitter or upstream rate limiting can lead to connection interruption at any time.
3. Context length affects latency: The longer the Context, the higher the Time-To-First-Token (TTFT) and total elapsed time.
4. Complex multimodal input processing: Latency differences for processing audio, images, and text are huge.
5. Multi-goroutine collaboration: Multiple Goroutines may process the same task, resulting in out-of-order logs.

The problems users see usually occur in the latter half of the server-side pipeline. So the most difficult part of debugging AI systems is not "whether there are logs", but: when a request crosses multiple modules, multiple asynchronous boundaries, and multiple IO systems, can you still stitch it back together?

This is the value of TraceID and full-link logging. It is not to make logs more voluminous, but to make every log answer the same question: To which user request does this log belong?

I. Why AI Systems Turn Into Black Boxes More Easily Than Ordinary Systems

Traditional CRUD systems usually have short problem paths. A request comes in, queries the database, makes a business decision, and returns the result. If an error occurs, it can be located in the API logs, SQL logs, or error stack traces in most cases.

But AI systems are not like this. Take a voice AI request as an example, it undergoes an extremely long and complex path:

In this pipeline, any failure in any module will lead to serious user experience issues:

• ASR succeeded, but LLM timed out.
• LLM succeeded, but WebSocket push failed.
• WebSocket push succeeded, but frontend failed to handle the final event correctly.
• Model returned content, but persistence failed, leading to lost history records.
• Queue task was consumed, but context was not passed correctly.
• Retry mechanism was triggered twice, leading to duplicate results for the user.

This is where the black-box feeling comes from: it's not that the system really doesn't have logs, but that the logs lack a common coordinate system.

TraceID establishes a coordinate system for this pipeline.

II. TraceID is Not a Field, But the Lifeline of a Request

In distributed AI systems, TraceID is like the lifeline of a request. It should appear from the very first moment the request enters the system, and be carried along whenever crossing boundaries.

These boundaries include:

• HTTP request boundaries
• WebSocket connection boundaries
• Goroutine asynchronous boundaries
• Message queue boundaries
• Third-party model call boundaries
• Database write boundaries
• Cron task or callback boundaries

[!IMPORTANT]
Generating TraceID only at the API layer is meaningless. What is truly useful is whether it can penetrate every layer of the system.

A more ideal pipeline should look like this:

trace_id = T-001

HTTP request received
  └─> auth checked
      └─> quota checked
          └─> task created
              └─> queue published
                  └─> worker consumed
                      └─> embedding requested
                          └─> vector search completed
                              └─> llm stream started
                                  └─> websocket chunks pushed
                                      └─> final message persisted

When a user reports a problem, as long as we get trace_id = T-001, we should be able to fetch the complete behavior of this request.

• If you can only find HTTP layer logs but not worker logs, it means the TraceID broke at the 队列边界 (Queue Boundary).
• If you can find model call logs but not WebSocket push logs, it means the TraceID broke in the 长连接会话 (Long Connection Session).
• If you can find async task logs but not the user request entry, it means the async task became an isolated island.

III. In Go, TraceID Should Start from context

In Go projects, the most natural carrier for TraceID is context.Context.

It was originally designed to pass cancellation signals, timeouts, and metadata within the scope of a request. A common practice is to generate or read the TraceID at the entry layer and inject it into the request context:

func TraceMiddleware(next Handler) Handler {
    return func(ctx Context, req Request) Response {
        // 1. Read upstream TraceID with priority
        traceID := req.Header.Get("X-Trace-ID")
        if traceID == "" {
            traceID = NewTraceID() // 2. Generate if missing
        }

        ctx = WithTraceID(ctx, traceID)

        resp := next(ctx, req)
        
        // 3. Write TraceID back to response header for frontend/user reporting
        resp.Header.Set("X-Trace-ID", traceID)

        return resp
    }
}

Key Details

1. Read upstream TraceID with priority: If there is a gateway, BFF, or client SDK in front of your system, they may have already generated a TraceID. Overwriting it directly will cut the cross-service link.
2. Write back to response header: This is highly practical. When users report issues, the frontend can report the TraceID in the response together, making troubleshooting much faster.
3. Avoid directly reading and writing bare string keys in business code: Use strong types to wrap the read/write logic to prevent overwriting and conflicts.

type traceIDKey struct{}

func WithTraceID(ctx context.Context, traceID string) context.Context {
    return context.WithValue(ctx, traceIDKey{}, traceID)
}

func TraceIDFromContext(ctx context.Context) string {
    if v, ok := ctx.Value(traceIDKey{}).(string); ok {
        return v
    }
    return ""
}

IV. Log Wrapper: Don't Let Business Code Manually String-Concatenate TraceID

If you rely on business developers to manually append TraceIDs when writing logs, style discrepancies (such as trace_id=xxx, traceId=xxx, tid=xxx, etc.) will quickly pop up, making unified log index search impossible.

The correct approach is to inject TraceID as part of the logging infrastructure:

func Info(ctx context.Context, msg string, fields ...Field) {
    fields = appendTraceFields(ctx, fields...)
    logger.Info(msg, fields...)
}

func Warn(ctx context.Context, msg string, fields ...Field) {
    fields = appendTraceFields(ctx, fields...)
    logger.Warn(msg, fields...)
}

func Error(ctx context.Context, msg string, fields ...Field) {
    fields = appendTraceFields(ctx, fields...)
    logger.Error(msg, fields...)
}

func appendTraceFields(ctx context.Context, fields ...Field) []Field {
    if traceID := TraceIDFromContext(ctx); traceID != "" {
        fields = append(fields, String("trace_id", traceID))
    }
    return fields
}

Now, business developers only need to care about core business fields:

log.Info(ctx, "llm stream started",
    String("model", modelName),
    Int("prompt_tokens", promptTokens),
)

The final generated structured JSON log will automatically enrich the TraceID:

{
  "level": "info",
  "time": "2026-06-23T10:21:03.120+08:00",
  "msg": "llm stream started",
  "trace_id": "T-001",
  "model": "model_x",
  "prompt_tokens": 1024
}

V. Three Fragile Boundaries in AI Pipelines

5.1 Goroutine Asynchronous Boundary

In Go, we are used to using go func directly to handle background tasks:

// Bad practice: context disconnected
go func() {
    processJob(job)
}()

This causes the task to decouple from the original request context. A more robust approach is to explicitly pass the context:

// Improved version: pass Context
go func(ctx context.Context, job Job) {
    processJob(ctx, job)
}(ctx, job)

[!WARNING]
Beware of disconnected connections: The original request's ctx will be cancelled if the HTTP connection is interrupted. If the background task must continue running, you should copy the TraceID and rebuild a task-level Context with no cancellation semantics.

// Correct practice: extend tracing, but decouple cancellation signal
taskCtx := NewBackgroundContext()
taskCtx = WithTraceID(taskCtx, TraceIDFromContext(ctx))

go func(ctx context.Context, job Job) {
    processJob(ctx, job)
}(taskCtx, job)

5.2 Message Queue (MQ) Boundary

When a task enters the queue, the process contexts of the producer and consumer are completely disconnected. We must write the TraceID into the message's Metadata to pass it along:

type JobMessage struct {
    ID       string
    Payload  Payload
    Metadata map[string]string // Store tracing metadata
}

// Producer publishes task:
msg.Metadata["trace_id"] = TraceIDFromContext(ctx)
queue.Publish(msg)

// Consumer consumes task:
func Consume(msg JobMessage) {
    ctx := context.Background()
    ctx = WithTraceID(ctx, msg.Metadata["trace_id"]) // Restore TraceID
    process(ctx, msg.Payload)
}

5.3 WebSocket Long Connection Boundary

A WebSocket is a continuously connected channel, which may carry dozens of user AI dialogues and streaming pushes in the middle. If a single ID is generated only when the connection is established, logs of multiple dialogue rounds will be jumbled up.

The correct way is to distinguish two concepts:

1. connection_id: Identifies and tracks this specific WebSocket physical connection.
2. trace_id: Identifies each specific request event or single-round dialogue task.

connection_id = C-001, user_id = U-001
    ├── trace_id = T-101, event = user_audio_started
    ├── trace_id = T-101, event = llm_chunk_pushed
    └── trace_id = T-101, event = response_completed

VI. Full-Link Logging is Not Printing Everything

To avoid log platform storage explosions, performance degradation, and noise flooding, full-link logging should follow the principle of "key nodes + stage latency" instead of full recording.

We structure logs into three core categories:

1. Link Event Logs (Where)

Used to accurately describe which core node the request has reached:

• request_received -> auth_checked -> retrieval_started -> llm_started -> tts_completed -> message_persisted

2. Performance Metric Logs (Why Slow)

Used to quantitatively answer where the slow request bottleneck is:

• http_latency_ms (API latency)
• queue_wait_ms (Queue waiting)
• llm_first_token_latency_ms (Time-To-First-Token, crucial)
• llm_total_latency_ms (Model inference total time)
• tts_latency_ms (Speech synthesis latency)

3. Result Status Logs (Success Or Not)

In AI pipelines, there are gray states of "partial success" (e.g., model returned text successfully, but TTS synthesis failed). We must log status finely:

• status = success | failed | canceled | partial_success
• error_code = upstream_timeout
• retry_count = 2

VII. What Should Not Go into Logs (Masking Rules)

AI input and output usually contain user privacy, sensitive proprietary knowledge base fragments, or internal Prompts. Logging them without masking is a serious security vulnerability.

VIII. Troubleshooting a Real Issue Using TraceID

Suppose a user reports: "Just now after I finished speaking, AI took a very long time to answer, and it cut off halfway."

Using TraceID, the troubleshooting logic will be as simple as peeling an onion:

Through link troubleshooting, you can accurately restore the scene:

1. Exclude ASR fault: ASR latency is 920ms, normal.
2. Lock first token latency: LLM's first Token took 2600ms, locating the bottleneck at model service overload or cold start.
3. Locate interruption cause: Logs show llm_stream_interrupted with upstream_timeout, indicating the stream broke on the model side, which then triggered the WebSocket closure.

IX. TraceID, RequestID, and SpanID Collaborative Design

• TraceID: Identifies a complete end-to-end business link (e.g., a round of multi-modal dialogue initiated by a user).
• RequestID: Identifies a specific network request within the link.
• SpanID: Identifies a specific micro-execution step or sub-module call.

In complex large model architectures, it is recommended to reserve the following fields in logging specifications for seamless integration with Loki, ELK, or OpenTelemetry:

{
  "trace_id": "T-101",
  "request_id": "R-202",
  "span_id": "S-303",
  "connection_id": "C-001",
  "span_name": "vector_search",
  "latency_ms": 150,
  "status": "success"
}

X. Six Traps Most Easy to Fall Into

1. Only error logs carry TraceID: You must know what the system was doing before the error occurred. Therefore, Info and Warn logs at key nodes must also carry TraceIDs.
2. TraceID lost in async tasks (Goroutine/Queue): Queue boundaries failed to parse Metadata, or new Goroutines were opened with empty contexts.
3. A WebSocket long connection uses a single TraceID from beginning to end: Must use connection_id to identify the connection, and trace_id to distinguish each dialogue round.
4. Inconsistent logging field names: traceId, trace_id, and tid are mixed, causing aggregation analysis queries to fail. Standardize on trace_id.
5. Print raw Prompt / Response text to production logs for convenience: Data privacy red line, extremely easy to cause leaks.
6. Only log total request latency: AI systems must break down stage latency (especially first packet time TTFT and inference time), otherwise you cannot determine if it's slow on the network, model inference, or speech synthesis.

Conclusion

In building complex AI engineering, once context breaks at a physical or coroutine boundary, all logs degrade from a "continuous lifeline" into "isolated fragments".

TraceID full-link logging is not to eliminate AI system uncertainty, but to make complexity traceable, explainable, and repairable when timeout, interruption, or hallucination occurs.