Lab: Investigate a Metric -> Logs -> Trace Workflow

Objective

By the end of this lab you will have taken one alert-shaped symptom and walked it down to a single span attribute, and you will have rejected two plausible causes on evidence rather than on instinct. The stack is already wired: this is not a lab about configuring correlation, it is a lab about using it under the one condition that makes it hard, which is that more than one thing changed at the same time.

The fixture plays a twelve-minute incident with three signals and three candidate causes. Exactly one is the cause. The other two are the two most common red herrings in the causality lesson — a coincident deploy and a symptom of the symptom — and both of them are real, observable, and correctly timed. Dismissing them is easy and worthless; disproving them is the exercise.

Architecture

Five containers and one script. The script is the application: it writes a Prometheus exposition, pushes log lines to Loki, and pushes spans to Tempo, all for the same simulated request stream, so the three signals agree with each other because they describe the same events.

  drive-incident.sh (on the host, 12 minutes)
     |            |                    |
     | writes     | pushes             | pushes
     v            v                    v
  exposition   Loki push API      Tempo OTLP/HTTP
  file            :3100                :4318
     |               |                    |
     | served by     |                    |
     v  nginx :8080  |                    |
  +-----------+      |                    |
  | prometheus|      |                    |
  |  :9090    |      |                    |
  +-----------+      |                    |
        |            |                    |
        +------------+--------------------+
                     |
                you (curl + jq)
        metric -> logs -> trace, by hand

There is no Grafana here on purpose. Every pivot in this lab is a command, so what you learn is the join — a label set, a time window, a trace id — rather than which button produces it. The buttons are the subject of the correlation lab; this one is about what you do once they exist.

Requirements

• A disposable Linux host with Docker Engine 28.x and the Compose v2 plugin. The lab binds five loopback ports (8080, 9090, 3100, 3200, 4318), creates four named volumes and one directory under your home.
• curl and jq on the host. The fixture builds every push body with jq; the investigation reads every response with it.
• GNU date for date -u -d '5 minutes ago', and bash for the driver’s arithmetic loops.
• About 2 GB of free disk and 1.5 GB of RAM headroom.
• Roughly 25 uninterrupted minutes. The fixture runs for twelve minutes in real time and the investigation is done against it, so this is one of the few labs in the course you cannot pause halfway through and resume tomorrow.
• No out-of-band access requirement. Nothing touches the host network configuration, the firewall, or SSH.

Scenario

You are on call. The alert says:

CheckoutErrorRatioHigh — checkout error ratio above 5% for 3 minutes.

You know three things before you look at anything. The platform has all three signals. There was a deployment about half an hour into the shift. And the last person who worked an incident like this reverted that deployment, waited, and then had to explain why the errors continued for another forty minutes.

Your job is not to be fast. It is to be right in a way you can show someone afterwards, which means the evidence has to survive the question “how do you know it was not the deploy?”

Tasks

Task 1: Lay out the working tree and check the ports

LABDIR="$HOME/rb-obs-investigation"
mkdir -p "$LABDIR/exposition"
cd "$LABDIR"

for PORT in 8080 9090 3100 3200 4318; do
  if ss -ltn "sport = :$PORT" | grep -q LISTEN; then
    echo "PORT $PORT IS ALREADY IN USE - stop that service or move this lab"
  fi
done
echo "port check done"

A silent loop means every port is free. Resolve anything that prints now: a port conflict discovered later looks like a signal that is missing rather than a container that never started, and this lab is entirely about not being misled by a missing signal.

Task 2: Write the backend configurations

prometheus.yml — a five-second scrape, because a twelve-minute incident needs resolution:

# prometheus.yml
global:
  scrape_interval: 5s
  evaluation_interval: 15s

scrape_configs:
  - job_name: checkout-exposition
    static_configs:
      - targets: ['exposer:80']
        labels:
          env: prod

loki-config.yaml — the single-binary filesystem configuration:

# loki-config.yaml
auth_enabled: false

server:
  http_listen_port: 3100
  grpc_listen_port: 9096
  log_level: warn

common:
  instance_addr: 127.0.0.1
  path_prefix: /loki
  storage:
    filesystem:
      chunks_directory: /loki/chunks
      rules_directory: /loki/rules
  replication_factor: 1
  ring:
    kvstore:
      store: inmemory

schema_config:
  configs:
    - from: 2024-04-01
      store: tsdb
      object_store: filesystem
      schema: v13
      index:
        prefix: index_
        period: 24h

limits_config:
  reject_old_samples: false
  ingestion_rate_mb: 16
  ingestion_burst_size_mb: 32

analytics:
  reporting_enabled: false

tempo.yaml — local storage with the OTLP receivers on:

# tempo.yaml
server:
  http_listen_port: 3200
  log_level: warn

