Lab: Ship Structured Logs

Objective

By the end of this lab you will have taken a log stream in three different shapes and made it answer the question an on-call engineer actually asks: give me every line, from every service, for this one request.

Along the way you will separate the defects that a query-time parser can repair from the one it cannot. Field names, missing structure and awkward formats can all be worked around at query time, badly and repeatedly. The event timestamp cannot. Once a line is stored under the wrong time, no query fixes it, and the incident timeline you build from it is wrong in a way nothing on the page admits to.

Architecture

One host, three containers, and two log files that a single generator writes in deliberately inconsistent shapes.

  +---------------------------+
  | app (alpine + shell loop) |
  |                           |
  |  /var/log/app/            |
  |    checkout.log  --------------+  4 of 5 lines: JSON, RFC3339 ts
  |                           |    |  1 of 5 lines: legacy English
  |    payments.log  --------------+  JSON, Unix-seconds ts,
  +---------------------------+    |  correlation field named req_id
                                   |
                                   v  tails both files
                        +----------------------+
                        | alloy                |
                        |  loki.source.file x2 |
                        |  loki.process        |  <-- the whole lab
                        |  loki.write          |
                        |  :12345              |
                        +----------+-----------+
                                   | push
                                   v
                        +----------------------+
                        | loki 3.3 single      |
                        |  tsdb + filesystem   |
                        |  :3100               |
                        +----------------------+

There is no Grafana in this lab. Every observation is a curl against the Loki HTTP API, so that what you are reading is Loki’s answer rather than a panel’s interpretation of it.

Requirements

• A Linux host with Docker Engine 28.x and Docker Compose v2.
• curl and jq on the host.
• Free TCP ports 3100 and 12345.
• About 1 GiB of free disk. The generator writes a few MiB per hour; the images are the bulk of it.
• 90 minutes, including two waits of about two minutes each while a changed pipeline produces enough new lines to measure.
• Nothing outside the lab directory and the Compose project is modified.

Scenario

At 03:12 an on-call engineer needs every log line belonging to the checkout request that returned HTTP 500 for one customer. Three services were involved. The engineer opens the log store, writes the query, and gets back part of the story: some lines from checkout, none from payments, and a set of timestamps that puts the payment authorisation after the failure it supposedly caused.

None of that is a Loki problem. The checkout service still has an old code path that logs English sentences. The payments service ships JSON, but calls the correlation field req_id and writes its timestamp in Unix seconds. The pipeline that ships all of it was configured to tail files and nothing else. Every one of those decisions was reasonable in isolation, and together they cost forty minutes in the middle of an incident.

You are going to reproduce that stream, and then fix it one stage at a time, measuring what each stage bought.

Tasks

Task 1: Write the generator and read its output

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

gen-logs.sh produces the three shapes from the scenario. Read the comments: every awkward thing in this file is something a real estate has, and the lab depends on each one.

#!/bin/sh
# Log generator for the structured-logging lab. Three shapes on purpose:
#
#   checkout.log   4 of 5 lines: JSON, RFC3339 timestamp, field request_id
#                  1 of 5 lines: the English format the old code path still
#                                writes, with the same data embedded in prose
#   payments.log   every line:   JSON, but the timestamp is Unix seconds and
#                                the correlation field is called req_id
#
# Every 25th request is written as if the service had buffered it: the event
# time is 20 minutes in the past, while the line reaches the file now.
set -eu

CHECKOUT=/var/log/app/checkout.log
PAYMENTS=/var/log/app/payments.log
RATE=${RATE:-5}
BACKDATE_SECONDS=1200

mkdir -p /var/log/app

