Skip to main content
RunBook Academy

← All labs in Observability

Lab · intermediate · ~90 min

Lab: Query Logs with LogQL

B · Nested virtualisationC · Simulation

Objectives

  • Load a deterministic corpus with a printed manifest of counts, so every query in the lab has a checkable answer
  • Read the stats block Loki returns with every query and use it to compare two ways of asking the same question
  • Show that only the stream selector and the time range change how many bytes a query reads
  • Parse JSON, logfmt and free-form lines in one tenant, and count the lines that fail to parse instead of hiding them
  • Reproduce the two failures that make a correct-looking query return nothing: a parsed field in the selector, and a filter placed before its parser

Prerequisites

  • Docker Engine 28.x and Docker Compose v2 on a disposable Linux host
  • curl, jq and GNU date on the host
  • Lesson: LogQL Stream Selectors (Part XXXVII) — the selector is the only part of the query that touches the index
  • Lesson: LogQL Line Filters (Part XXXVII) — filters run over whatever the selector opened
  • Lesson: LogQL Parsers (Part XXXVII) — a parsed field is not a stream label

Objective

By the end of this lab you will have answered four questions about a failing service using LogQL alone, against a corpus whose exact contents you generated and therefore already know, and you will have recorded what each answer cost in bytes read, lines processed and wall-clock time.

The knowing-the-answer part is the design. Almost every LogQL tutorial ends with a query that returns something, which is indistinguishable from a query that returns the wrong thing. Here the generator prints a manifest — how many error lines it wrote, how many of them were on which endpoint, how many lines it deliberately truncated — and every query you write is checked against it. A query that disagrees with the manifest is wrong, and you will find out inside the lab rather than inside an incident.

Architecture

One container and one shell. There is no agent and no application: the corpus is generated on the host and pushed straight to Loki’s HTTP API, because the subject of this lab is the read path and a deterministic corpus makes every measurement repeatable.

  make-corpus.sh                 corpus.tsv          manifest.env
  (deterministic, no random)  -> ~7,200 lines   +    the counts every
                                  3 services         answer is checked
                                  3 log formats      against
        |
        | jq builds one push body per stream
        v
  POST /loki/api/v1/push
        |
        v
  +--------------------------+
  |  loki 3.3 single binary  |     labels: service, env, level
  |  tsdb index + filesystem |     everything else lives in the line
  |  :3100                   |
  +--------------------------+
        ^
        | GET /loki/api/v1/query_range   -> lines + stats
        | GET /loki/api/v1/query         -> one number + stats
        | GET /loki/api/v1/series        -> what the index holds
        |
     curl + jq

Three services write three different shapes on purpose: checkout emits JSON, gateway emits logfmt, and legacy-billing emits free-form text with a few key=value fragments in it. A real estate always looks like this, and the parser you reach for is decided by the shape rather than by preference.

Requirements

  • A disposable Linux host with Docker Engine 28.x and the Compose v2 plugin. docker compose version must work. The lab binds one loopback port (3100), creates one named volume and one directory under your home.
  • curl and jq on the host. Every measurement in this lab reads a specific field out of a JSON response. Reaching for grep on that JSON is how people convince themselves a wrong query is right.
  • GNU date. The generator uses date -u -d "@1700000000" to turn epoch seconds into timestamps; BSD date on macOS does not accept that form.
  • bash. The generator uses arithmetic for loops and (( )), which dash does not provide.
  • About 500 MB of free disk and 1 GB of RAM headroom. The corpus is roughly 1.5 MB of log lines; nothing here is large.
  • No out-of-band access requirement. Nothing touches the host network configuration, the firewall, or any service outside the compose project.

Scenario

About half an hour ago the checkout service began returning 502 on the payment path. It stopped on its own five minutes later. Nobody was paged, because the alert threshold is a ten-minute window and the incident did not last that long. A support ticket has just arrived: a customer says their payment failed, and they have quoted the request id from the error page.

Everything you need is in the log store and nothing is in a dashboard. You have three services, three log formats, one hour of history, and a request id from the customer. Four questions have to be answered before the ticket can be closed:

  1. When did checkout start failing, when did it stop, and how many requests were affected?
  2. Which endpoint failed, and did anything else in checkout fail at the same time?
  3. Did the gateway see the same failures, and what did it think the upstream was?
  4. What happened to the customer’s specific request, in all three services?

Tasks

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

LABDIR="$HOME/rb-obs-logql"
mkdir -p "$LABDIR/queries"
cd "$LABDIR"

