Detecting an Incident From a Log Stream Before an Alert Fires

A metric alert is not slow because the system is slow. It is slow because of a chain of deliberate delays, each individually reasonable, that add up to several minutes before anybody’s phone rings. Log patterns can shortcut some of those delays and none of the others, and it is worth knowing which.

Where the minutes go

Take the standard path: an application increments a counter, a time-series database scrapes it, a rule evaluates, an alert fires, a router groups it, and a human is notified. Every hop has a configuration parameter that is a delay.

• Aggregation interval. A counter is only visible after the interval it accumulates in ends. A rate computed over a one-minute interval cannot reflect a failure that started 10 seconds ago.
• Scrape interval. The collector polls every 15, 30 or 60 seconds. The expected wait for the next scrape is half the interval; the worst case is the whole interval.
• Rate window. A rule expressed over a five-minute rate reaches its full value only five minutes after the change starts. Halfway through, the computed rate is roughly half the true new rate, which is why a rule that would fire at the true rate does not fire immediately even with no other delay.
• The for duration. Alerting rules require the condition to hold continuously for a stated period before the alert becomes firing — this is what suppresses flapping, and it is a straight addition to detection time.
• Notification grouping. Alertmanager’s documented defaults are group_wait 30s before sending the first notification for a new group, group_interval 5m before sending an update, and repeat_interval 4h — see the Prometheus Alertmanager configuration reference. The 30 seconds exists so a burst of related alerts arrives as one page, which is worth having and is nonetheless 30 seconds.

A worked lead time

Assume a database connection pool exhausts at T+0. Take a conventional configuration: 15-second scrape, a rule on a 5-minute error rate, for: 5m, and default grouping. Assume the error rate jumps from near zero to 40% instantly, and the rule threshold is 5%.

metric path
  T+0       pool exhausts, errors start
  T+0..60   1-minute counter interval must complete            +60 s
  T+~68     next 15 s scrape picks it up            (avg +8 s)  +8 s
  T+~106    5-minute rate crosses 5%: the window holds 5 min of
            history, so the computed rate reaches 5% after
            0.05/0.40 x 300 s = 37.5 s of elevated errors      +38 s
  T+406     "for: 5m" satisfied                                +300 s
  T+436     group_wait elapses, page sent                      +30 s
  ----------------------------------------------------------------
  total detection-to-page                                  ~436 s = 7 m 16 s

log-pattern path
  T+0       pool exhausts, first "connection timeout" line written
  T+~2      line shipped and parsed                             +2 s
  T+2       template T_timeout count in the current 10 s bucket
            jumps from a baseline of 0.1/bucket to 60/bucket
  T+10      bucket closes, threshold (mu + 4 sigma) cleared     +8 s
  T+30      persistence rule: 3 consecutive buckets over        +20 s
  T+60      group_wait equivalent                              +30 s
  ----------------------------------------------------------------
  total                                                     ~60 s

lead time = 436 - 60 = 376 s = 6 m 16 s

Those inputs are assumptions, stated so you can substitute your own. What is not an assumption is the structure of the answer: almost all of the six minutes comes from two parameters, the for duration and the rate window, and both of them exist to suppress false positives. The log-pattern detector is not faster because logs are magic. It is faster because it uses a 10-second bucket and a three-bucket persistence rule instead of a five-minute window and a five-minute hold, and it can afford to because the signal — a template that normally never appears — has a much higher signal-to-noise ratio than a percentage of a rate.

Which log signals lead

Not every log signal is early. The ones that reliably lead a user-visible metric are the ones written at the point of first internal degradation, before retries and fallbacks have finished hiding it.

• A template that has never been seen before. The single highest-value detector in this whole area, and the cheapest: an unseen template id is a code path that has not executed since the template store was built. Most of them are benign and it still ranks well, because the volume is naturally tiny.
• Retry and backoff lines. A retry is by definition evidence of a failure that has not yet reached the user. Retry volume leads user-visible error rate by exactly the retry budget.
• Queue depth and pool saturation messages. These lead latency, which leads timeouts, which lead errors. Three hops of lead time if you instrument the first.
• Silence. A source that logs every few seconds and stops is a signal, and it is the one that beats every metric-based approach, because a dead process does not export metrics either — but an absent metric is often indistinguishable from a scrape failure, while an expected-heartbeat rule is explicit.

What the lead time costs you

A detector six minutes earlier and with a worse false-positive rate is not obviously better, and the honest comparison has to price both sides. The relevant arithmetic: if a detector fires on n series with a per-bucket false-alarm probability p over b buckets per day, expected daily false pages are n·p·b, and a 10-second bucket gives 8,640 buckets per day rather than 1,440. Everything else equal, moving from one-minute to ten-second buckets multiplies false alarms by six. That has to be paid for somewhere — with a higher threshold, with a persistence requirement, or with aggregation across series, all of which are worked through in burst detection.

The usual resolution is to not treat the two detectors as competing. Route the fast log-pattern detector to a low-severity channel that a person looks at rather than a page that wakes them, and keep the slow metric alert as the paging authority. The lead time then buys investigation head start rather than a faster page, and the false-positive cost is a glance instead of an interrupted night.

Building the leading detector

1. Run template extraction over the stream and persist the template store, so “unseen template” means unseen across deploys rather than unseen since the process started.
2. Emit a per-template count per 10-second bucket, keyed by service. This is a tumbling aggregation and is cheap; the cardinality is templates × services, not lines.
3. Maintain an EWMA mean and variance per (template, service). Alert on μ + 4σ with a three-bucket persistence requirement, and separately on any template whose lifetime count was zero before this bucket.
4. Deduplicate against the metric alerting path so the same incident does not arrive twice with different names — duplicate alert detection is the same fingerprinting problem.
5. Record, for each real incident, the timestamp of the first log line that in hindsight indicated it and the timestamp of the page. The difference is your actual lead time, and it is the only number that justifies keeping the detector.