i=0
while :; do
  n=0
  while [ "$n" -lt "$RATE" ]; do
    i=$((i + 1))
    n=$((n + 1))

    now=$(date -u +%s)
    iso=$(date -u +%Y-%m-%dT%H:%M:%SZ)
    rid="req-${now}-${i}"

    case $((i % 20)) in
      0)   level=error; status=500 ;;
      1|2) level=warn;  status=200 ;;
      *)   level=info;  status=200 ;;
    esac

    # The buffered batch. Only the payments side carries the delay, which is
    # enough to make the timeline wrong for the whole request.
    if [ $((i % 25)) -eq 0 ]; then
      event_epoch=$((now - BACKDATE_SECONDS))
    else
      event_epoch=$now
    fi

    if [ $((i % 5)) -eq 0 ]; then
      printf '%s checkout[1]: handled request %s for user u-%d, status %d in %dms\n' \
        "$iso" "$rid" "$(( (i % 400) + 1 ))" "$status" "$(( (i % 90) + 10 ))" \
        >> "$CHECKOUT"
    else
      printf '{"ts":"%s","level":"%s","service":"checkout","request_id":"%s","status":%d,"duration_ms":%d,"msg":"checkout handled"}\n' \
        "$iso" "$level" "$rid" "$status" "$(( (i % 90) + 10 ))" \
        >> "$CHECKOUT"
    fi

    printf '{"ts":%s,"level":"%s","service":"payments","req_id":"%s","amount_cents":%d,"msg":"payment authorised"}\n' \
      "$event_epoch" "$level" "$rid" "$(( (i % 9000) + 100 ))" \
      >> "$PAYMENTS"
  done
  sleep 1
done

chmod +x gen-logs.sh

Five requests per second is deliberately small. Nothing in this lab is about volume; every measurement is a shape, and a shape is visible at any rate.

Task 2: Ship the logs with a pipeline that does nothing

loki-config.yaml — single-binary Loki on the filesystem backend, with the TSDB index and schema v13:

auth_enabled: false

server:
  http_listen_port: 3100
  grpc_listen_port: 9096
  log_level: info

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: true
  reject_old_samples_max_age: 168h
  ingestion_rate_mb: 8
  ingestion_burst_size_mb: 16

config.alloy — version one. Two sources, one writer, no processing at all. This is the pipeline from the scenario, and it is a completely reasonable place for a team to have stopped:

local.file_match "checkout" {
  path_targets = [{
    __path__ = "/var/log/app/checkout.log",
    job      = "application",
    service  = "checkout",
    env      = "lab",
  }]
}

local.file_match "payments" {
  path_targets = [{
    __path__ = "/var/log/app/payments.log",
    job      = "application",
    service  = "payments",
    env      = "lab",
  }]
}

loki.source.file "checkout" {
  targets    = local.file_match.checkout.targets
  forward_to = [loki.write.local.receiver]
}

loki.source.file "payments" {
  targets    = local.file_match.payments.targets
  forward_to = [loki.write.local.receiver]
}

loki.write "local" {
  endpoint {
    url = "http://loki:3100/loki/api/v1/push"
  }
}

service is a static label on the target, not something parsed out of the line. That is the right place for it: a pipeline that reads the service name out of the payload can be lied to by the payload.

compose.yaml:

name: rb-obs-structured

services:
  app:
    image: alpine:3.20
    container_name: rb-str-app
    command: ['/bin/sh', '/gen-logs.sh']
    environment:
      RATE: '5'
    volumes:
      - ./gen-logs.sh:/gen-logs.sh:ro
      - applogs:/var/log/app

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

  alloy:
    image: grafana/alloy:latest
    container_name: rb-str-alloy
    command:
      - 'run'
      - '--server.http.listen-addr=0.0.0.0:12345'
      - '--storage.path=/var/lib/alloy/data'
      - '/etc/alloy/config.alloy'
    volumes:
      - ./config.alloy:/etc/alloy/config.alloy:ro
      - applogs:/var/log/app:ro
      - alloy-data:/var/lib/alloy/data
    ports:
      - '12345:12345'
    depends_on:
      - loki

volumes:
  applogs:
  loki-data:
  alloy-data:

Alloy is the one image here that is not pinned, matching the rest of this course. If you are running this long after the verified date, pin it to whatever docker image inspect reports and write that version in your notes — the Alloy configuration language does change between releases.

$ docker compose up -d

sleep 30
curl -sf http://localhost:3100/ready && echo LOKI-READY
curl -sf http://localhost:12345/-/ready && echo ALLOY-READY
docker compose exec app tail -n 3 /var/log/app/checkout.log
docker compose exec app tail -n 2 /var/log/app/payments.log