distributor:
  receivers:
    otlp:
      protocols:
        http:
          endpoint: 0.0.0.0:4318
        grpc:
          endpoint: 0.0.0.0:4317

ingester:
  # Short blocks so a span pushed during the lab is retrievable during the lab.
  max_block_duration: 5m

compactor:
  compaction:
    block_retention: 1h

storage:
  trace:
    backend: local
    wal:
      path: /var/tempo/wal
    local:
      path: /var/tempo/blocks

nginx.conf — serves whatever the driver last wrote:

# nginx.conf
server {
    listen 80;
    server_name _;

    location = /metrics {
        default_type "text/plain; version=0.0.4; charset=utf-8";
        alias /srv/metrics;
    }
}

compose.yaml:

# compose.yaml
name: rb-obs-investigation

services:
  exposer:
    image: nginx:1.27-alpine
    volumes:
      - ./nginx.conf:/etc/nginx/conf.d/default.conf:ro
      # The DIRECTORY, not the file. The driver rewrites the exposition by
      # writing a temporary file and renaming it, which replaces the inode;
      # a single-file bind mount would keep serving the original inode
      # forever, and the symptom would be a metric that never changes.
      - ./exposition:/srv:ro
    ports:
      - '127.0.0.1:8080:80'

  prometheus:
    image: prom/prometheus:v2.55.1
    command:
      - --config.file=/etc/prometheus/prometheus.yml
      - --storage.tsdb.path=/prometheus
      - --storage.tsdb.retention.time=3h
    volumes:
      - ./prometheus.yml:/etc/prometheus/prometheus.yml:ro
      - prom-data:/prometheus
    ports:
      - '127.0.0.1:9090:9090'

  loki:
    image: grafana/loki:3.3.0
    command: ['-config.file=/etc/loki/loki-config.yaml']
    volumes:
      - ./loki-config.yaml:/etc/loki/loki-config.yaml:ro
      - loki-data:/loki
    ports:
      - '127.0.0.1:3100:3100'

  # Tempo runs as uid 10001 and its storage paths do not exist in the image,
  # so Docker creates the volume owned by root and Tempo cannot write to it.
  # This one-shot container fixes the ownership before Tempo starts.
  tempo-init:
    image: grafana/tempo:2.6.0
    user: root
    entrypoint: ['/bin/sh', '-c']
    command: ['chown -R 10001:10001 /var/tempo']
    volumes:
      - tempo-data:/var/tempo

  tempo:
    image: grafana/tempo:2.6.0
    command: ['-config.file=/etc/tempo/tempo.yaml']
    depends_on:
      tempo-init:
        condition: service_completed_successfully
    volumes:
      - ./tempo.yaml:/etc/tempo/tempo.yaml:ro
      - tempo-data:/var/tempo
    ports:
      - '127.0.0.1:3200:3200'
      - '127.0.0.1:4318:4318'

volumes:
  prom-data:
  loki-data:
  tempo-data:

Create an empty exposition before nginx starts, so the first scrape reads an empty file rather than a 404 and Prometheus records the target as up from the beginning:

: > "$LABDIR/exposition/metrics"

Task 3: Write the fixture

This script is the application, the deploy, the dependency and the incident. Read it once now — knowing what it does is not cheating, because the exercise is the discipline of the investigation, not the guessing.

cat > "$LABDIR/drive-incident.sh" <<'DRIVE'
#!/usr/bin/env bash
# Twelve minutes of one service's telemetry in three signals.
#   0:00 - 4:00   healthy
#   3:30          an unrelated service deploys        (distraction one)
#   4:00 - 9:00   the payment dependency degrades     (the cause)
#   4:00 - 9:00   checkout's log volume multiplies     (distraction two)
#   9:00 - 12:00  recovery
set -uo pipefail