# Nothing may already own the port this lab publishes.
if ss -ltn 'sport = :3100' | grep -q LISTEN; then
  echo "PORT 3100 IS ALREADY IN USE - stop that service or move this lab"
else
  echo "port 3100 free"
fi

Everything below lives in $LABDIR, at the path named in the first line of its block. The queries/ directory matters more than it looks: by the end of the lab each answer is a named file, which is what makes the answers reviewable, diffable and re-runnable. A LogQL expression that only ever existed in a Grafana text box is an answer nobody else can check.

Task 2: Write the corpus generator

This is the only long script in the lab, and it is worth reading rather than pasting blind: everything you assert later is an assertion about what this loop wrote.

cat > "$LABDIR/make-corpus.sh" <<'GEN'
#!/usr/bin/env bash
# Deterministic corpus for the LogQL lab. No randomness: two runs produce the
# same corpus shifted forward in time. Writes:
#   corpus.tsv    service <tab> level <tab> timestamp_ns <tab> line
#   manifest.env  the counts every later assertion is checked against
set -euo pipefail

OUT=${1:-corpus.tsv}
MANIFEST=${2:-manifest.env}

TICKS=1800              # one tick every STEP seconds
STEP=2                  # 1800 x 2s = one hour of history
INCIDENT_FROM=900       # tick at which the payment upstream starts failing
INCIDENT_TO=1050        # tick at which it recovers
NOW=$(date -u +%s)
BASE=$(( NOW - TICKS * STEP - 120 ))    # the corpus ends two minutes ago

checkout_lines=0; gateway_lines=0; legacy_lines=0
checkout_errors=0; gateway_502=0; legacy_declined=0; malformed=0

: > "$OUT"

for (( i=1; i<=TICKS; i++ )); do
  t=$(( BASE + i * STEP ))
  ns=$(( t * 1000000000 ))
  iso=$(date -u -d "@$t" +%Y-%m-%dT%H:%M:%SZ)
  rid=$(printf 'req-%06d' "$i")
  uid=$(printf 'u-%04d' $(( i % 400 + 1 )))

  case $(( i % 3 )) in
    0) endpoint=/api/v1/orders ;;
    1) endpoint=/api/v1/cart ;;
    2) endpoint=/api/v1/payment ;;
  esac

  # checkout, JSON. One ordinary request per tick.
  printf 'checkout\tinfo\t%s\t{"ts":"%s","level":"info","service":"checkout","endpoint":"%s","status":200,"latency_ms":%d,"request_id":"%s","user_id":"%s","msg":"request completed"}\n' \
    "$ns" "$iso" "$endpoint" "$(( 40 + i % 50 ))" "$rid" "$uid" >> "$OUT"
  checkout_lines=$(( checkout_lines + 1 ))

  # checkout, the payment path. Healthy, except during the incident window.
  if (( i >= INCIDENT_FROM && i <= INCIDENT_TO )); then
    printf 'checkout\terror\t%s\t{"ts":"%s","level":"error","service":"checkout","endpoint":"/api/v1/payment","status":502,"latency_ms":%d,"request_id":"%s","user_id":"%s","msg":"payment upstream returned 502"}\n' \
      "$ns" "$iso" "$(( 3000 + i % 700 ))" "$rid" "$uid" >> "$OUT"
    checkout_errors=$(( checkout_errors + 1 ))
  else
    printf 'checkout\tinfo\t%s\t{"ts":"%s","level":"info","service":"checkout","endpoint":"/api/v1/payment","status":200,"latency_ms":%d,"request_id":"%s","user_id":"%s","msg":"payment authorised"}\n' \
      "$ns" "$iso" "$(( 90 + i % 60 ))" "$rid" "$uid" >> "$OUT"
  fi
  checkout_lines=$(( checkout_lines + 1 ))

  # checkout, a truncated line every 200 ticks. Real pipelines emit these when
  # a writer is killed mid-line or a log driver splits an oversized entry.
  if (( i % 200 == 0 )); then
    printf 'checkout\tinfo\t%s\t{"ts":"%s","level":"info","service":"checkout","endpoint":"%s","status":200,"latency_ms\n' \
      "$ns" "$iso" "$endpoint" >> "$OUT"
    checkout_lines=$(( checkout_lines + 1 ))
    malformed=$(( malformed + 1 ))
  fi

  # gateway, logfmt.
  if (( i >= INCIDENT_FROM && i <= INCIDENT_TO )); then
    printf 'gateway\terror\t%s\tts=%s level=error method=POST path=/api/v1/payment status=502 upstream=payments duration_ms=%d request_id=%s msg="upstream returned 502"\n' \
      "$ns" "$iso" "$(( 3000 + i % 700 ))" "$rid" >> "$OUT"
    gateway_502=$(( gateway_502 + 1 ))
  else
    printf 'gateway\tinfo\t%s\tts=%s level=info method=POST path=%s status=200 upstream=checkout duration_ms=%d request_id=%s msg="proxied"\n' \
      "$ns" "$iso" "$endpoint" "$(( 20 + i % 40 ))" "$rid" >> "$OUT"
  fi
  gateway_lines=$(( gateway_lines + 1 ))

  # legacy-billing, free form with a few key=value fragments.
  if (( i >= INCIDENT_FROM && i <= INCIDENT_TO && i % 2 == 0 )); then
    printf 'legacy-billing\terror\t%s\t%s ERROR [billing] user=%s action=charge result=declined took=%dms rid=%s\n' \
      "$ns" "$iso" "$uid" "$(( 800 + i % 300 ))" "$rid" >> "$OUT"
    legacy_declined=$(( legacy_declined + 1 ))
  else
    printf 'legacy-billing\tinfo\t%s\t%s INFO [billing] user=%s action=charge result=ok took=%dms rid=%s\n' \
      "$ns" "$iso" "$uid" "$(( 60 + i % 90 ))" "$rid" >> "$OUT"
  fi
  legacy_lines=$(( legacy_lines + 1 ))
