Alerting that people do not learn to ignore

The monitoring channel received 340 alerts in November. Four of them corresponded to something a user would have noticed. The other 336 taught everyone in the channel that alerts are noise, which is why the fourth one — a genuine outage at eleven at night — was seen forty minutes after it fired.

The symptom

$ grep -c '[ALERT]' /var/log/alerts/2017-11.log
340

$ grep '[ALERT]' /var/log/alerts/2017-11.log 
    | sed 's/.*] //' | cut -d: -f1 | sort | uniq -c | sort -rn | head
    112 CPU load high on web02
     71 Disk usage above 80% on db01
     44 Memory usage above 90% on worker01
     38 Nginx 5xx rate above 0
     22 Redis connected_clients above 100
     19 MySQL slow queries detected
      4 Checkout error rate above 5%

The last line is the only one anybody should have been woken for. The line above it fired nineteen times for slow queries on a reporting replica where slow queries are the entire workload. The 80% disk alert on db01 had been firing since March; the disk was at 81% and growing by a percent a quarter.

Why it happens

Every one of those alerts was added by a competent person in response to a real incident, and each was individually reasonable. The pattern connecting them is that they alert on causes — CPU, memory, disk, connection counts — and there are unlimited causes, most of which are compatible with a perfectly healthy system.

High CPU on a web server is what a busy web server looks like. Ninety percent memory on a worker is a JVM or a PHP process doing its job. These become interesting only when they cause something, and the something is what should be alerted on.

The fix

Alert on what a user would notice

The test for whether something deserves to wake a person is whether a customer could tell. Everything that fails that test goes on a dashboard, where it is available during an investigation and silent the rest of the time.

# pages a human — a user is affected right now
groups:
  - name: symptoms
    rules:
      - alert: CheckoutFailing
        expr: |
          sum(rate(http_requests_total{route="checkout",status=~"5.."}[5m]))
          /
          sum(rate(http_requests_total{route="checkout"}[5m])) > 0.02
        for: 5m
        labels:   { severity: page }
        annotations:
          summary: "{{ $value | humanizePercentage }} of checkouts failing"
          runbook: "https://wiki.internal/runbooks/checkout-5xx"

      - alert: SiteSlow
        expr: histogram_quantile(0.95,
                sum(rate(http_duration_seconds_bucket[5m])) by (le)) > 2
        for: 10m
        labels:   { severity: page }

Four symptom alerts replaced twenty-two cause alerts: checkout failing, the site slow, the queue not draining, and the site not responding at all. Everything else moved to a dashboard or to a ticket.

Duration, because an instant threshold is always wrong

The for clause is the single highest-value line in any alert rule and the one most often left out. A threshold evaluated instantaneously fires on every transient spike, and transient spikes are constant.

# fires on a single scrape. this is the 112 CPU alerts.
- alert: CPUHigh
  expr: node_load5 > 8

# fires when it has been true for ten minutes, which is a different claim
- alert: SaturatedForTenMinutes
  expr: node_load5 > 8
  for: 10m

# and for a slowly changing resource, alert on the trend rather than
# the level — this fires four days out, not eighteen months early
- alert: DiskWillFill
  expr: predict_linear(node_filesystem_avail_bytes[6h], 4 * 24 * 3600) < 0
  for: 1h
  labels: { severity: ticket }

The disk prediction is the replacement for the 80% threshold that fired seventy-one times. Eighty percent on a disk growing a percent a quarter is not a problem; eighty percent on a disk that gained fifteen points overnight is, and only the second one fires.

Grouping and inhibition, so one incident is one message

A database going away produces an alert from every service that talks to it. That is one incident and should be one notification, or the channel fills during exactly the minutes when reading it matters most.

route:
  group_by: ['alertname', 'service']
  group_wait: 30s          # collect related alerts before sending
  group_interval: 5m       # then batch updates
  repeat_interval: 4h      # do not re-page every five minutes

  routes:
    - match: { severity: page }
      receiver: oncall
    - match: { severity: ticket }
      receiver: tracker

# and suppress the consequences of a known cause
inhibit_rules:
  - source_match: { alertname: DatabaseDown }
    target_match: { severity: page }
    equal: ['datacenter']

The repeat_interval matters more than it looks. An alert that re-notifies every five minutes for an incident somebody is already working on is training that person to mute the channel, and the mute will outlast the incident.

The runbook link, without which an alert is a puzzle

An alert that says a number crossed a threshold hands the receiver a research project. At three in the morning, to somebody who did not write the rule, three sentences are worth more than any amount of precision in the expression.

annotations:
  summary: "{{ $value | humanizePercentage }} of checkouts failing"
  description: |
    Users cannot complete purchases. Check, in order:
      1. the payment circuit breaker  — redis-cli get cb:payments:open
      2. the gateway status page      — https://status.provider.example
      3. recent deploys               — https://ci.internal/deploys
    Safe first action: none. Do not restart php-fpm; it loses nothing
    and hides the evidence.
  dashboard: "https://grafana.internal/d/checkout"
  runbook: "https://wiki.internal/runbooks/checkout-5xx"

Writing what not to do is as valuable as the checklist. Restarting things is the universal first instinct and it destroys the state that would have explained the incident.

Verifying it worked

# december, same command
$ grep -c '[ALERT]' /var/log/alerts/2017-12.log
11

$ grep '[ALERT]' /var/log/alerts/2017-12.log | sed 's/.*] //' 
    | cut -d: -f1 | sort | uniq -c | sort -rn
      5 CheckoutFailing
      3 QueueNotDraining
      2 SiteSlow
      1 DiskWillFill

# and the check that matters: the four november incidents, replayed
$ promtool test rules alerts_test.yml
SUCCESS

Eleven alerts instead of 340 is only good news if the real ones still fire, which is what the rule test asserts — the four November incidents replayed against the new rules, all four firing, within the same minute they did originally. Without that, a quiet channel is indistinguishable from a broken one.

The other measurement worth taking is time to acknowledge. It went from thirty-one minutes to four, and that is the number the exercise was actually about; the alert count is a proxy.

What this costs

Alerting on symptoms means the alert says what is broken and not why, and somebody still has to find the cause. That is the trade being made deliberately: the cause alerts were fast at pointing at a machine and useless at telling anyone whether it mattered. Dashboards keep the causes available for exactly the moment they are needed, and the runbook is what bridges the gap.

There is also a real risk of missing something. A cause that never produced a symptom in the twelve months of history reviewed can still produce one next March, and the pruning removed the alert that would have caught it early. The mitigation is that every incident ends with a question about whether an alert should have fired and did not — which makes the rule set something maintained continuously rather than a cleanup done once and then left to accumulate again.