Command Palette

Search for a command to run...

Hectal
Case 2.3·Logs at ScaleSEV2

“Checkout errors started 'sometime this afternoon'. There were three deploys. Which one?”

case name: Was it the deploy? Diffing before and after

Service
shoplite-api
Impact
~20% of checkouts failing; the team was about to roll back the wrong release
Detected by
CheckoutErrorRatioHigh (from Case 0.3)
Time to resolve
22 min

Skills you'll use on this case

deploy markers from metrics and logsoffset in PromQL and LogQLunless to find what's newchange correlation

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
$ docker compose restart shoplite && sleep 60 && curl -s -X POST localhost:8080/admin/chaos -H 'content-type: application/json' -d '{"scenario":"errors"}'
── lab output ──
{"active":["errors"]}
A restart (the 'deploy'), then a new failure mode, just like a bad release.

01 The investigation

  1. 15:48

    ALERT

    CheckoutErrorRatioHigh firing

    Three deploys went out today: 11:20, 14:02, 15:31. Rolling back all three is slow and risky; rolling back the wrong one wastes the whole incident.

  2. 15:50

    QUERY

    When exactly did errors start — and when did processes restart?

    Plot the error ratio and the process start times together. A restart that lines up with the step change in errors is the prime suspect. In Grafana, show restarts as annotations (Case 1.1).

    PromQL· Prometheus
    timestamp(changes(process_start_time_seconds{job="shoplite"}[1m]) > 0)
    result
    {instance="shoplite:8080", job="shoplite"}  1758899460   → 15:31:00
  3. 15:53

    QUERY

    Did the NEW version start logging errors the old one never logged?

    offset shifts a query back in time. unless keeps only series on the left that have NO match on the right, so this returns error messages that exist now but didn't exist an hour ago: errors introduced since then.

    LogQL· Loki
    sum by (err_message) (count_over_time({container="shoplite"} | json | level = 50 [15m]))
    unless
    sum by (err_message) (count_over_time({container="shoplite"} | json | level = 50 [15m] offset 1h))
    result
    {err_message="could not obtain lock on row in relation \"stock\""}  274
  4. 15:56

    QUERY

    Compare the same metric now vs one hour ago

    offset in PromQL gives the same shape of answer: a before/after comparison without eyeballing graphs.

    PromQL· Prometheus
    sum(rate(http_request_duration_seconds_count{job="shoplite", route="/checkout", status=~"5.."}[10m]))
    -
    sum(rate(http_request_duration_seconds_count{job="shoplite", route="/checkout", status=~"5.."}[10m] offset 1h))
    result
    {}  1.19   (errors/s higher than an hour ago)
  5. 16:10

    RESOLVED

    The 15:31 release is rolled back; new error message disappears

Root cause

The 15:31 release introduced a new code path that took row locks on stock in a different order, causing lock timeouts. Correlating the error onset with process restarts, and diffing error messages before and after, identified the release in minutes instead of rolling back blindly.

02 The concepts behind it

Most incidents are caused by change

Deploys, config changes, feature flags, schema migrations, and infrastructure changes cause the large majority of production incidents. So 'what changed around the time it started?' is the first question in any investigation, and your observability should make CHANGES as visible as symptoms: deploy annotations, a version label, a changelog feed.

offset and set operators

offset 1h evaluates a selector as if it were one hour ago. It works in PromQL and LogQL alike, and makes 'now vs then' a single query. Set operators work on the label sets of vectors: and (intersection), or (union), unless (left minus right). Together they answer questions like 'which routes have errors now but didn't yesterday?'.

Expose the version

The strongest signal is a version label. Export a build_info gauge (value 1, with labels version, commit) and log the version on startup. Then sum by (version) (...) splits every metric by release, which makes canary comparisons and 'is it only the new version?' trivial.

03 The fix

  1. 01Roll back — here, switch the failure off

    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. 01A build_info metric

    Gauge value is always 1; the information is in the labels. Join it onto other metrics with * on (instance) group_left(version) shoplite_build_info to split anything by version.

    obs-lab/shoplite/server.jsadd to filejs
    const buildInfo = new client.Gauge({
      name: "shoplite_build_info",
      help: "Build information",
      labelNames: ["version", "commit"],
    });
    buildInfo.set({ version: process.env.APP_VERSION ?? "dev", commit: process.env.GIT_SHA ?? "unknown" }, 1);
    log.info({ version: process.env.APP_VERSION, commit: process.env.GIT_SHA }, "starting");
  2. 02Error ratio split by version

    During a canary or rolling deploy, this shows immediately whether the new version is worse than the old one.

    PromQL· Prometheus
    sum by (version) (
      rate(http_request_duration_seconds_count{job="shoplite", status=~"5.."}[5m])
      * on (instance) group_left(version) shoplite_build_info
    )
    /
    sum by (version) (
      rate(http_request_duration_seconds_count{job="shoplite"}[5m])
      * on (instance) group_left(version) shoplite_build_info
    )

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 PromQL query returning routes that have 5xx errors now but had none 1 day ago.

02

Find the timestamps of ShopLite's startup log lines in the last 6 hours, to use as deploy annotations.

06 Interview questions from this case

01

An incident starts and several changes went out recently. How do you find the culprit?

02

What's a build_info metric and why is it useful?

0/4 · 0%