Cross-Cutting Debugging — Request Tracing, Correlation, End-to-End

Tại sao quan trọng ở Production

Ketika client request slow (latency high, atau timeout):

client → load balancer → ingress → service → pod → sidecar → app → database

Mana yang slow? Load balancer? Pod? Database call?

Tanpa tracing, anda blind guessing:

Check pod logs (maybe normal)
Check database latency (maybe normal)
But still not know where request stuck

Distributed tracing solve ini: instrumentasi request, track request path through system, measure latency at each hop.

Internal Model: Distributed Tracing

Trace Structure

Trace:
  ├── Span 1 (incoming HTTP request @ load balancer)
  │   ├── Span 1.1 (DNS resolution)
  │   ├── Span 1.2 (TCP connect to pod)
  │   └── Span 1.3 (HTTP request processing)
  │       ├── Span 1.3.1 (database query)
  │       ├── Span 1.3.2 (cache lookup)
  │       └── Span 1.3.3 (response serialize)
  └── Span 2 (response send to client)

Trace: root request, from entry point to exit point.

Span: atomic operation (single service, single operation). Each span have:

name: operation name (e.g., "HTTP GET /api/users")
start_time: when operation start
end_time: when operation end
duration: end_time - start_time
span_id: unique identifier
parent_span_id: which span call this
trace_id: which trace contain this span
attributes: key-value metadata (e.g., http.status_code=200, db.query="SELECT ...")

Trace ID Propagation

Request flow multiple services:

Client (HTTP GET /api/users)
  ↓
  Generate trace_id = "abc123..."
  
Load Balancer
  ├── Create span "LB:recv_request"
  ├── Add trace_id to request header: "traceparent: 00-abc123...-<span_id>-01"
  ├── Forward to backend
  
Backend Service (pod)
  ├── Read trace_id from header
  ├── Create span "app:handle_request"
  │   └── Parent span_id = LB span_id
  ├── Call database
  │   ├── Create span "db:query"
  │   └── Add trace_id to database protocol
  
Database
  ├── Read trace_id (if supported)
  ├── Create span "mysql:execute"
  └── Return result

Critical: trace_id harus propagate across services, otherwise tracing broken.

Trace Backends

Trace data tebal, sulit store. Usually sample (record 1/100 requests, or adaptive sampling).

Cloud Trace adalah GCP managed backend:

Automatic sampling
Real-time visualization
Integration dengan Cloud Logging

Debugging Using Cloud Trace

Enable Tracing in GKE

bash

# Ensure Cloud Trace API enabled
gcloud services enable cloudtrace.googleapis.com

# Application must instrument code to send traces
# Use OpenTelemetry (recommended, vendor-neutral)

Instrumenting Application with OpenTelemetry

python

# Python example
from opentelemetry import trace
from opentelemetry.exporter.gcp_trace import CloudTraceExporter
from opentelemetry.sdk.trace import TracerProvider
from opentelemetry.sdk.trace.export import BatchSpanProcessor

# Setup exporter
trace_exporter = CloudTraceExporter()
trace.set_tracer_provider(TracerProvider())
trace.get_tracer_provider().add_span_processor(
    BatchSpanProcessor(trace_exporter)
)

# Get tracer
tracer = trace.get_tracer(__name__)

# Instrument code
with tracer.start_as_current_span("handle_request") as span:
    span.set_attribute("http.method", "GET")
    span.set_attribute("http.url", request.url)
    
    # Call downstream service
    with tracer.start_as_current_span("call_db"):
        result = query_database()
    
    return result

View Traces in Cloud Console

bash

# From GCP console:
# 1. Cloud Trace → Traces
# 2. Filter by service name, endpoint, latency
# 3. Click trace to see waterfall view

# Or via gcloud CLI
gcloud trace list --filter="service:my-app"

# Export trace for analysis
gcloud trace export <trace-id> > trace.json

Distributed Trace Waterfall Example

[Client]
  ├─ HTTP GET /api/users (total: 234ms)
  │  ├─ LB processing (2ms)
  │  ├─ TLS handshake (45ms)
  │  ├─ Network latency (8ms)
  │  ├─ Pod receive (1ms)
  │  └─ App processing (178ms)
  │     ├─ Authentication (12ms)
  │     ├─ Database query (150ms)  ← BOTTLENECK
  │     └─ Response serialization (16ms)
  └─ Network to client (2ms)

Trace immediately show database query is bottleneck (150ms out of 234ms).

Debugging Using Logs + Traces + Metrics Correlation

The Three Pillars

Logs: What happened (events, state changes) Traces: How long it took (timing, latency path) Metrics: Aggregated statistics (avg latency, error rate)

Combine ketiga untuk complete picture:

Scenario: latency spike
1. Metrics show: 99th percentile latency = 5s (normally 100ms)
2. Traces show: database query = 4.8s (normally 50ms)
3. Logs show: database slow query log, disk I/O intensive
4. Conclusion: database disk I/O bottleneck

Correlation via Request ID

