Command Palette

Search for a command to run...

Hectal
Case 0.3·Seeing Anything at AllSEV2

“Checkout errors are at 20%. The metric can't tell us what the error actually is.”

case name: Metrics say 'failing' — logs say why

Service
shoplite-api · /checkout
Impact
1 in 5 checkouts returned HTTP 500 for 18 minutes
Detected by
The error-ratio query from Case 0.1 (still run by hand — this case adds the alert)
Time to resolve
18 min

Skills you'll use on this case

structured JSON logsLogQL stream selectors| json parsingcount_over_timelabels vs fieldsfirst alert rule

00 It starts

Reproduce this incident in your lab, then work the case alongside the timeline below. Try each query yourself before reading its result.

terminal
$ curl -s -X POST localhost:8080/admin/chaos -H 'content-type: application/json' -d '{"scenario":"errors"}'
── lab output ──
{"active":["errors"]}

01 The investigation

  1. 16:02

    QUERY

    The error ratio for /checkout jumps to 0.2

    The metric knows THAT requests fail and WHERE (route, status). It can't know WHY. Nobody puts error messages in metric labels (see the concepts).

    /checkout error ratio5xx / all
    0.000.120.2415:4516:10
  2. 16:04

    QUERY

    Select ShopLite's log stream and keep only error-level lines

    A LogQL query starts with a STREAM SELECTOR in braces, which chooses streams by their labels (here container, set by Alloy). Then comes a PIPELINE: | json parses each line's JSON into fields, and | level = 50 filters on pino's numeric level (50 = error). Nested fields are flattened with underscores, so err.message becomes err_message.

    LogQL· Loki
    {container="shoplite"} | json | level = 50 | line_format "{{.msg}}: {{.err_message}}"
    result
    2026-09-26 16:04:11  checkout failed: could not obtain lock on row in relation "stock"
    2026-09-26 16:04:11  checkout failed: could not obtain lock on row in relation "stock"
    2026-09-26 16:04:10  checkout failed: could not obtain lock on row in relation "stock"
    ...
  3. 16:06

    QUERY

    Is it ONE error or several? Count them by message

    count_over_time(...[5m]) turns log lines into a metric: lines per stream per window. sum by (err_message) groups them by the parsed field. One message accounts for all the errors, so it's a single failure mode.

    LogQL· Loki
    sum by (err_message) (
      count_over_time({container="shoplite"} | json | level = 50 [5m])
    )
    result
    {err_message="could not obtain lock on row in relation \"stock\""}  362
  4. 16:09

    HYPOTHESIS

    Postgres error 55P03 is lock_not_available: something is holding locks on stock

    The parsed err_code field says 55P03. In a real system the next step is pg_stat_activity / pg_locks to find the blocking session. In Case 0.1 it was an admin script holding a transaction open.

    LogQL· Loki
    {container="shoplite"} | json | level = 50 | line_format "{{.err_code}} {{.err_type}}"
    result
    55P03 Error
    55P03 Error
    ...
  5. 16:20

    RESOLVED

    Blocking session terminated; the errors stop

    This time: 18 minutes from first signal to fix, instead of 47 minutes and a customer tweet.

Root cause

Same failure class as Case 0.1: row-lock contention on stock. The difference is the investigation. Structured JSON logs, queryable in Loki, turned '1,183 lines containing the word error' into 'one specific Postgres error, 362 times in 5 minutes, all on checkout'.

02 The concepts behind it

Structured logging

console.log("checkout failed for " + id + ": " + err) produces a sentence that humans can read and machines can't reliably parse. log.error({ err, productId }, "checkout failed") produces ONE JSON OBJECT per line, with a fixed message and separate fields. Every field is then filterable, groupable, and countable, with no regex archaeology.

Keep messages constant ("checkout failed") and put variable data in fields. Constant messages can be grouped (sum by (msg)); interpolated ones produce thousands of unique strings.

Labels vs fields in Loki: the most important Loki decision