EXPO=${1:-./exposition/metrics}
LOKI=${LOKI:-http://127.0.0.1:3100}
TEMPO=${TEMPO:-http://127.0.0.1:4318}
TICKS=144; STEP=5           # 144 x 5s = 12 minutes
INCIDENT_FROM=48            # tick 48  = 4:00
INCIDENT_TO=108             # tick 108 = 9:00
DEPLOY_AT=42                # tick 42  = 3:30

pay_ok=0; pay_err=0; cart_ok=0; rec_ok=0
b01=0; b05=0; b1=0; b5=0; binf=0; sum_ms=0
rec_version=4.1.0

write_expo() {
  # Written to a temporary file and renamed, so a scrape never reads a
  # half-written exposition. A partial scrape looks like a counter reset.
  {
    echo '# HELP http_server_requests_total Requests handled, by endpoint and status.'
    echo '# TYPE http_server_requests_total counter'
    printf 'http_server_requests_total{service="checkout",endpoint="/api/v1/payment",status="200"} %d\n' "$pay_ok"
    printf 'http_server_requests_total{service="checkout",endpoint="/api/v1/payment",status="502"} %d\n' "$pay_err"
    printf 'http_server_requests_total{service="checkout",endpoint="/api/v1/cart",status="200"} %d\n' "$cart_ok"
    printf 'http_server_requests_total{service="recommendations",endpoint="/api/v1/recommend",status="200"} %d\n' "$rec_ok"
    echo '# HELP http_server_request_duration_seconds Checkout request duration.'
    echo '# TYPE http_server_request_duration_seconds histogram'
    printf 'http_server_request_duration_seconds_bucket{service="checkout",le="0.1"} %d\n' "$b01"
    printf 'http_server_request_duration_seconds_bucket{service="checkout",le="0.5"} %d\n' "$b05"
    printf 'http_server_request_duration_seconds_bucket{service="checkout",le="1"} %d\n' "$b1"
    printf 'http_server_request_duration_seconds_bucket{service="checkout",le="5"} %d\n' "$b5"
    printf 'http_server_request_duration_seconds_bucket{service="checkout",le="+Inf"} %d\n' "$binf"
    printf 'http_server_request_duration_seconds_sum{service="checkout"} %d.%03d\n' "$(( sum_ms / 1000 ))" "$(( sum_ms % 1000 ))"
    printf 'http_server_request_duration_seconds_count{service="checkout"} %d\n' "$binf"
    echo '# HELP service_build_info The version each service is running.'
    echo '# TYPE service_build_info gauge'
    printf 'service_build_info{service="checkout",version="2.8.1"} 1\n'
    printf 'service_build_info{service="recommendations",version="%s"} 1\n' "$rec_version"
  } > "$EXPO.tmp"
  mv "$EXPO.tmp" "$EXPO"
}

push_log() {   # push_log SERVICE LEVEL LINE
  jq -nc --arg ts "$(date -u +%s)000000000" \
         --arg svc "$1" --arg lvl "$2" --arg line "$3" \
    '{streams:[{stream:{service:$svc, env:"prod", level:$lvl},
                values:[[$ts,$line]]}]}' \
  | curl -sf -X POST "$LOKI/loki/api/v1/push" \
      -H 'Content-Type: application/json' --data-binary @- >/dev/null
}

emit_traced_request() {   # emit_traced_request ok|fail
  local outcome=$1 tid sid cid dur code level msg scode
  tid=$(printf '%016x%016x' "$(date +%s)" "$(( RANDOM * 32768 + RANDOM ))")
  sid=$(printf '%016x' "$(( RANDOM * 32768 + RANDOM ))")
  cid=$(printf '%016x' "$(( RANDOM * 32768 + RANDOM ))")
  if [ "$outcome" = fail ]; then
    dur=3100; code=502; level=error; scode=2; msg="payment upstream returned 502"
  else
    dur=120;  code=200; level=info;  scode=0; msg="payment authorised"
  fi

  # The log line carries the trace id. This is the whole log-to-trace pivot.
  push_log checkout "$level" \
    "$(jq -nc --arg t "$tid" --arg c "$code" --arg m "$msg" \
        '{level:(if $c=="502" then "error" else "info" end),
          service:"checkout", endpoint:"/api/v1/payment",
          status:($c|tonumber), upstream:"payments-gateway",
          trace_id:$t, msg:$m}')"

  local pe ps ce cs
  pe=$(( $(date -u +%s) * 1000000000 ))
  ps=$(( pe - dur * 1000000 ))
  cs=$(( ps + 10000000 )); ce=$(( pe - 5000000 ))

  jq -nc --arg tid "$tid" --arg sid "$sid" --arg cid "$cid" \
     --arg ps "$ps" --arg pe "$pe" --arg cs "$cs" --arg ce "$ce" \
     --arg code "$code" --arg msg "$msg" --argjson scode "$scode" '
     {resourceSpans:[{
       resource:{attributes:[{key:"service.name",
                              value:{stringValue:"checkout"}}]},
       scopeSpans:[{scope:{name:"runbook-academy-fixture"},
         spans:[
           {traceId:$tid, spanId:$sid, name:"POST /api/v1/payment", kind:2,
            startTimeUnixNano:$ps, endTimeUnixNano:$pe,
            attributes:[{key:"http.response.status_code",
                         value:{stringValue:$code}}],
            status:{code:$scode}},
           {traceId:$tid, spanId:$cid, parentSpanId:$sid,
            name:"POST payments-gateway /charge", kind:3,
            startTimeUnixNano:$cs, endTimeUnixNano:$ce,
            attributes:[{key:"peer.service",
                         value:{stringValue:"payments-gateway"}},
                        {key:"http.response.status_code",
                         value:{stringValue:$code}}],
            status:{code:$scode, message:$msg}}
         ]}]}]}' \
  | curl -sf -X POST "$TEMPO/v1/traces" \
      -H 'Content-Type: application/json' --data-binary @- >/dev/null
}