Read those five lines before you go on. Two of the three shapes are in front of you, and the third — the English line — appears every fifth line, so run the tail again if you did not catch one.

Task 3: Ask the incident question with what you have

Every Loki API call needs a time window. Re-run these two lines whenever you take a new measurement:

START=$(date -u -d '-15 min' +%Y-%m-%dT%H:%M:%SZ)
END=$(date -u +%Y-%m-%dT%H:%M:%SZ)
echo "window $START .. $END"

Measurement one — the label set. Ask Loki what streams it holds:

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

{"env":"lab","filename":"/var/log/app/checkout.log","job":"application","service":"checkout"}
{"env":"lab","filename":"/var/log/app/payments.log","job":"application","service":"payments"}

Two streams. level is in every JSON line and in none of the labels, so “show me the errors” is a full scan of the line bodies rather than an index lookup.

Measurement two — how much of the stream parses. LogQL sets a synthetic __error__ field on any line a parser could not read, which makes the mixed-format problem countable:

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

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

The ratio should be close to one in five, which is the English code path. To see what the parser objected to, drop the aggregation and look at the error field on a few lines:

curl -sG http://localhost:3100/loki/api/v1/query_range \
  --data-urlencode 'query={service="checkout"} | json | __error__ != ""' \
  --data-urlencode "start=$START" --data-urlencode "end=$END" \
  --data-urlencode 'limit=3' \
| jq -r '.data.result[].stream.__error__' | sort -u

JSONParserErr on every one of them. This number is the single most useful metric a log platform can publish about itself during a format migration: it goes to zero when the last legacy code path is gone, and until then it tells you exactly how much of the stream your dashboards cannot see.

Measurement three — follow one request. Take a real request id out of an error line:

RID=$(curl -sG http://localhost:3100/loki/api/v1/query_range \
  --data-urlencode 'query={service="checkout"} | json | level = "error"' \
  --data-urlencode "start=$START" --data-urlencode "end=$END" \
  --data-urlencode 'limit=1' \
  | jq -r '.data.result[0].values[0][1] | fromjson | .request_id')
echo "$RID"

Now ask both services about it, which is the query from the scenario:

curl -sG http://localhost:3100/loki/api/v1/query_range \
  --data-urlencode "query={service=~\"checkout|payments\"} | json | request_id = \"$RID\"" \
  --data-urlencode "start=$START" --data-urlencode "end=$END" \
| jq -r '.data.result[] | .stream.service'

Only checkout comes back. The payments line for that request exists, is in Loki, and is invisible to this query, because in that service the field is called req_id. Nothing failed. Nothing was logged. The query returned 200 and a shorter story than the truth.

Task 4: The one thing a query cannot fix

Compare Loki’s timestamp for a payments line against the timestamp inside the line body. The first is the index key Loki sorted the line under; the second is when the event actually happened:

$ curl -sG http://localhost:3100/loki/api/v1/query_range --data-urlencode 'query={service="payments"}' --data-urlencode "start=$START" --data-urlencode "end=$END" --data-urlencode 'limit=200' | jq -r '.data.result[].values[] | ((((.[0][0:10]) | tonumber) - (.[1] | fromjson | .ts)) | tostring)' | sort -n | uniq -c

    192 0
    8 1200

Two populations. Most lines have a delta of zero: they were written and ingested in the same second. One line in twenty-five is 1,200 seconds — twenty minutes — adrift, and it is adrift in the direction that matters, with Loki filing it later than it happened. Loki is not wrong: with no timestamp stage in the pipeline, the ingest time is the only time it was given. The event time was sitting in the payload the whole way and nobody read it.

Fix it in the pipeline. Add a loki.process component and route both sources through it. This is config.alloy, version two:

loki.source.file "checkout" {
  targets    = local.file_match.checkout.targets
  forward_to = [loki.process.app.receiver]
}

loki.source.file "payments" {
  targets    = local.file_match.payments.targets
  forward_to = [loki.process.app.receiver]
}