Loki indexes only LABELS (like container), never the log content. Each unique label combination is a separate STREAM. That's why Loki is cheap, and why high-cardinality labels break it: making user_id or err_message a label would create millions of tiny streams and overwhelm the index.

So labels should be few and low-cardinality: service, container, environment, level at most. Everything else stays in the log line and is extracted at QUERY time with | json or | logfmt. Filtering after a good stream selector is fast; the selector is what keeps queries cheap.

Log queries vs metric queries in LogQL

A LOG query returns lines: {selector} | filters | parsers. A METRIC query wraps a log query in a range function like count_over_time, rate, bytes_over_time, or with | unwrap field, avg_over_time, then aggregates it like PromQL. That's how you graph and even alert on things that only exist in logs.

03 The fix

  1. 01Resolve and switch the scenario off

    Real fixes for lock contention: keep transactions short, set lock_timeout so waiters fail fast instead of piling up, and use SELECT ... FOR UPDATE SKIP LOCKED for queue-like access patterns.

    terminal
    $ curl -s -X POST localhost:8080/admin/chaos -H 'content-type: application/json' -d '{"scenario":"errors","enabled":false}'
    ── expected output ──
    {"active":[]}

04 Make sure it never surprises you again

  1. 01The first alert rule: page on user-facing error ratio

    Case 0.1 needed a customer; this case needed someone running a query. An alert rule runs the query every 15 seconds. for: 2m avoids paging on a single bad scrape. Labels route it, and annotations explain it. Chapter 4 replaces this with SLO burn-rate alerts; for now, a sensible threshold is a big step up from nothing.

    obs-lab/prometheus/alerts.ymlwhole fileyaml
    groups:
      - name: shoplite
        rules:
          - alert: CheckoutErrorRatioHigh
            expr: |
              sum(rate(http_request_duration_seconds_count{job="shoplite", route="/checkout", status=~"5.."}[5m]))
              /
              sum(rate(http_request_duration_seconds_count{job="shoplite", route="/checkout"}[5m]))
              > 0.05
            for: 2m
            labels:
              severity: critical
              service: shoplite
            annotations:
              summary: "{{ $value | humanizePercentage }} of checkouts are failing"
              runbook: "Check error logs: {container=\"shoplite\"} | json | level = 50"
    terminal
    $ curl -s -X POST localhost:9090/-/reload && curl -s localhost:9090/api/v1/rules | jq -r '.data.groups[].rules[] | .name + " " + .health'
    ── expected output ──
    CheckoutErrorRatioHigh ok
  2. 02Test the alert by replaying the incident

    An alert you've never seen fire is an alert you can't trust. Switch errors on, watch the rule go pending (condition true, for not yet satisfied) and then firing at http://localhost:9090/alerts. Chapter 4 routes it to an actual notification channel. Switch it off again afterwards.

    terminal
    $ curl -s -X POST localhost:8080/admin/chaos -H 'content-type: application/json' -d '{"scenario":"errors"}'
    sleep 180 && curl -s localhost:9090/api/v1/alerts | jq -r '.data.alerts[] | .labels.alertname + " " + .state'
    ── expected output ──
    CheckoutErrorRatioHigh firing

05 Your turn: write the query

Run each one against your lab before revealing the answer. Share your own version in the comments; there's usually more than one correct query.

01

Write a LogQL query that shows only log lines from payments that took longer than 1 second, using pino-http's responseTime field (milliseconds).

02

Graph ShopLite's error log lines per second, split by HTTP route. (pino-http's completion log includes req_url after json parsing.)

03

A teammate proposes adding user_id as a Loki label 'so we can find a user's logs faster'. What do you tell them, and how should they query instead?

06 Interview questions from this case

01

Why use structured (JSON) logging?

02

How does Loki differ from Elasticsearch-style log storage, and what does that mean for labels?

03

An alert has for: 2m. What does that do, and why use it?

0/4 · 0%