echo "driver started $(date -u +%H:%M:%S) - 12 minutes"

for (( i=1; i<=TICKS; i++ )); do
  rec_ok=$(( rec_ok + 25 ))

  if (( i == DEPLOY_AT )); then
    rec_version=4.2.0
    push_log recommendations info \
      '{"level":"info","service":"recommendations","msg":"starting","version":"4.2.0"}'
  fi

  if (( i >= INCIDENT_FROM && i <= INCIDENT_TO )); then
    cart_ok=$(( cart_ok + 20 )); pay_ok=$(( pay_ok + 12 )); pay_err=$(( pay_err + 6 ))
    b05=$(( b05 + 32 )); b1=$(( b1 + 32 )); b5=$(( b5 + 38 )); binf=$(( binf + 38 ))
    sum_ms=$(( sum_ms + 32 * 120 + 6 * 3100 ))
    # One traced failure per tick, plus two untraced ones: most requests are
    # not sampled, which is why finding a log line WITH a trace id is a skill.
    emit_traced_request fail
    push_log checkout error \
      '{"level":"error","service":"checkout","endpoint":"/api/v1/payment","status":502,"upstream":"payments-gateway","msg":"payment upstream returned 502"}'
    push_log checkout error \
      '{"level":"error","service":"checkout","endpoint":"/api/v1/payment","status":502,"upstream":"payments-gateway","msg":"payment upstream returned 502"}'
  else
    cart_ok=$(( cart_ok + 20 )); pay_ok=$(( pay_ok + 18 ))
    b05=$(( b05 + 38 )); b1=$(( b1 + 38 )); b5=$(( b5 + 38 )); binf=$(( binf + 38 ))
    sum_ms=$(( sum_ms + 38 * 120 ))
    (( i % 4 == 0 )) && emit_traced_request ok
    (( i % 4 == 0 )) && push_log checkout info \
      '{"level":"info","service":"checkout","endpoint":"/api/v1/cart","status":200,"msg":"cart rendered"}'
  fi

  write_expo
  sleep "$STEP"
done

echo "driver finished $(date -u +%H:%M:%S)"
DRIVE

chmod +x "$LABDIR/drive-incident.sh"

Task 4: Start everything, then confirm all three signals arrive

$ cd ~/rb-obs-investigation && docker compose up -d

cd "$LABDIR"
for i in $(seq 1 40); do
  curl -sf http://127.0.0.1:9090/-/ready >/dev/null &&
  curl -sf http://127.0.0.1:3100/ready   >/dev/null &&
  curl -sf http://127.0.0.1:3200/ready   >/dev/null && break
  sleep 2
done
docker compose ps -a

Start the fixture in the background and note the wall-clock time it began — every window you ask about later is relative to it:

nohup "$LABDIR/drive-incident.sh" "$LABDIR/exposition/metrics" \
  > "$LABDIR/driver.log" 2>&1 &
echo $! > "$LABDIR/driver.pid"
date -u +'driver started at %H:%M:%SZ' | tee "$LABDIR/t0.txt"

Wait about ninety seconds, then prove each signal is actually landing. Do this before you need it: a signal you discover is missing halfway through an investigation costs you the investigation.

# Metrics: the target is up and the counter is moving.
curl -sG http://127.0.0.1:9090/api/v1/query \
  --data-urlencode 'query=sum(rate(http_server_requests_total[1m]))' \
| jq -r '.data.result[0].value[1]'

# Logs: something is in the stream.
curl -sG http://127.0.0.1:3100/loki/api/v1/query \
  --data-urlencode 'query=sum(count_over_time({service="checkout"}[1m]))' \
| jq -r '.data.result[0].value[1]'

# Traces: Tempo's distributor counts what it has received. Read the names in
# the output rather than assuming one - the set differs between versions, and
# the counter you want is whichever one names received or accepted spans.
curl -s http://127.0.0.1:3200/metrics | grep -E '^tempo_distributor_' | head -5

Now wait until the driver has been running for about six minutes, so the incident window is genuinely in the past and genuinely in the data. Use the time to read Task 5 and write your hypotheses before you look at anything.

Task 5: State the symptom as a fact, with numbers

The alert is a claim. The first job is to turn it into a statement that has a magnitude, a window, and a scope — the difference between “checkout is broken” and something you can test.

