Traces, Logs, Metrics - Tương quan và Correlation

Three Pillars of Observability

Observability modern yêu cầu ba loại data:

         Metrics                Logs                  Traces
           |                     |                       |
    Aggregated stats        Individual events      Request flow
    (counters, gauges)       (text messages)       (call hierarchy)
           |                     |                       |
    "CPU 80%"            "User 123 logged in"    "Frontend → DB → Cache"
    "P99 latency 500ms"   "DB query failed"       "1s in DB, 0.1s in Cache"
           |                     |                       |
    Time series            Structured data         Causal relationships
           |                     |                       |
    Good for: alerts       Good for: debugging    Good for: diagnosis
    Good for: trends       Good for: context      Good for: root cause

Key insight: Ba loại data này không independent:

Metric spike: "latency ↑"
    ↓
Query logs: "Why latency high?"
    ↓
Find logs from affected requests
    ↓
Query traces: "Show me request flow"
    ↓
Trace shows: "stuck on DB query"
    ↓
Profile shows: "DB connection pool exhausted"
    ↓
Root cause found!

Correlation through Trace Context

Correlation ID (Request ID)

Correlation ID hay Request ID là identifier duy nhất cho một request:

Frontend receives request
├── Generates correlation_id = "req-abc123xyz"
├── Logs: "Request started, correlation_id=req-abc123xyz"
├── Trace: span.attribute("correlation_id", "req-abc123xyz")
├── Calls User Service + header: "X-Request-ID: req-abc123xyz"
│   └── User Service logs: "correlation_id=req-abc123xyz, fetching user..."
│   └── Calls Product Service + header: "X-Request-ID: req-abc123xyz"
│       └── Product Service logs: "correlation_id=req-abc123xyz, fetching product..."
└── Metrics: counter("requests_total", labels={"correlation_id": "req-abc123xyz"})

Result: Tất cả traces, logs, metrics cho single request được linked bằng correlation_id.

Trace ID vs Request ID

Thường có hai IDs:

ID	Scope	Purpose	Who Generates
Trace ID	Entire distributed trace	For Cloud Trace backend	Tracing library
Request ID	Single logical request	For logging & debugging	Application code

Trace ID: a0f3c87f9a1b2c3d4e5f6a7b8c9d0e1f
  │
  ├── Request ID: req-abc123  (Frontend → User Service)
  │
  ├── Request ID: req-def456  (User Service → Product Service)
  │
  └── Request ID: req-ghi789  (Product Service → Cache)

Mỗi "hop" trong microservice có Request ID riêng, nhưng chung một Trace ID.

Best practice: Include cả hai trong every log line:

import logging
import uuid

class CorrelationFilter(logging.Filter):
    def filter(self, record):
        record.trace_id = get_current_trace_id()
        record.request_id = get_current_request_id()
        return True

logging.basicConfig(
    format='%(asctime)s - %(trace_id)s - %(request_id)s - %(message)s'
)
logger = logging.getLogger(__name__)
logger.addFilter(CorrelationFilter())

logger.info("Processing order")  # Logs: "... trace_id=abc123 request_id=req-xyz ..."

Query Patterns - Debug Workflows

Workflow 1: "Latency Spike - Find Root Cause"

Scenario: P99 latency tăng từ 100ms lên 500ms.

Investigation steps:

1. Query metrics:

   SELECT
     timestamp,
     PERCENTILE_CONT(latency_ms, 0.99) as p99_latency,
     AVG(latency_ms) as avg_latency
   FROM latency_metrics
   WHERE timestamp >= NOW() - INTERVAL 1 HOUR
   GROUP BY timestamp
   HAVING p99_latency > 400

   Result: Spike at 10:30 AM.

2. Query logs for affected period:

   SELECT
     severity,
     COUNT(*) as count
   FROM logs
   WHERE timestamp >= TIMESTAMP("2026-06-24 10:30:00")
     AND timestamp < TIMESTAMP("2026-06-24 10:35:00")
   GROUP BY severity

   Result: Error count doubled.

3. Find error logs:

   SELECT
     timestamp,
     jsonPayload.error_message,
     labels.service,
     COUNT(*) as frequency
   FROM logs
   WHERE severity = "ERROR"
     AND timestamp >= TIMESTAMP("2026-06-24 10:30:00")
   GROUP BY error_message, service
   ORDER BY frequency DESC

   Result: "DB connection pool exhausted" in user-service.