done

cat > "$MANIFEST" <<EOF
CORPUS_START=$(date -u -d "@$(( BASE + STEP ))" +%Y-%m-%dT%H:%M:%SZ)
CORPUS_END=$(date -u -d "@$(( BASE + TICKS * STEP ))" +%Y-%m-%dT%H:%M:%SZ)
INCIDENT_START=$(date -u -d "@$(( BASE + INCIDENT_FROM * STEP ))" +%Y-%m-%dT%H:%M:%SZ)
INCIDENT_END=$(date -u -d "@$(( BASE + INCIDENT_TO * STEP ))" +%Y-%m-%dT%H:%M:%SZ)
INCIDENT_RID=req-001000
CHECKOUT_LINES=$checkout_lines
GATEWAY_LINES=$gateway_lines
LEGACY_LINES=$legacy_lines
CHECKOUT_ERRORS=$checkout_errors
GATEWAY_502=$gateway_502
LEGACY_DECLINED=$legacy_declined
MALFORMED=$malformed
EOF

echo "wrote $(wc -l < "$OUT") lines to $OUT"
cat "$MANIFEST"
GEN

chmod +x "$LABDIR/make-corpus.sh"
"$LABDIR/make-corpus.sh"

Read the manifest it printed. The arithmetic is simple enough to check by hand: the incident runs from tick 900 to tick 1050 inclusive, so CHECKOUT_ERRORS and GATEWAY_502 are both 151; LEGACY_DECLINED is 76, because billing only declines on even ticks; MALFORMED is 9, one truncated line every 200 ticks. If your manifest disagrees with that, stop and find out why before pushing anything — the manifest is the ground truth for the rest of the lab.

INCIDENT_RID is the customer’s request id from the ticket. It is tick 1000, which lands inside the incident window and on an even tick, so that one id appears in all three services.

Task 3: Write the Loki configuration and the compose file

loki-config.yaml — a single-binary Loki on the filesystem backend, with the TSDB index and schema v13 that Loki 3.x defaults to:

# 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:
  # This lab pushes an hour of history in three requests, which is not a shape
  # any real client produces. These four values exist so that burst gets
  # through; they are not a recommendation. In production, size the rate from
  # the largest client's measured peak plus headroom, and alert on
  # loki_discarded_samples_total rather than raising the limit until it stops
  # firing.
  ingestion_rate_mb: 32
  ingestion_burst_size_mb: 64
  per_stream_rate_limit: 64MB
  per_stream_burst_size: 128MB

  # The corpus is timestamped within the last hour, so the default age rule is
  # left on. If you leave the stack running overnight and re-push an old
  # corpus.tsv, this is the limit that will reject it.
  reject_old_samples: true
  reject_old_samples_max_age: 168h

  max_entries_limit_per_query: 10000

ingester:
  chunk_idle_period: 2m
  max_chunk_age: 10m

analytics:
  reporting_enabled: false

compose.yaml:

# compose.yaml
name: rb-obs-logql

services:
  loki:
    image: grafana/loki:3.3.0
    container_name: rb-logql-loki
    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'

volumes:
  loki-data:
Configuration changelab host
$ cd ~/rb-obs-logql && docker compose up -d
cd "$LABDIR"
for i in $(seq 1 30); do
  curl -sf http://127.0.0.1:3100/ready >/dev/null && break
  sleep 2
done
curl -s http://127.0.0.1:3100/ready

The readiness endpoint is component-aware: it answers only once the ingester has finished WAL replay. A 503 here for the first few seconds is the endpoint working, not the endpoint failing.

Task 4: Push the corpus and confirm what the index holds

The push API takes a stream label set and a list of nanosecond-timestamped lines. Build the body with jq rather than by hand — the log lines are themselves JSON, and hand-escaping JSON inside JSON is where this goes wrong:

cd "$LABDIR"

jq -Rn '
  [inputs | split("\t") | {service: .[0], level: .[1], ts: .[2], line: .[3]}]
  | group_by(.service + "�" + .level)
  | {streams: [ .[] | {stream: {service: .[0].service, env: "prod", level: .[0].level},
                       values: [ .[] | [.ts, .line] ]} ]}
' corpus.tsv > push.json

jq '.streams | length' push.json
jq -r '.streams[] | "\(.stream.service)/\(.stream.level): \(.values | length) lines"' push.json

That is the whole label design, visible in one command: three services times two or three levels is a handful of streams, and every other field — endpoint, status, latency, request id, user id — stays inside the line. Push it:

curl -sf -X POST http://127.0.0.1:3100/loki/api/v1/push \
  -H 'Content-Type: application/json' \
  --data-binary @push.json \
  -w 'push: HTTP %{http_code}\n'

A successful push returns HTTP 204 with an empty body. A 400 names the offending field in the response body; a 429 is a rate limit, and means one of the four limits_config values in Task 3 did not get applied.

Now ask the index what it received. This is the series endpoint, and it reads the index rather than the chunks:

export START=$(date -u -d '-90 min' +%Y-%m-%dT%H:%M:%SZ)
export END=$(date -u +%Y-%m-%dT%H:%M:%SZ)

curl -sG http://127.0.0.1:3100/loki/api/v1/series \
  --data-urlencode 'match[]={env="prod"}' \
  --data-urlencode "start=$START" --data-urlencode "end=$END" \
| jq -c '.data[]'

curl -sG http://127.0.0.1:3100/loki/api/v1/labels \
  --data-urlencode "start=$START" --data-urlencode "end=$END" \
| jq -r '.data[]'

Seven or eight label sets, and exactly three label names. Everything you are about to query for — a status code, an endpoint, a request id — is absent from that list, which is the point: those are line content, and LogQL has a different tool for each of them.

Task 5: The selector, and the two things it decides

Define two helpers. The first runs a log query and returns the raw response; the second pulls out the statistics Loki attaches to every response:

q() {
  curl -sG http://127.0.0.1:3100/loki/api/v1/query_range \
    --data-urlencode "query=$1" \
    --data-urlencode "start=$START" --data-urlencode "end=$END" \
    --data-urlencode "limit=${2:-100}"
}

qstats() {
  q "$1" 1 | jq '.data.stats.summary'
}

Read the shape of the stats object once, before you start reading fields out of it, so that the numbers you record are numbers Loki actually reported:

qstats '{service="checkout"}' | jq 'keys'
qstats '{service="checkout"}'

The fields this lab uses are totalBytesProcessed, totalLinesProcessed, totalEntriesReturned and execTime. If a name in your output differs, use your output — it is the authority, not this page.

Now the three selector experiments. Predict the answer to each before you run it, and write your prediction down:

# A refusal is not always JSON, so read the raw body and the status code
# rather than piping a failure into jq.
qraw() {
  curl -sG -w '\nHTTP %{http_code}\n' \
    http://127.0.0.1:3100/loki/api/v1/query_range \
    --data-urlencode "query=$1" \
    --data-urlencode "start=$START" --data-urlencode "end=$END" \
    --data-urlencode 'limit=1'
}

# 1. The empty selector.
qraw '{}'

# 2. A regex matcher that also matches the empty string.
qraw '{env=~".*"}'

# 3. A regex matcher that does not match the empty string.
qraw '{env=~".+"}' | tail -1