# The error ratio, per endpoint. The grouping is the point: an error ratio
# without a scope is a number nobody can act on.
curl -sG http://127.0.0.1:9090/api/v1/query \
  --data-urlencode 'query=sum by (endpoint) (rate(http_server_requests_total{service="checkout",status=~"5.."}[2m]))
                          / sum by (endpoint) (rate(http_server_requests_total{service="checkout"}[2m]))' \
| jq -r '.data.result[] | "\(.metric.endpoint) \(.value[1])"'

# The latency the user experiences, from the histogram.
curl -sG http://127.0.0.1:9090/api/v1/query \
  --data-urlencode 'query=histogram_quantile(0.95, sum by (le) (rate(http_server_request_duration_seconds_bucket{service="checkout"}[2m])))' \
| jq -r '.data.result[0].value[1]'

# Is the traffic itself unusual? A rate that fell would be a different
# incident with a different first move.
curl -sG http://127.0.0.1:9090/api/v1/query \
  --data-urlencode 'query=sum(rate(http_server_requests_total{service="checkout"}[2m]))' \
| jq -r '.data.result[0].value[1]'

Then find the edges of the window, because “when did it start” is the question every hypothesis will be tested against:

START=$(date -u -d '12 minutes ago' +%s)
END=$(date -u +%s)

curl -sG http://127.0.0.1:9090/api/v1/query_range \
  --data-urlencode 'query=sum(rate(http_server_requests_total{service="checkout",status="502"}[1m]))' \
  --data-urlencode "start=$START" --data-urlencode "end=$END" \
  --data-urlencode 'step=15' \
| jq -r '.data.result[0].values[] | "\(.[0] | tonumber | strftime("%H:%M:%S")) \(.[1])"' \
| awk '$2 != "0" { print }' | head -3

Write the symptom down now, in one sentence with four parts. Mine reads: “From 04:0x, roughly a third of requests to /api/v1/payment on checkout returned 502 and p95 latency moved from the sub-second bucket into the multi-second one; the cart endpoint and the overall request rate are unaffected.” Yours should carry your own timestamps and your own numbers.

Note what the quantile is and is not. histogram_quantile interpolates inside whichever bucket the percentile falls into, so the figure it returns is a statement about bucket boundaries rather than a duration any single request took. That is fine for “did latency move”, which is the question here, and it is why the number changes when someone edits the buckets.

Task 6: Write three hypotheses before you look at anything else

Do this in a file, before the next command. The act of writing forces the precision, and the file is what makes the post-incident review honest.

cat > "$LABDIR/hypotheses.md" <<'DOC'
# Candidate causes
# Written before the evidence, in order of my prior confidence.

H1. The recommendations deploy at ~03:30 broke something checkout depends on.
    Prediction if true: the errors began after the version changed, and
    checkout's failing path touches recommendations.

H2. A downstream dependency of the payment path is failing or slow.
    Prediction if true: the failing requests spend their time outside
    checkout, and checkout's own error lines name the dependency.

H3. The logging pipeline is in trouble and the errors are an artefact.
    Prediction if true: the log volume rose before or with the error rate,
    and the log store shows rejections.
DOC

cat "$LABDIR/hypotheses.md"

H1 is there because a deploy really did happen thirty seconds before the symptom, and recency is the fourth red herring in the causality lesson: the most salient change is the one you reach for. H3 is there because you are about to see checkout’s log volume triple, and a spike in logs is a symptom of a symptom.

Task 7: Evidence, cheapest first — metric to logs

The pivot from a metric to logs is the label set plus the time window. The metric series that is failing is {service="checkout", endpoint="/api/v1/payment", status="502"}; the Loki stream carries service and level, and the rest of the fields live in the line:

LSTART=$(date -u -d '12 minutes ago' +%s)000000000
LEND=$(date -u +%s)000000000

# The error lines behind the metric, most recent first.
curl -sG http://127.0.0.1:3100/loki/api/v1/query_range \
  --data-urlencode 'query={service="checkout", level="error"} | json | endpoint = "/api/v1/payment"' \
  --data-urlencode "start=$LSTART" --data-urlencode "end=$LEND" \
  --data-urlencode 'limit=5' \
| jq -r '.data.result[].values[][1]'

Every line names an upstream. That is the first piece of evidence for H2 and the first thing that does not mention recommendations at all.

Now test H3 while you are in the log store, because it is cheap here and expensive later. Compare when the log volume rose against when the errors rose:

curl -sG http://127.0.0.1:3100/loki/api/v1/query_range \
  --data-urlencode 'query=sum(count_over_time({service="checkout"}[1m]))' \
  --data-urlencode "start=$LSTART" --data-urlencode "end=$LEND" \
  --data-urlencode 'step=30' \
| jq -r '.data.result[0].values[] | "\(.[0] | tonumber | strftime("%H:%M:%S")) \(.[1])"'