Implement request ID (correlation ID) untuk trace through logs:

python

# Flask middleware
import uuid

@app.before_request
def set_request_id():
    g.request_id = request.headers.get('X-Request-ID', str(uuid.uuid4()))

@app.after_request
def add_request_id_header(response):
    response.headers['X-Request-ID'] = g.request_id
    return response

# In logs, always include request_id
logger.info("processing request", extra={'request_id': g.request_id, 'user_id': user_id})

Then search logs by request_id:

bash

# All logs for single request
kubectl logs -n default --selector=app=api | grep "request_id=abc-123"

# Or Cloud Logging
gcloud logging read "jsonPayload.request_id='abc-123'" --limit 100

Build End-to-End Timeline

14:23:45.123  Client: send request (trace_id=xyz)
14:23:45.135  Load Balancer: receive request
14:23:45.140  Pod: receive request
14:23:45.145  App: start processing
14:23:45.200  Database: receive query
14:23:45.500  Database: query complete (result: 100 rows)
14:23:45.505  App: process result
14:23:45.520  Pod: send response
14:23:45.530  Load Balancer: forward response
14:23:45.535  Client: receive response
         ↑
      392ms total latency

Every component contribute their latency. Find which one significant.

Debugging Request Path Through GKE

Path: Client → Load Balancer → Ingress → Service → Pod

bash

# 1. Check client perspective
# Network trace dari client machine (outside cluster)
curl -v https://my-app.example.com/api/users

# Check response time
time curl -s https://my-app.example.com/api/users > /dev/null

Step 1: Load Balancer

bash

# Check load balancer logs in GCP
gcloud compute backend-services describe <backend-service> \
  --global \
  --format='value(healthChecks)'

# Check LB response time
gcloud logging read \
  'resource.type="http_load_balancer" AND httpRequest.latency>' \
  --limit 50

# Look untuk slow requests

Step 2: Ingress

bash

# Ingress route traffic to backend service
kubectl describe ingress <name>
# Check rules, backend service mapping

# Check ingress controller logs
kubectl logs -n ingress-nginx -l app=ingress-nginx | tail -50

Step 3: Service

bash

# Service virtual IP route to endpoints
kubectl get endpoints <service>
# Check if endpoints exist

# Test service latency (from within cluster)
kubectl run test-pod --image=curlimages/curl -it --rm -- \
  sh -c "for i in {1..10}; do time curl -s http://my-service:8080/health > /dev/null; done"

# Average time show service + pod latency combined

Step 4: Pod

bash

# Port-forward to bypass service
kubectl port-forward pod/<name> 8080:8080

# Test pod latency directly
time curl http://localhost:8080/api/users
# If fast → service routing slow
# If slow → pod itself slow

Real-World Debugging Scenario

Symptom: API Endpoint Slow

Client complaint: request take >10 seconds.

bash

# Step 1: Check metrics
# Prometheus query: histogram_quantile(0.99, http_request_duration_seconds)
# Show: 99th percentile = 12s (bad)
# 95th percentile = 1s (normal)
# Meaning: some requests very slow, not all

# Step 2: Check traces
gcloud trace list --filter="latency>10000" --limit 10
# List top 10 slowest traces

# View specific slow trace
gcloud trace describe <trace-id>
# Output:
# - LB latency: 50ms (normal)
# - Pod latency: 9.8s (bottleneck!)

# Step 3: Check pod logs for those slow requests
kubectl logs -l app=api --since=10m | grep "request_id=<from-trace>"
# Log show: "query took 9.7s" (database)

# Step 4: Check database
# Slow query log
# Check if index missing, or disk I/O issue

# Step 5: Root cause: missing database index
# Add index, latency return to normal

GCP-Specific Tracing

Cloud Trace Auto-Instrumentation

GKE can auto-instrument via sidecar proxy (if using service mesh like Istio):

bash

# Install Istio
gcloud container clusters update <cluster> \
  --addons HorizontalPodAutoscaling,Istio

# Istio auto-inject sidecar proxy (Envoy)
# Envoy capture all traffic, auto-generate spans
# Spans sent to Cloud Trace automatically

Tracing Application Errors

Instrument error handling:

python

try:
    result = query_database()
except DatabaseError as e:
    # Record error in trace
    span.set_attribute("error", True)
    span.set_attribute("error.type", type(e).__name__)
    span.set_attribute("error.message", str(e))
    raise

Metrics-Based SLO

Use traces to define SLO:

yaml

# Example SLO: 95% of requests <500ms
spec:
  objectives:
  - displayName: "API latency"
    goal: 0.95
    indicator:
      requestBased:
        goodTotalRatio:
          totalServiceFilter: |-
            metric.type="kubernetes.io/http_request_duration_seconds"
            resource.label.service_name="my-api"
          goodServiceFilter: |-
            metric.type="kubernetes.io/http_request_duration_seconds"
            resource.label.service_name="my-api"
            metric.value < 0.5  # < 500ms