The first two do not run, and the message names the rule: a query needs at least one matcher that cannot match the empty string. Record the exact wording and the status code; it is what you will meet the first time someone builds a selector from a Grafana template variable that happened to be blank, and it arrives as a failed panel rather than as a slow one.

The third runs, and it is the maximum-cost query in this tenant: every stream, every chunk in the window. Compare it against a bounded selector, and then against a bounded selector plus the one other label the pipeline set:

for SEL in '{env=~".+"}' '{service="checkout"}' '{service="checkout", level="error"}'; do
  printf '%-42s ' "$SEL"
  qstats "$SEL" | jq -c '{bytes: .totalBytesProcessed, lines: .totalLinesProcessed, ms: (.execTime * 1000 | round)}'
done

Three rows, and the numbers fall monotonically. That is the entire index model made visible: each additional equality matcher removes streams from the candidate set before a single chunk is opened, so the bytes read fall with it.

Task 6: Line filters, and what they actually change

Now measure a filter rather than assume it. Same selector, same window, one extra filter:

for Q in '{service="checkout"}' \
         '{service="checkout"} |= "502"' \
         '{service="checkout"} |= "502" != "authorised"' \
         '{service="checkout"} |~ "\"status\":50[0-9]"'; do
  printf '%-52s ' "$Q"
  qstats "$Q" | jq -c '{bytes: .totalBytesProcessed, lines: .totalLinesProcessed,
                        returned: .totalEntriesReturned, ms: (.execTime * 1000 | round)}'
done

Read the four rows against the model from Task 5. totalEntriesReturned should collapse as soon as the filter is added, because that is what the filter is for. totalBytesProcessed should stay close to the unfiltered figure, because the same chunks were opened either way. The regex row should cost more CPU than the substring rows for the same result, which is the reason to reach for |= first and |~ only when you genuinely need a pattern.

If your numbers tell a different story, believe your numbers and go and find out what is different about your Loki — a chunk cache that was warm for one query and cold for another is the usual explanation, and re-running each query twice separates that out.

Now use a filter for what it is good at. Save the first real answer as a file:

cat > "$LABDIR/queries/01-when-and-how-many.logql" <<'LOGQL'
sum(count_over_time({service="checkout", level="error"}[75m]))
LOGQL

curl -sG http://127.0.0.1:3100/loki/api/v1/query \
  --data-urlencode "query=$(cat "$LABDIR/queries/01-when-and-how-many.logql")" \
  --data-urlencode "time=$END" \
| jq -r '.data.result[0].value[1]'

That number must equal CHECKOUT_ERRORS in the manifest. This is the first query in the lab with a right answer rather than a plausible one.

For the when, keep the same expression but ask for the series over time rather than a single number, and let the step do the bucketing:

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

The first and last non-zero rows are the start and end of the incident. Compare them with INCIDENT_START and INCIDENT_END from the manifest; they will agree to within the one-minute step, and understanding why only to within the step is worth thirty seconds of thought.

Task 7: Parsers, one per shape

Three services, three formats, three parsers. Start with JSON, and answer the second question — which endpoint failed:

cat > "$LABDIR/queries/02-which-endpoint.logql" <<'LOGQL'
sum by (endpoint, status) (
  count_over_time({service="checkout", level="error"} | json [75m])
)
LOGQL

curl -sG http://127.0.0.1:3100/loki/api/v1/query \
  --data-urlencode "query=$(cat "$LABDIR/queries/02-which-endpoint.logql")" \
  --data-urlencode "time=$END" \
| jq -r '.data.result[] | "\(.metric.endpoint) status=\(.metric.status) \(.value[1])"'

One row: the payment endpoint, status 502, and a count that matches the manifest. The by (endpoint, status) grouping works because | json promoted those two fields out of the line — neither is a stream label, and neither could be used in the selector.

Now logfmt, for the third question:

cat > "$LABDIR/queries/03-gateway-view.logql" <<'LOGQL'
sum by (status, upstream) (
  count_over_time({service="gateway"} | logfmt | status = "502" [75m])
)
LOGQL

curl -sG http://127.0.0.1:3100/loki/api/v1/query \
  --data-urlencode "query=$(cat "$LABDIR/queries/03-gateway-view.logql")" \
  --data-urlencode "time=$END" \
| jq -r '.data.result[] | "status=\(.metric.status) upstream=\(.metric.upstream) \(.value[1])"'

The count must equal GATEWAY_502, and the upstream label is the answer to the interesting half of the question: the gateway blamed payments, not checkout. Two services, two views of one failure, and the second one names a dependency the first one never mentions.