The volume multiplies several times over, and it does so at the error rate’s rise rather than before it. A cause precedes its effect; this follows. Add the second half of the disproof — the log store is not rejecting anything, so nothing is being lost:

curl -s http://127.0.0.1:3100/metrics | grep '^loki_discarded_samples_total' \
  || echo "no discards recorded"

H3 is rejected, on two independent pieces of evidence. Write the rejection and its reason into hypotheses.md now rather than at the end; a rejected hypothesis that nobody wrote down gets re-investigated by the next person.

Task 8: Disprove the deploy, positively

This is the task most investigations skip, and the reason the previous on-call engineer reverted an innocent change. The timeline supports H1: the version did change thirty seconds before the errors began. Confirm that first, because an argument you have not checked is not an argument:

curl -sG http://127.0.0.1:9090/api/v1/query_range \
  --data-urlencode 'query=service_build_info{service="recommendations"}' \
  --data-urlencode "start=$START" --data-urlencode "end=$END" \
  --data-urlencode 'step=15' \
| jq -r '.data.result[] | "\(.metric.version) first=\(.values[0][0] | tonumber | strftime("%H:%M:%S")) last=\(.values[-1][0] | tonumber | strftime("%H:%M:%S"))"'

Two series, one per version, and the handover time is right before the symptom. On recency alone, H1 wins. So go and look for the mechanism it would need:

# 1. Did the deployed service itself start failing?
curl -sG http://127.0.0.1:9090/api/v1/query \
  --data-urlencode 'query=sum by (status) (rate(http_server_requests_total{service="recommendations"}[2m]))' \
| jq -r '.data.result[] | "status=\(.metric.status) \(.value[1])"'

# 2. Does the deployed service appear anywhere in checkout's failure lines?
curl -sG http://127.0.0.1:3100/loki/api/v1/query \
  --data-urlencode 'query=sum(count_over_time({service="checkout", level="error"} |= "recommendations" [10m]))' \
| jq -r '.data.result[0].value[1] // "0"'

The deployed service is serving 200s at a steady rate, and it is named in none of checkout’s error lines. A deploy that broke the payment path would have to show up somewhere on the payment path; it shows up nowhere. H1 is contradicted by evidence rather than dismissed by intuition, and that distinction is the whole difference between this investigation and the last one.

Task 9: Log to trace, and the decisive evidence

Only some requests are sampled, so the first job is to find an error line that actually carries a trace id:

TRACE_ID=$(curl -sG http://127.0.0.1:3100/loki/api/v1/query_range \
  --data-urlencode 'query={service="checkout", level="error"} | json | trace_id != ""' \
  --data-urlencode "start=$LSTART" --data-urlencode "end=$LEND" \
  --data-urlencode 'limit=1' \
| jq -r '.data.result[0].values[0][1]' | jq -r '.trace_id')

echo "trace: $TRACE_ID"

Fetch it from Tempo. Read the shape first, then read the answer out of it:

curl -sf -H 'Accept: application/json' \
  "http://127.0.0.1:3200/api/traces/$TRACE_ID" | jq 'keys'

curl -sf -H 'Accept: application/json' \
  "http://127.0.0.1:3200/api/traces/$TRACE_ID" \
| jq -r '[.. | .spans? // empty | .[]] | .[]
         | "\(.name)  \(((.endTimeUnixNano|tonumber) - (.startTimeUnixNano|tonumber)) / 1000000 | floor) ms"'

Two spans: the checkout request, and inside it a call to the payments gateway that accounts for nearly all of its duration. Now read the attributes on the child span, which is where the cause finally has a name:

curl -sf -H 'Accept: application/json' \
  "http://127.0.0.1:3200/api/traces/$TRACE_ID" \
| jq '[.. | .spans? // empty | .[]] | .[] | select((.parentSpanId // "") != "")
      | {name, attributes, status}'

peer.service names the dependency, the status code is the 502 the metric counted, and the span status carries the message the log line carried. Three independent signals, one request, one conclusion: checkout is not failing, checkout is reporting a dependency that is.

Task 10: Decide, then write it down

You have a cause and you do not own the fix — the failing dependency is another team’s. That is the ordinary case, and it is where the decision that matters gets made.

The loop says mitigate before you fully understand, and you now understand more than enough. The options are the usual three, and each carries a cost worth stating out loud: fail the payment path fast rather than after three seconds, so that the latency stops consuming checkout’s connection pool; disable the feature that calls it, which trades revenue for stability; or hold, and page the team that owns the gateway. Holding is a first-class option when the blast radius is bounded and someone owns the next step — but a hold with no owner and no end time is not a decision, it is a silence.

cat > "$LABDIR/incident-note.md" <<'DOC'
# Incident note - checkout error ratio