loki.process "app" {
  forward_to = [loki.write.local.receiver]

  // Project the fields the later stages need. Extraction on its own
  // changes nothing that Loki stores; it fills a per-entry map that the
  // stages below read.
  stage.json {
    expressions = {
      ts         = "ts",
      level      = "level",
      request_id = "request_id",
    }
  }

  // checkout writes RFC3339, payments writes Unix seconds. One stage
  // handles both, because the fallback list is tried in order.
  stage.timestamp {
    source           = "ts"
    format           = "RFC3339"
    fallback_formats = ["Unix"]
  }
}

Leave the two local.file_match blocks and the loki.write block exactly as they were. Reload:

docker compose restart alloy
sleep 90

Alloy keeps its file positions in the alloy-data volume, so it resumes where it stopped rather than re-reading the files. Everything already in Loki keeps the timestamps it was stored with — this fix applies to new lines only, which is the first thing worth knowing about it.

Take a fresh window and run the same comparison:

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

curl -sG http://localhost:3100/loki/api/v1/query_range \
  --data-urlencode 'query={service="payments"}' \
  --data-urlencode "start=$START" --data-urlencode "end=$END" \
  --data-urlencode 'limit=50' \
| jq -r '.data.result[].values[] | ((((.[0][0:10]) | tonumber) - (.[1] | fromjson | .ts)) | tostring)' \
| sort -n | uniq -c

One population now, not two: every line in the window has a delta of zero. That single number is the proof. The 1,200-second population did not disappear — it is being filed twenty minutes in the past, where the events happened, which is why a query about the last five minutes no longer returns it.

Confirm the backdated lines were accepted rather than refused, because “moved” and “dropped” look identical from a five-minute window:

curl -sG http://localhost:3100/loki/api/v1/query \
  --data-urlencode 'query=sum(count_over_time({service="payments"}[30m]))' \
  | jq -r '.data.result[0].value[1]'

docker compose logs --since=3m alloy | tail -5

The count keeps climbing between runs and the agent log is quiet. A push Loki had refused would show up in both places at once — a count that stalls, and an error from the writer.

Task 5: Bridge the renamed field, then close it at the source

The payments service calls it req_id. During an incident you do not get to deploy a fix first, so bridge it in the query. The JSON parser accepts explicit assignments, so you can name the field whatever your query expects:

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

RID=$(curl -sG http://localhost:3100/loki/api/v1/query_range \
  --data-urlencode 'query={service="checkout"} | json | level = "error"' \
  --data-urlencode "start=$START" --data-urlencode "end=$END" \
  --data-urlencode 'limit=1' \
  | jq -r '.data.result[0].values[0][1] | fromjson | .request_id')

curl -sG http://localhost:3100/loki/api/v1/query_range \
  --data-urlencode "query={service=\"payments\"} | json request_id=\"req_id\" | request_id = \"$RID\"" \
  --data-urlencode "start=$START" --data-urlencode "end=$END" \
| jq -r '.data.result[].values[][1]'

There is the payment line for that request. | json request_id="req_id" extracts one named field under a different name; it is the log equivalent of an alias in a view, and it is exactly as durable as one — it lives in whoever’s query history, and the next engineer will not have it.

Close it at the source. Emit both names for one release window, which is what a field rename costs when anything downstream depends on it. Edit the payments printf at the bottom of gen-logs.sh so that it carries both fields with the same value:

    printf '{"ts":%s,"level":"%s","service":"payments","req_id":"%s","request_id":"%s","amount_cents":%d,"msg":"payment authorised"}\n' \
      "$event_epoch" "$level" "$rid" "$rid" "$(( (i % 9000) + 100 ))" \
      >> "$PAYMENTS"

Restart the generator and wait for new traffic:

docker compose restart app
sleep 60

Now the query from Task 3 — the one that returned half the story — against a window that only contains new lines:

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

RID=$(curl -sG http://localhost:3100/loki/api/v1/query_range \
  --data-urlencode 'query={service="checkout"} | json | __error__ = "" | request_id != ""' \
  --data-urlencode "start=$START" --data-urlencode "end=$END" \
  --data-urlencode 'limit=1' \
  | jq -r '.data.result[0].values[0][1] | fromjson | .request_id')

