Command Palette

Search for a command to run...

Hectal
Case 2.1·Logs at ScaleSEV3

“Log storage grew 40 GB overnight and every Loki query now times out. Nobody changed the logging config.”

case name: One log line, 40 GB a day

Service
loki · shoplite-api
Impact
Log search unusable for ~3 hours; storage bill spike
Detected by
Engineers complaining that Explore queries time out
Time to resolve
3 h

Skills you'll use on this case

log volume per streambytes_over_time / rate in LogQLlog levels in productiondropping at the collector

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":"log-flood"}'
── lab output ──
{"active":["log-flood"]}
Each /products request now writes 100 extra 'cache probe' lines at INFO level: ~1,400 lines/s.

01 The investigation

  1. 09:05

    REPORT

    'Loki is broken, even a 1-hour search times out'

    Loki is fine. It's being asked to scan fifty times more data than yesterday.

  2. 09:12

    QUERY

    Which stream is producing the bytes?

    bytes_over_time measures log volume per stream. Summed by container, it gives the logging bill per service.

    LogQL· Loki
    sort_desc(sum by (container) (bytes_over_time({container=~".+"}[1h])))
    result
    {container="shoplite"}    1.41 GB
    {container="payments"}    6.9 MB
    {container="alloy"}       1.2 MB
    {container="prometheus"}  0.4 MB
  3. 09:15

    QUERY

    Lines per second — and what they say

    rate() over a log query gives lines per second. Grouping by the parsed msg field shows that one constant message is almost all of it, which is exactly why constant messages (Case 0.3) are so useful.

    LogQL· Loki
    topk(3, sum by (msg) (rate({container="shoplite"} | json [5m])))
    result
    {msg="cache probe"}         1402.3
    {msg="request completed"}     20.1
    {msg="checkout started"}       6.0
    shoplite log lines / slines/s
    0.00824164800:0009:15
  4. 09:20

    FINDING

    A debugging line from yesterday's cache investigation shipped at INFO

    Debug output at INFO is the most common source of log floods: it's fine for the one request you're investigating, and ruinous across every request, forever.

  5. 12:10

    RESOLVED

    Line dropped at the collector immediately; code fix shipped later

Root cause

A per-iteration debug message was logged at INFO inside a hot path, multiplying ShopLite's log volume by ~50. Nothing capped or alerted on log volume, so it ran overnight until queries became too slow to use.

02 The concepts behind it

Log volume is a cost and a performance problem

Every line is paid for three times: shipping it, storing it (compressed, but still bytes), and scanning it at query time. Loki scans content, so a query over a stream with 50× more lines is roughly 50× slower. Volume grows with TRAFFIC, which means a line that's fine in dev scales with every user in production.

Levels are a production contract

ERROR: something failed and someone may need to act. WARN: unexpected but handled. INFO: one line per meaningful event (request completed, order placed), and never inside loops. DEBUG/TRACE: developer detail, off in production by default and switchable at runtime for a single service when needed. pino, logback, and Python's logging all support a runtime level; ShopLite reads LOG_LEVEL.

Drop, sample, or aggregate at the collector

A collector (Alloy, Vector, Fluent Bit, the OTel Collector) sits between apps and storage and can DROP known-useless lines, SAMPLE high-volume but low-value ones (keep 1 in 100 health-check logs), or turn them into metrics. It's the fastest lever in an incident, because it needs no app deploy, and a good long-term guardrail.

03 The fix

  1. 01Stop the flood at the collector — no deploy needed

    Insert a loki.process stage between the Docker source and the writer. stage.json extracts msg; stage.drop discards lines whose msg matches. Restart Alloy, and the lines-per-second graph drops within a minute.

    obs-lab/alloy/config.alloyadd to filehcl
    loki.source.docker "containers" {
      host          = "unix:///var/run/docker.sock"
      targets       = discovery.docker.containers.targets
      relabel_rules = discovery.relabel.containers.rules
      forward_to    = [loki.process.drop_noise.receiver]   // was: loki.write.local.receiver
    }
    
    loki.process "drop_noise" {
      stage.json {
        expressions = { msg = "msg" }
      }
      stage.drop {
        source = "msg"
        value  = "cache probe"
        drop_counter_reason = "debug_noise"
      }
      forward_to = [loki.write.local.receiver]
    }
    terminal
    $ docker compose restart alloy
    ── expected output ──
    ✔ Container obs-lab-alloy-1 Started
  2. 02Fix the code: DEBUG, not INFO

    In server.js, change req.log.info({ i }, "cache probe") to req.log.debug(...). With the default LOG_LEVEL=info, pino doesn't even serialise it. Then switch off the scenario.

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

04 Make sure it never surprises you again

  1. 01Alert on log volume per service

    Grafana alerting can evaluate LogQL directly. Create an alert rule on this query with a threshold around 3× normal (ShopLite normally writes ~30 lines/s). Loki's own per-tenant limits (ingestion_rate_mb, per_stream_rate_limit) are the hard backstop.

    LogQL· Loki
    sum by (container) (rate({container=~".+"}[5m])) > 100

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

What share of ShopLite's log BYTES in the last hour came from the cache probe message?

02

Without the Alloy drop rule, how could you keep only 1% of cache probe lines instead of dropping them all?

06 Interview questions from this case

01

Log volume doubled overnight. How do you find the cause, and what do you do immediately?

02

What belongs at INFO level in a production service?

0/4 · 0%