## Symptom
(one sentence: metric, magnitude, window, scope - from Task 5)

## Impact
(error ratio and p95 latency on the affected endpoint; unaffected endpoints)

## Cause
Calls from checkout to the payments gateway returned 502 with ~3 s latency.
Evidence: error ratio by endpoint (metric), upstream field on checkout's own
error lines (logs), child span to payments-gateway carrying the error status
and nearly all of the request duration (trace).

## Rejected: recommendations deploy at ~03:30
Contradicted by: the deployed service continued serving 200s at a steady
rate; it is named in none of checkout's error lines; it appears in no span of
the failing trace. Time proximity only.

## Rejected: logging pipeline problem
Contradicted by: log volume rose with the error rate rather than before it;
no discards recorded at the log store.

## Mitigation
(what you would do, who owns it, and when you would re-evaluate)

## Follow-up
(the alert that should have caught the dependency directly)
DOC

$EDITOR "$LABDIR/incident-note.md" 2>/dev/null || cat "$LABDIR/incident-note.md"

Fill in the bracketed sections from your own numbers. The two rejection sections are already written because they are the part of an incident note that is almost always missing, and they are the part the next investigator needs most.

Validation

The investigation is only finished if someone else can re-run it and reach the same conclusion. This script asserts the evidence chain rather than your conclusion, which is the only part a machine can check.

cat > "$LABDIR/check-investigation.sh" <<'CHECK'
#!/usr/bin/env bash
# Asserts the evidence chain of the checkout investigation.
# Run while the driver is still running, or within an hour of it finishing.
set -uo pipefail

cd "$(dirname "$0")"
PROM=http://127.0.0.1:9090
LOKI=http://127.0.0.1:3100
TEMPO=http://127.0.0.1:3200
fail() { echo "FAIL: $1"; exit 1; }

# 1. Exactly one endpoint carries a non-zero error ratio.
BAD=$(curl -sfG "$PROM/api/v1/query" --data-urlencode \
  'query=sum by (endpoint) (rate(http_server_requests_total{service="checkout",status=~"5.."}[10m])) > 0' \
  | jq -r '[.data.result[].metric.endpoint] | join(",")')
[ "$BAD" = "/api/v1/payment" ] \
  || fail "expected the payment endpoint to be the only failing scope, got: $BAD"

# 2. The deployed service never failed.
REC=$(curl -sfG "$PROM/api/v1/query" --data-urlencode \
  'query=sum(rate(http_server_requests_total{service="recommendations",status=~"5.."}[10m]))' \
  | jq -r '.data.result[0].value[1] // "0"')
[ "${REC%%.*}" = "0" ] \
  || fail "the recommendations service shows a non-zero error rate: $REC"

# 3. Checkout's own error lines name an upstream, and at least one is traced.
LINE=$(curl -sfG "$LOKI/loki/api/v1/query_range" --data-urlencode \
  'query={service="checkout", level="error"} | json | trace_id != ""' \
  --data-urlencode 'since=60m' --data-urlencode 'limit=1' \
  | jq -r '.data.result[0].values[0][1] // empty')
[ -n "$LINE" ] || fail "no checkout error line carries a trace id"
echo "$LINE" | jq -e '.upstream == "payments-gateway"' >/dev/null \
  || fail "the error line does not name the payments-gateway upstream"

# 4. That trace exists and blames the dependency.
TID=$(echo "$LINE" | jq -r '.trace_id')
SPANS=$(curl -sf -H 'Accept: application/json' "$TEMPO/api/traces/$TID") \
  || fail "Tempo has no trace $TID"
echo "$SPANS" | grep -q 'payments-gateway' \
  || fail "trace $TID contains no span naming payments-gateway"
echo "$SPANS" | grep -q 'recommendations' \
  && fail "trace $TID mentions recommendations - the fixture is not the one this lab describes"

# 5. The write-up exists and records both rejections.
grep -q '^## Rejected' incident-note.md \
  || fail "incident-note.md records no rejected hypothesis"

echo "PASS: scope, disproof, log pivot, trace and write-up all check out"
CHECK

chmod +x "$LABDIR/check-investigation.sh"
"$LABDIR/check-investigation.sh"

Assertion 5 is the one that looks out of place and is not. An investigation whose rejected hypotheses were never written down will be repeated in full by whoever gets the same alert next month, and the cost of that repetition is almost always larger than the cost of the original incident.

Expected Outcome

• Five containers running, and a driver that ran for twelve minutes and exited cleanly.
• A written symptom with a magnitude, a window and a scope, derived from three PromQL queries rather than from the alert text.
• Three hypotheses written before the evidence, with two of them rejected and the contradicting evidence recorded next to each.
• One trace id lifted from a log line, and a trace whose child span names payments-gateway, carries the 502, and accounts for nearly all of the request’s duration.
• An incident note containing both rejection sections.
• check-investigation.sh printing PASS and exiting 0.