curl -sG http://localhost:3100/loki/api/v1/query_range \
  --data-urlencode "query={service=~\"checkout|payments\"} | json | request_id = \"$RID\"" \
  --data-urlencode "start=$START" --data-urlencode "end=$END" \
| jq -r '.data.result[] | .stream.service'

Both services answer. Note what did not happen: no reindex, no backfill, no migration job. Lines written before the change still need the alias, which is the entire argument for shipping both field names for a release window rather than swapping one for the other.

Task 6: Promote the labels that earn their place

level is in every JSON line and filtered on by nearly every panel, and it has a handful of possible values. That is the profile of a stream label. Add the promotion as the last stage of loki.process, after the extraction that produces it:

  // Runs after stage.json, because a labels stage can only promote what
  // an earlier stage has already extracted.
  stage.labels {
    values = { level = "" }
  }

An empty value on the right means “use the extracted field of the same name”. Reload and wait for new streams:

docker compose restart alloy
sleep 90

START=$(date -u -d '-1 min' +%Y-%m-%dT%H:%M:%SZ)
END=$(date -u +%Y-%m-%dT%H:%M:%SZ)
curl -sG http://localhost:3100/loki/api/v1/series \
  --data-urlencode 'match[]={job="application"}' \
  --data-urlencode "start=$START" --data-urlencode "end=$END" \
| jq -c '.data[] | {service, level, filename}'

The label set grew from two streams to at most seven: three levels for checkout, three for payments, and one more for the English lines, which have no level to promote and so keep the label-free stream. Seven is bounded by the number of services multiplied by the number of severities. It does not grow when traffic grows, which is the only property that matters.

request_id was extracted three tasks ago and has still not been promoted. Do not promote it. It is unique per request, so each value would open its own stream, and the label-cardinality lab in this course walks the resulting incident and its repair end to end. The point here is narrower: a field can be extracted, queryable and useful without ever touching the index.

Now the query the whole lab was for, with level as a label:

$ curl -sG http://localhost:3100/loki/api/v1/query_range --data-urlencode 'query={service=~"checkout|payments", level="error"} | json | __error__ = ""' --data-urlencode "start=$START" --data-urlencode "end=$END" --data-urlencode 'limit=10' | jq -r '.data.result[] | "\(.stream.service) \(.stream.level)"'

checkout error
payments error

The selector now does the level filtering in the index, and the parser only runs on the lines that survived it. That ordering — cheap index filter first, parser second — is the difference between a query that returns during an incident and one that times out.

Validation

Each of these is checkable, and each fails visibly if a step was skipped.

1. curl -sf http://localhost:3100/ready and curl -sf http://localhost:12345/-/ready both succeed.
2. The __error__ != "" count over five minutes is roughly a fifth of the __error__ = "" count, and the error value is JSONParserErr.
3. Before the timestamp stage, backdated payments lines show a delta of about 1,200 seconds between Loki’s timestamp and the payload’s ts. After it, the delta is zero for every line in the window.
4. After the timestamp stage, the delta histogram over a fresh five-minute window has a single population at zero, and the thirty-minute line count keeps climbing between runs — the backdated lines moved, they were not refused.
5. | json | request_id = "..." across both services returns one service before the source fix and two after it.
6. | json request_id="req_id" returns the payments line for a request id even on lines written before the source fix.
7. The /series response contains at most seven label sets, and no label named request_id appears in any of them.
8. Reverting stage.timestamp and restarting Alloy makes measurement 3 fail again. Put it back.

Expected Outcome

rb-obs-structured/
├── compose.yaml
├── config.alloy
├── gen-logs.sh
└── loki-config.yaml

A pipeline with three stages, each of which you can justify: stage.json because the fields have to be extracted before anything can use them, stage.timestamp because the event time cannot be recovered later, and stage.labels because exactly one extracted field earns a place in the index. A generator that emits both correlation field names, as a service does during a rename. And one query that answers the 03:12 question in full.

Troubleshooting

No streams at all in /series. Check that Alloy is tailing the files: docker compose logs alloy | tail -20. The most common cause is the applogs volume not being mounted into both containers, so Alloy is looking at an empty directory.