4. Get correlation IDs from error logs:

   SELECT
     jsonPayload.correlation_id,
     jsonPayload.error_message,
     timestamp
   FROM logs
   WHERE jsonPayload.error_message LIKE "%DB connection%"
     AND timestamp >= TIMESTAMP("2026-06-24 10:30:00")
   LIMIT 10

   Result: correlation_ids = [req-123, req-456, req-789, ...]

5. Query traces for those correlation IDs:

   SELECT
     trace_id,
     duration_millis,
     spans
   FROM traces
   WHERE labels.correlation_id IN ('req-123', 'req-456', 'req-789')

   Result: Traces show bottleneck at database span.

6. Profiling: Use trace info to identify which profiles are affected, check CPU/memory.

Result: Root cause found - database connection pool was exhausted due to slow queries.

Workflow 2: "Error Rate Spike - Quantify Impact"

Scenario: Error rate jumped from 0.01% to 0.5%.

Investigation:

1. Query error metrics:

   SELECT
     timestamp,
     SUM(CASE WHEN status_code >= 500 THEN 1 ELSE 0 END) as errors_5xx,
     COUNT(*) as total_requests,
     ROUND(SUM(CASE WHEN status_code >= 500 THEN 1 ELSE 0 END) / COUNT(*) * 100, 2) as error_rate_percent
   FROM request_metrics
   WHERE timestamp >= NOW() - INTERVAL 1 HOUR
   GROUP BY timestamp
   ORDER BY error_rate_percent DESC

2. Query Error Reporting for frequency:

   from google.cloud import error_reporting_v1beta1
   
   client = error_reporting_v1beta1.ErrorStatsServiceClient()
   
   stats = client.list_error_stats(
       project_name="projects/my-project",
       time_range=monitoring_v3.TimeInterval(
           start_time=datetime.datetime.now() - datetime.timedelta(hours=1)
       )
   )
   
   for error_group in stats:
       print(f"Error: {error_group.group.name}")
       print(f"  Count: {error_group.count}")
       print(f"  Affected users: {error_group.affected_users_count}")

3. Get affected user IDs:

   SELECT
     jsonPayload.user_id,
     jsonPayload.error_message,
     COUNT(*) as error_count
   FROM logs
   WHERE severity = "ERROR"
     AND timestamp >= TIMESTAMP("2026-06-24 10:30:00")
   GROUP BY user_id, error_message
   ORDER BY error_count DESC

4. Determine rollout impact:

   SELECT
     labels.version,
     COUNT(*) as total_requests,
     SUM(CASE WHEN severity = "ERROR" THEN 1 ELSE 0 END) as errors,
     ROUND(SUM(CASE WHEN severity = "ERROR" THEN 1 ELSE 0 END) / COUNT(*) * 100, 2) as error_rate_percent
   FROM logs
   WHERE timestamp >= TIMESTAMP("2026-06-24 10:30:00")
   GROUP BY version

   Result: Version 1.5.0 has 0.5% error rate, version 1.4.9 has 0.01%. → 1.5.0 introduced bug!

5. Rollback: Immediate rollback to 1.4.9.

Observability as System

The Observability Graph

                        METRICS
                          |
                    (latency spike?)
                          |
                    ↓
                        LOGS
                          |
                  (which service? error message?)
                          |
                    ↓
                      TRACES
                          |
              (which function bottleneck? flow?)
                          |
                    ↓
                      PROFILER
                          |
            (CPU/memory/goroutine issue?)
                          |
                    ↓
                  ROOT CAUSE

Each layer provides more detail:

• Metrics: High-level health (red/yellow/green)
• Logs: Context (what happened)
• Traces: Causality (request flow)
• Profiler: Micro-level (CPU/memory)

Integration Example: Grafana + Cloud Logging + Cloud Trace

In Grafana dashboard:

1. Panel 1: Latency metric (time series graph)
2. Annotation: Link to Cloud Logging for error logs
3. Drill-down: Click time range → Open Cloud Logging
4. In Cloud Logging: Click correlation_id → Open Cloud Trace
5. In Cloud Trace: View flame graph + CPU details

Single click flow: metric → logs → traces → profiler.

Baggage & Metadata Propagation

Baggage for Business Context

from opentelemetry.baggage import set_baggage, get_baggage

# In frontend request handler
set_baggage("user_id", request.user_id)
set_baggage("customer_tier", request.user.tier)
set_baggage("feature_flag", "new_checkout")

# In any downstream service, automatically available
user_id = get_baggage("user_id")

# Logs automatically include baggage
logger.info("Processing order")  # Logs includes user_id from baggage