The legacy service is neither JSON nor logfmt, so it needs the regexp parser and named capture groups. Write the query to a file — this is also the cleanest way to get RE2 syntax past two layers of quoting:

cat > "$LABDIR/queries/04-legacy-declines.logql" <<'LOGQL'
sum by (result) (
  count_over_time(
    {service="legacy-billing"}
    | regexp "user=(?P<user>\\S+) action=(?P<action>\\S+) result=(?P<result>\\S+)"
    [75m]
  )
)
LOGQL

curl -sG http://127.0.0.1:3100/loki/api/v1/query \
  --data-urlencode "query=$(cat "$LABDIR/queries/04-legacy-declines.logql")" \
  --data-urlencode "time=$END" \
| jq -r '.data.result[] | "result=\(.metric.result) \(.value[1])"'

The declined count must equal LEGACY_DECLINED. Note the double backslashes: LogQL string literals process escapes, so \\S in the file is the two characters that LogQL hands to RE2 as \S. A single backslash there is the most common reason a regexp parser silently extracts nothing.

Finally, count what the parser could not parse. The generator truncated nine lines on purpose, and a JSON parser meets them the way it meets every real pipeline defect:

curl -sG http://127.0.0.1:3100/loki/api/v1/query \
  --data-urlencode 'query=sum(count_over_time({service="checkout"} | json | __error__ != "" [75m]))' \
  --data-urlencode "time=$END" \
| jq -r '.data.result[0].value[1]'

That count must equal MALFORMED. Two things follow from it. First, every aggregation you write over parsed fields is quietly computed over the lines that parsed — adding | __error__ = "" makes that explicit rather than accidental. Second, this number belongs on a dashboard: a parse-error count that climbs after a deploy is a pipeline regression, and it is invisible in every panel that filters errors by level.

Task 8: The two mistakes that return nothing

Both of these look right and neither returns the lines you wanted. Run each one raw, so you see whatever Loki actually says — an empty result and a refusal are different diagnoses — and then run the fixed form next to it.

Mistake one: a parsed field in the stream selector.

# The mistake: status is not a stream label, so the index has nothing to
# match. qraw is the helper from Task 5; it prints the body and the code.
qraw '{service="checkout", status="502"}' | tail -3

# The fix: parse the line, then filter on the parsed field.
q '{service="checkout"} | json | status = "502"' | jq '.data.result | length'

The first is asking the index for a label that does not exist. Whether it returns an error or an empty result, the conclusion an engineer draws under pressure is “there are no 502s”, and that conclusion is wrong. status lives in the line; only service, env and level live in the index, and you confirmed exactly that with the labels endpoint in Task 4.

Mistake two: a filter before its parser.

# The mistake: nothing has extracted status when the filter is evaluated.
qraw '{service="checkout"} | status = "502" | json' | tail -3

# The fix: the parser comes first.
q '{service="checkout"} | json | status = "502"' | jq '.data.result | length'

The pipeline runs left to right. In the first form nothing has extracted status yet when the filter is evaluated. In the second it has. The fix is never to loosen the query — the reflex to “delete the filter until something comes back” is how an unbounded query gets committed to a dashboard — it is to put the parser where the pipeline needs it.

Task 9: Follow one request across three services

The fourth question is the customer’s, and it is the one that pays for all the label discipline. Their request id is in the manifest:

cd "$LABDIR"
# shellcheck disable=SC1091
. ./manifest.env
echo "looking for $INCIDENT_RID"

for SVC in checkout gateway legacy-billing; do
  echo "--- $SVC"
  q "{service=\"$SVC\"} |= \"$INCIDENT_RID\"" 20 \
  | jq -r '.data.result[].values[][1]'
done

Three lines, one per service, one request: checkout reporting a 502 on the payment endpoint, the gateway naming payments as the upstream that returned it, and billing recording a declined charge for the same user. That is the ticket answered.

Note what made it possible. The request id is not a label — putting it in the index would have created one stream per request, which is the incident the cardinality lab in this course is entirely about — and the lookup still costs only a scan of the chunks that {service="..."} opened. A bounded label set is what keeps a full-text lookup affordable.

Save it, then assemble the deliverable table:

cat > "$LABDIR/queries/05-one-request.logql" <<'LOGQL'
{service=~"checkout|gateway|legacy-billing"} |= "req-001000"
LOGQL