Alloy will not start after an edit. Run docker compose logs alloy | tail -20. A River syntax error names the line. A forward_to that points at a component you renamed is the usual one — the reference is loki.process.app.receiver, matching the block’s label.

__error__ counts are zero for both queries. The metric query needs a range that overlaps live data. Re-run the START/END helpers; a window older than the container is empty and returns nothing rather than zero.

The timestamp comparison shows a delta for every line, not one in twenty-five. The stage.timestamp did not parse, so everything fell back to ingest time. Confirm stage.json extracts ts, and that the format and fallback_formats cover both shapes — checkout writes RFC3339 strings, payments writes bare integers.

Backdated lines never appear in the wider window. Loki refused them as too old for the stream. Check docker compose logs alloy for push rejections, and confirm you did not lower max_chunk_age or reject_old_samples_max_age in the Loki config.

jq: error: Cannot index string. You ran a payload-parsing jq against the English lines, which are not JSON. Scope the query to {service="payments"} or filter with | json | __error__ = "" first.

The sed in Task 5 changed nothing. Shell quoting varies by editor. Edit the payments printf by hand instead; the only requirement is that req_id and request_id carry the same value.

Cleanup

The lab created three containers, three named volumes, one Compose network and one directory.

Step 1. Stop the stack and remove the volumes. The log volume is one of them, so everything the generator wrote goes with it:

$ cd "$HOME/rb-obs-structured" && docker compose down -v

Step 2. Confirm nothing is left and the ports are free:

docker compose ps
ss -ltnp 2>/dev/null | grep -E ':(3100|12345)\b' || echo 'ports free'

$ mkdir -p "$HOME/obs-lab-deliverables/structured-logs" && cp -a "$HOME/rb-obs-structured/." "$HOME/obs-lab-deliverables/structured-logs/" && rm -rf "$HOME/rb-obs-structured"

Step 3. The images stay in the local cache. Leave them if you are going on to another logging lab; otherwise:

docker image rm grafana/loki:3.3.0 grafana/alloy:latest alpine:3.20

Production notes

Mapping this exercise onto a real estate:

• Parse at the source, not in the pipeline. Everything you did here was recovery work. The application knows the field names and the event time; a structured logger in the application makes stage.json a formality instead of a repair.
• __error__ belongs on a dashboard. A parse-failure rate per service is the migration burndown chart, and it is the only signal that tells you a new deploy started emitting something the pipeline cannot read.
• A field rename is a breaking change. Ship both names for a release window, migrate the queries and dashboards, then drop the old one. Anything faster leaves an alias in someone’s query history as the only documentation.
• Timestamp stages need a fallback list and an owner. When the parse fails, the pipeline silently falls back to ingest time, which is the failure you cannot see in the data. Watch the agent’s own pipeline metrics on :12345/metrics — curl -s localhost:12345/metrics | grep loki_process shows what your build exposes — and alert on the failure counter rather than trusting the configuration.
• Every promotion to a label is permanent for the lifetime of the chunk. Removing a label from the pipeline stops new streams; it does not merge the old ones. Get the label set right before the volume arrives.
• Clock discipline is upstream of all of this. A perfectly parsed timestamp from a host whose clock is ten minutes off is a well-formatted lie. NTP is part of the logging pipeline, whatever the org chart says.

What You Learned

• A query-time parser repairs shape, not time. Field names, missing structure and awkward formats all yielded to LogQL. The one defect that did not was the one that changed where the line lived.
• The mixed-format problem is countable. | json | __error__ != "" turned “some of our logs are legacy” into a number per minute that goes to zero when the migration finishes.
• A partial answer is the expensive failure. The renamed field produced no error, no warning and no missing-data indicator — just a shorter story, delivered with full confidence.
• Stage order is a data dependency. stage.labels can only promote what stage.json already extracted, and a labels stage placed first promotes empty strings without complaining.
• Extraction and indexing are separate decisions. request_id was extracted, queryable and useful for the whole lab without ever becoming a label.
• Pipeline changes apply forward only. Every fix in this lab improved new lines and left the old ones exactly as they were stored, which is why the cost of a logging defect is proportional to how long it ran.