Baggage automatically propagated through trace context headers.

Struct Logging for Correlation

Instead of free-text logs, use structured logging:

import json

# BAD
logger.info("User 123 ordered product")

# GOOD
logger.info("User ordered product", extra={
    "user_id": 123,
    "product_id": 456,
    "order_amount": 99.99,
    "correlation_id": request.correlation_id,
    "trace_id": get_current_span().context.trace_id,
})

Structured logging enables querying:

SELECT
  jsonPayload.user_id,
  jsonPayload.product_id,
  jsonPayload.order_amount,
  jsonPayload.trace_id
FROM logs
WHERE jsonPayload.user_id = 123
ORDER BY timestamp DESC

Cost Optimization Through Correlation

Sampling Coordination

If metric shows P99 latency spike:

def dynamic_sampling_rate():
    p99_latency = get_metric("p99_latency_ms")
    
    if p99_latency > 1000:
        # Spike detected! Increase sampling to capture traces
        return 0.1  # 10% sampling (normal: 0.01%)
    else:
        return 0.01  # 1% sampling (cost-conscious)

Result: Automatically capture traces when investigating (cost-effective).

Selective Logging

Only log detailed info when needed:

def detailed_logging_enabled(user_id):
    # Check if this user has relevant error
    recent_errors = get_recent_errors(user_id)
    
    if len(recent_errors) > 0:
        return True  # Enable detailed logging for this user
    
    return False  # Disable detailed logging

# In application
if detailed_logging_enabled(request.user_id):
    logger.debug("Detailed request info", extra={...})  # Verbose
else:
    logger.info("Request received")  # Concise

Result: Reduce log volume by 10x while maintaining debugging capability.

Observability as Code

Observable Infrastructure

from opentelemetry import trace, metrics, logging as otel_logging

# Initialize all three pillars
trace_provider = setup_tracing()
meter_provider = setup_metrics()
logger_provider = setup_logging()

@app.route("/orders/<order_id>")
def get_order(order_id):
    # Tracing
    with tracer.start_as_current_span("get_order") as span:
        span.set_attribute("order_id", order_id)
        
        # Metrics
        counter = meter.create_counter("order_requests")
        counter.add(1, {"order_id": order_id})
        
        # Logging
        logger.info("Fetching order", extra={"order_id": order_id})
        
        try:
            order = db.query(order_id)
            
            # Success metric
            meter.create_histogram("order_fetch_duration").record(
                time.time() - start_time,
                {"status": "success"}
            )
            
            return order
        
        except NotFoundError:
            # Error metric
            error_counter = meter.create_counter("order_errors")
            error_counter.add(1, {"error_type": "not_found"})
            
            # Error logging
            logger.error("Order not found", extra={
                "order_id": order_id,
                "error_type": "not_found"
            })
            
            # Error trace
            span.record_exception(e)
            span.set_status(trace.Status(trace.StatusCode.ERROR))
            
            raise

Single code block emits all three signals!

Anti-Patterns

Anti-pattern 1: Logs without Correlation ID

# BAD
logger.info("Processing order")  # No way to link to trace!

# GOOD
logger.info("Processing order", extra={
    "correlation_id": request.correlation_id,
    "trace_id": get_current_span().context.trace_id,
})

Anti-pattern 2: Metrics without Trace Context

# BAD
counter.add(1)  # Which request caused this metric?

# GOOD
counter.add(1, {
    "service": "user-service",
    "endpoint": request.endpoint,
    "status": response.status_code,
})

Anti-pattern 3: Traces without Business Context

# BAD
span.set_attribute("operation", "query")  # Too vague

# GOOD
span.set_attribute("operation", "query")
span.set_attribute("table", "orders")
span.set_attribute("user_id", user_id)
span.set_attribute("query_cost", db_cost)

Anti-pattern 4: No Sampling Coordination

# BAD - Independent sampling
trace_sample_rate = 0.01
log_sample_rate = 0.1
metric_sample_rate = 1.0

# Result: Metric shows error spike, but only 1% of logs sampled, 0.1% of traces!
# Can't correlate.

# GOOD - Coordinated sampling
if error_spike_detected():
    trace_sample_rate = 0.5  # Capture more traces
    log_sample_rate = 0.5    # Capture more logs
else:
    trace_sample_rate = 0.01
    log_sample_rate = 0.01

References

• Observability Overview
• Cloud Logging Documentation
• Cloud Monitoring (Metrics) Documentation
• Correlation IDs Best Practices
• Structured Logging
• OpenTelemetry Correlation Context