for F in "$LABDIR"/queries/*.logql; do
  printf '%-34s ' "$(basename "$F")"
  qstats "$(cat "$F")" \
  | jq -c '{bytes: .totalBytesProcessed, lines: .totalLinesProcessed,
            returned: .totalEntriesReturned, ms: (.execTime * 1000 | round)}'
done

Five rows: the query, and what it cost. That table is the deliverable, and the habit behind it is the actual skill — a query whose cost nobody measured is a query nobody can defend when it lands on a dashboard that refreshes every fifteen seconds.

Validation

Everything above collapses into one script with an exit code. This is the thing you would schedule; the table is the thing you would show a colleague.

cat > "$LABDIR/check-answers.sh" <<'CHECK'
#!/usr/bin/env bash
# Asserts each LogQL answer against the corpus manifest.
# Non-zero exit = an answer drifted from the corpus that produced it.
set -euo pipefail

cd "$(dirname "$0")"
# shellcheck disable=SC1091
. ./manifest.env

LOKI=http://127.0.0.1:3100
NOW=$(date -u +%Y-%m-%dT%H:%M:%SZ)
fail() { echo "FAIL: $1"; exit 1; }

# One instant query, one number out.
count() {
  curl -sfG "$LOKI/loki/api/v1/query" \
    --data-urlencode "query=$1" --data-urlencode "time=$NOW" \
  | jq -r '.data.result[0].value[1] // "0"'
}

got=$(count 'sum(count_over_time({service="checkout", level="error"}[75m]))')
[ "$got" = "$CHECKOUT_ERRORS" ] || fail "checkout errors: got $got, manifest says $CHECKOUT_ERRORS"

got=$(count 'sum(count_over_time({service="gateway"} | logfmt | status = "502" [75m]))')
[ "$got" = "$GATEWAY_502" ] || fail "gateway 502s: got $got, manifest says $GATEWAY_502"

got=$(count 'sum(count_over_time({service="checkout"} | json | __error__ != "" [75m]))')
[ "$got" = "$MALFORMED" ] || fail "unparseable lines: got $got, manifest says $MALFORMED"

# The customer request must be visible in all three services.
for SVC in checkout gateway legacy-billing; do
  n=$(curl -sfG "$LOKI/loki/api/v1/query_range" \
        --data-urlencode "query={service=\"$SVC\"} |= \"$INCIDENT_RID\"" \
        --data-urlencode 'since=90m' | jq '[.data.result[].values[]] | length')
  [ "$n" -ge 1 ] || fail "$INCIDENT_RID is absent from $SVC"
done

# A tighter selector must read fewer bytes than a looser one over the same
# window. If the stats field is missing, say so rather than passing silently.
bytes() {
  curl -sfG "$LOKI/loki/api/v1/query_range" \
    --data-urlencode "query=$1" --data-urlencode 'since=90m' \
    --data-urlencode 'limit=1' \
  | jq -r '.data.stats.summary.totalBytesProcessed // "missing"'
}
wide=$(bytes '{service="checkout"}')
narrow=$(bytes '{service="checkout", level="error"}')
[ "$wide" != missing ] && [ "$narrow" != missing ] \
  || fail "no totalBytesProcessed in the stats block; run: qstats '{service=\"checkout\"}' | jq keys"
[ "$narrow" -lt "$wide" ] \
  || fail "the narrower selector read $narrow bytes, the wider one $wide"

echo "PASS: every answer matches the corpus that produced it"
CHECK

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

The last assertion is the one worth arguing about. The first four prove the queries are right; only the last proves the selector is doing the work, and it is the one that would catch a well-meaning edit that widened a dashboard panel’s selector while leaving its filters intact.

Expected Outcome

  • One container running, /ready returning a per-component ready state.
  • A manifest.env whose counts you can derive by hand from the generator, and a corpus in Loki that matches it.
  • Seven or eight streams and exactly three label names in the index, with status, endpoint, request id and user id all living inside the line.
  • Five saved queries under queries/, each with a recorded cost.
  • check-answers.sh printing PASS and exiting 0.
  • A stated, measured answer to “what does a line filter change” that is narrower than the one most people carry into this lab.

Troubleshooting

The push returns HTTP 400. Read the body; it names the field. Two causes dominate. A timestamp in seconds rather than nanoseconds — Loki reads it as a moment in 1970 and rejects it as too old. Or a stream label outside [a-zA-Z_][a-zA-Z0-9_]*; every label this lab creates is legal, so this points at an edited jq expression.

The push returns HTTP 429. A rate limit engaged, which means the four limits_config values in Task 3 are not in the running config. Confirm with curl -s http://127.0.0.1:3100/config | grep -A6 per_stream, and check that the bind mount path in compose.yaml matches the file you edited.

Queries return an empty result immediately after the push. Re-export START and END. The corpus ends two minutes in the past and begins an hour before that, so a window of “the last five minutes” contains none of it.

jq: error: inputs/0 is not defined. The -n flag is missing from the jq -Rn invocation. Without it, inputs is not available.

A count is off by exactly the number of lines in one tick. The corpus was regenerated between two measurements, or pushed twice. A second push of the same corpus duplicates every entry, and Loki will accept it. Run docker compose down -v && docker compose up -d, then push once.

totalBytesProcessed is identical for two different selectors. Both queries hit the results cache, or the window covered no data for either. Re-export the window, and change one character of the query to bypass the cache, then compare.

The container exits at startup. Read the log rather than restarting it: docker compose logs --no-log-prefix loki. Loki parses its configuration at startup and names the offending key. A restart loop with no log output at all is almost always a bind-mount path that does not exist on the host, which makes Docker create a directory where you meant to mount a file.

Cleanup

Data-loss risklab host
$ cd ~/rb-obs-logql && docker compose config --volumes && docker compose down -v
docker volume ls | grep rb-obs-logql || echo "volume gone"
cd "$HOME"
rm -rf "$HOME/rb-obs-logql"

The image stays in the local cache. Remove it with docker image rm grafana/loki:3.3.0 if you want the disk back.

Production notes

Audit the queries you already ship, with the same two commands. Every dashboard panel, every alert rule and every recording rule is a LogQL query somebody wrote once. Pull them out of the dashboard JSON and run each through the stats block against a production-sized window in a staging tenant. Rank by totalBytesProcessed. The top three are almost always a selector problem, and fixing a selector is a change with no runtime risk at all — it changes what a panel reads, not what the cluster stores.

Put the fields you always filter on into the index, and nothing else. The rule from the labels lessons applies directly here: a field is a label when its value set is bounded, semantic and stable — env, service, level. Anything per-request stays in the line, where a full-text filter can still find it behind a bounded selector, exactly as Task 9 did. Moving a field into a label to make a query faster is the single most expensive optimisation available.

A query with a right answer beats a query with an answer. The manifest device in this lab is not a lab trick. In production the equivalent is a synthetic line pushed on a known cadence with a known token, and a check that asserts the count. It catches a broken parser, a changed log format, a stalled agent and a silently rate-limited push — all of which otherwise present as “the panel looks quiet”, which is indistinguishable from good news.

Take the query limits seriously before someone finds them for you. max_entries_limit_per_query, max_query_length and the per-tenant query parallelism are the controls that stop one exploratory query from consuming the querier fleet that every other tenant shares. Set them from a measured baseline, and treat a rejected query as the guard working rather than as an obstacle to raise.

What You Learned

  • The selector and the time range decide the bytes; nothing else does. You measured three selectors over one window and watched the bytes fall with each matcher, then measured three filters and watched the bytes stay put. That asymmetry is the whole cost model.
  • A filter is for the result set, not for the budget. It decides what comes back and what the pipeline spends CPU on. Pairing a filter chain with a loose selector produces a tidy answer at the maximum possible price.
  • A parsed field is not a stream label, and the pipeline runs left to right. The two failures in Task 8 are the same mistake seen from two sides, and both present as an empty result rather than as an error.
  • Every parse has a failure count, and it belongs on a dashboard. Nine truncated lines were invisible to every query in this lab until __error__ != "" counted them, and an aggregation over parsed fields is always silently an aggregation over the lines that parsed.
  • Knowing the answer in advance is what makes a query checkable. The manifest turned five plausible queries into five verified ones, and the same device — a known token, a known count, an assertion — is what keeps a production log pipeline honest between incidents.

Deliverables

  • · A corpus generator and the manifest of counts it prints
  • · A cost table: query, bytes processed, lines processed, entries returned and execution time, for each of the four incident questions
  • · A queries/ directory holding every answer as a named .logql file
  • · A check script that asserts each answer against the manifest and exits non-zero when one drifts

Verification status

Last reviewed
2026-08-19
Executed end to end
not yet run on hardware

The commands and configuration here have been reviewed against the verified software versions, but nobody has run this lab start to finish on a system meeting its prerequisites. Treat the Expected Outcome as the intended result rather than an observed one, and keep the Cleanup section to hand.