Troubleshooting

Every PromQL query returns an empty result. The exposer has nothing to serve or Prometheus cannot reach it. Check the target first: curl -s http://127.0.0.1:9090/api/v1/targets | jq -r '.data.activeTargets[] | "\(.health) \(.lastError)"', then check the file exists and is non-empty with head -3 "$LABDIR/exposition/metrics".

The metric never changes, though the file on the host does. The exposer is mounting the file rather than the directory. A file bind mount binds the inode, and the driver replaces the inode on every tick, so the container keeps serving the original bytes. Check the mount is ./exposition:/srv:ro, then docker compose up -d --force-recreate exposer.

A counter appears to reset every scrape. Two copies of the driver are running, each with its own counters. Check with pgrep -fa drive-incident.sh and kill the extra one.

emit_traced_request produces no traces. Push directly and read the status: a 400 from the OTLP endpoint is a malformed payload and the body names the field, while a connection refused means Tempo has not finished starting. docker compose logs --no-log-prefix tempo distinguishes them.

Tempo returns 404 for a trace id that a log line just supplied. Compare the two ids character by character before suspecting Tempo — a truncated id is accepted at push time and stored under a different key than the one you query. If they match exactly, wait a few seconds: the span is in the ingester and becomes retrievable by id promptly, but not instantaneously.

The Loki push logs entry too far behind. The host clock moved, or the lab was resumed after a suspend. Stop the driver, restart it, and let the twelve minutes run uninterrupted.

The driver exits early. Read driver.log. It runs with set -uo pipefail rather than -e deliberately, so one failed push does not end the fixture, but an unset variable still will.

Cleanup

kill "$(cat "$LABDIR/driver.pid")" 2>/dev/null || echo "driver already finished"
pgrep -fa drive-incident.sh || echo "no driver process remains"

$ cd ~/rb-obs-investigation && docker compose config --volumes && docker compose down -v

docker compose ps -a
docker volume ls | grep rb-obs-investigation || echo "no lab volumes remain"
cd "$HOME"
rm -rf "$HOME/rb-obs-investigation"

The images stay in the local cache. Remove them with docker image rm grafana/tempo:2.6.0 grafana/loki:3.3.0 prom/prometheus:v2.55.1 nginx:1.27-alpine if you want the disk back.

Production notes

Pre-position the three queries, not the dashboard. The queries in Task 5 are the same three every service-level investigation starts with: error ratio by scope, latency quantile, request rate. Put them in the alert’s annotation as runbook links with the labels already substituted, so the on-call engineer’s first action is reading an answer rather than composing a query at 03:00.

Write the hypotheses in the incident channel, before the evidence. It costs thirty seconds and it changes the investigation: a written hypothesis can be disproved by a colleague, an unwritten one just quietly shifts to fit whatever turns up. It is also the only reliable defence against the recency herring, because the deploy that everyone remembers gets written down as a candidate rather than assumed as a conclusion.

Make the dependency observable from your side. The evidence that decided this incident was checkout’s own view of the gateway — an upstream field on its error lines and a client span for the call. Neither requires the other team to do anything. A service that records the identity, status and duration of every dependency call can attribute its own failures without waiting for anyone, and that attribution is what turns a thirty-minute investigation into a five-minute one.

Alert on the dependency, not only on the symptom. The alert that fired here said checkout was erroring. An alert on the payment gateway’s error ratio, from checkout’s client instrumentation, would have named the cause in its own text. That is the follow-up action this incident should generate, and it belongs in the note while the detail is fresh.

Keep the change log and your own action log side by side. During an incident, the system’s changes and the responders’ changes interleave, and a post-mortem that cannot tell them apart cannot say what fixed anything. Every mitigation you apply is a change with a timestamp; record it as one.

What You Learned

• A symptom with a scope has already eliminated most of the system. Three PromQL queries narrowed this to one endpoint, one status class and an unchanged request rate before any log line was read.
• Time proximity is the weakest evidence there is. The deploy landed thirty seconds before the errors and had nothing to do with them. The disproof was positive and specific: the deployed service never failed, was named in no error line, and appeared in no span of the failing trace.
• A spike in logs during an incident is usually the incident. The volume rose with the error rate rather than before it, which is the signature of a symptom of a symptom and the reason chasing it costs so much time.
• The three signals have a cost gradient, and it dictates the order. Metrics quantify, logs identify, traces confirm the mechanism. Reversing that order turns an investigation into an anecdote about one request.
• The rejections are the part of the write-up with the longest shelf life. The cause is fixed and forgotten; the reason nobody should revert the recommendations deploy next time is what saves the next investigator forty minutes.