Common Tracing Patterns & Anti-patterns

Pattern 1: Proper Trace ID Propagation

Good: Manually propagate trace ID if auto-instrumentation tidak work:

python

# Incoming request
trace_id = request.headers.get('traceparent', str(uuid.uuid4()))

# Outgoing request to downstream service
headers = {'traceparent': trace_id}
response = requests.get(url, headers=headers)

Bad: Lose trace ID at any hop → tracing broken.

Pattern 2: Span Sampling Strategy

Adaptive sampling: Sample high-latency requests, error requests

python

# Sample request if latency > 1s or error
if latency > 1000 or error:
    sampled = True
else:
    sampled = random.random() < 0.01  # 1% for normal requests

Good: Capture interesting traces while keeping cost low.

Anti-pattern 1: Trace Too Detailed

Bad: Span untuk setiap line of code → trace huge, expensive:

python

# Too many spans
with tracer.start_as_current_span("line1"):
    x = 1
with tracer.start_as_current_span("line2"):
    y = 2
with tracer.start_as_current_span("line3"):
    z = x + y

Better: Span untuk logical units (function, operation):

python

with tracer.start_as_current_span("calculate_total"):
    x = 1
    y = 2
    z = x + y

Anti-pattern 2: Sensitive Data in Traces

Bad: Log password, API key, credit card:

python

# Don't do this!
span.set_attribute("password", user_password)
span.set_attribute("api_key", api_key)

Better: Sanitize sensitive data:

python

# Safe
span.set_attribute("user_id", user_id)
span.set_attribute("authentication_success", True)
# Don't log actual credentials

Operational Practices

1. Trace Sampling Configuration

yaml

# OpenTelemetry sampler config
samplers:
  jaeger:
    samplingServerURL: "http://jaeger:14250"
    # Adaptive sampling: sample slow/error requests more

2. Trace Retention

Cloud Trace default retention: 30 days. For long-term analysis, export to BigQuery:

bash

# Export traces to BigQuery
gcloud config set project <project-id>
gcloud logging sinks create trace-sink \
  bigquery.googleapis.com/projects/<project>/datasets/<dataset> \
  --log-filter='resource.type="cloud_trace"'

3. Instrumenting Without Code Changes

Use service mesh (Istio) untuk automatic tracing:

bash

# Enable Istio sidecar injection
kubectl label namespace default istio-injection=enabled

# Pods in namespace auto-get Envoy sidecar
# Envoy generate spans automatically

Cross-Cutting Debugging — Request Tracing, Correlation, End-to-End ​

Tại sao quan trọng ở Production ​

Internal Model: Distributed Tracing ​

Trace Structure ​

Trace ID Propagation ​

Trace Backends ​

Debugging Using Cloud Trace ​

Enable Tracing in GKE ​

Instrumenting Application with OpenTelemetry ​

View Traces in Cloud Console ​

Distributed Trace Waterfall Example ​

Debugging Using Logs + Traces + Metrics Correlation ​

The Three Pillars ​

Correlation via Request ID ​

Build End-to-End Timeline ​

Debugging Request Path Through GKE ​

Path: Client → Load Balancer → Ingress → Service → Pod ​

Real-World Debugging Scenario ​

Symptom: API Endpoint Slow ​

GCP-Specific Tracing ​

Cloud Trace Auto-Instrumentation ​

Tracing Application Errors ​

Metrics-Based SLO ​

Common Tracing Patterns & Anti-patterns ​

Pattern 1: Proper Trace ID Propagation ​

Pattern 2: Span Sampling Strategy ​

Anti-pattern 1: Trace Too Detailed ​

Anti-pattern 2: Sensitive Data in Traces ​

Operational Practices ​

1. Trace Sampling Configuration ​

2. Trace Retention ​

3. Instrumenting Without Code Changes ​

References ​

Cross-Cutting Debugging — Request Tracing, Correlation, End-to-End

Tại sao quan trọng ở Production

Internal Model: Distributed Tracing

Trace Structure

Trace ID Propagation

Trace Backends

Debugging Using Cloud Trace

Enable Tracing in GKE

Instrumenting Application with OpenTelemetry

View Traces in Cloud Console

Distributed Trace Waterfall Example

Debugging Using Logs + Traces + Metrics Correlation

The Three Pillars

Correlation via Request ID

Build End-to-End Timeline

Debugging Request Path Through GKE

Path: Client → Load Balancer → Ingress → Service → Pod

Real-World Debugging Scenario

Symptom: API Endpoint Slow

GCP-Specific Tracing

Cloud Trace Auto-Instrumentation

Tracing Application Errors

Metrics-Based SLO

Common Tracing Patterns & Anti-patterns

Pattern 1: Proper Trace ID Propagation

Pattern 2: Span Sampling Strategy

Anti-pattern 1: Trace Too Detailed

Anti-pattern 2: Sensitive Data in Traces

Operational Practices

1. Trace Sampling Configuration

2. Trace Retention

3. Instrumenting Without Code Changes

References