“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
| json parsingcount_over_timelabels vs fieldsfirst alert rule00 It starts
Reproduce this incident in your lab, then work the case alongside the timeline below. Try each query yourself before reading its result.
01 The investigation
- 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 - 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:| jsonparses each line's JSON into fields, and| level = 50filters on pino's numeric level (50 = error). Nested fields are flattened with underscores, soerr.messagebecomeserr_message.LogQL· Loki{container="shoplite"} | json | level = 50 | line_format "{{.msg}}: {{.err_message}}"result2026-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" ... - 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· Lokisum 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 - 16:09
HYPOTHESIS
Postgres error 55P03 is
lock_not_available: something is holding locks onstockThe parsed
err_codefield says55P03. In a real system the next step ispg_stat_activity/pg_locksto 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}}"result55P03 Error 55P03 Error ... - 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
01Resolve and switch the scenario off
Real fixes for lock contention: keep transactions short, set
lock_timeoutso waiters fail fast instead of piling up, and useSELECT ... FOR UPDATE SKIP LOCKEDfor 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
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: 2mavoids 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 ok02Test the alert by replaying the incident
An alert you've never seen fire is an alert you can't trust. Switch
errorson, watch the rule gopending(condition true,fornot yet satisfied) and thenfiringathttp://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.
Write a LogQL query that shows only log lines from payments that took longer than 1 second, using pino-http's responseTime field (milliseconds).
Graph ShopLite's error log lines per second, split by HTTP route. (pino-http's completion log includes req_url after json parsing.)
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
Why use structured (JSON) logging?
How does Loki differ from Elasticsearch-style log storage, and what does that mean for labels?
An alert has for: 2m. What does that do, and why use it?