3. Detect Log Pattern Shifts Preceding Incidents

Why raw log lines cannot be baselined directly

Incident onset is usually preceded by a change in the shape of log traffic, not by a single dramatic line. A service that starts emitting connection reset by peer at 40× its normal rate, or suddenly produces a template that never appeared in the previous 14 days, is telling you something before latency or error-rate dashboards move. The obstacle is that raw log lines are almost all unique: timestamps, request IDs, durations, IPs, and payload fragments vary on every line, so a frequency baseline over raw strings is meaningless. The workflow below converts lines into templates first, then baselines template frequencies, then tests for statistically significant shifts.

Stage 1 — Template mining with a stable tokenizer

Use a drain-style fixed-depth parse tree: tokenize each line, replace variable tokens with wildcards, and match against a tree keyed by token count and leading tokens. The critical engineering decision is the masking policy, because it determines what counts as "the same pattern." Mask aggressively enough to collapse noise, conservatively enough to keep distinct failure signatures apart.

import re, math, json
from collections import defaultdict, Counter

# Masking policy: order matters — specific patterns before generic ones.
MASKS = [
    (re.compile(r'\b\d{4}-\d{2}-\d{2}[T ]\d{2}:\d{2}:\d{2}(?:\.\d+)?Z?\b'), '<TS>'),
    (re.compile(r'\b[0-9a-f]{8}-[0-9a-f]{4}-[0-9a-f]{4}-[0-9a-f]{4}-[0-9a-f]{12}\b'), '<UUID>'),
    (re.compile(r'\b(?:\d{1,3}\.){3}\d{1,3}(?::\d+)?\b'), '<IP>'),
    (re.compile(r'\b(?:0x)?[0-9a-f]{16,}\b'), '<HEX>'),
    (re.compile(r'\b\d+(?:\.\d+)?(?:ms|s|us|ns|MB|GB|KB)\b'), '<DUR>'),
    (re.compile(r'\b\d+\b'), '<NUM>'),
]

def mask(line):
    for rx, tag in MASKS:
        line = rx.sub(tag, line)
    return line

class Drain:
    """Minimal fixed-depth drain: depth=4, similarity threshold=0.5."""
    def __init__(self, depth=4, sim_thresh=0.5):
        self.depth, self.sim = depth, sim_thresh
        self.clusters = []          # list of dicts: {tokens, count, id}

    def _sim(self, a, b):
        n = min(len(a), len(b))
        if n == 0: return 0.0
        return sum(1 for i in range(n) if a[i] == b[i]) / n

    def add(self, masked_line):
        toks = masked_line.split()
        head = toks[:self.depth]
        best, best_s = None, 0.0
        for c in self.clusters:
            if len(c['tokens']) != len(toks):
                continue
            s = self._sim(c['tokens'][:self.depth], head)
            if s > best_s:
                best, best_s = c, s
        if best and best_s >= self.sim:
            best['count'] += 1
            # generalize positions that differ
            for i, (x, y) in enumerate(zip(best['tokens'], toks)):
                if x != y:
                    best['tokens'][i] = '<*>'
            return best['id']
        cid = len(self.clusters)
        self.clusters.append({'id': cid, 'tokens': toks, 'count': 1})
        return cid

def template_text(c):
    return ' '.join(c['tokens'])

Two masking choices deserve explicit justification. First, <DUR> is masked before <NUM> so that timeout after 3000ms and timeout after 5000ms collapse to one template — otherwise a latency regression would fragment into hundreds of "new" templates and look like novelty rather than a rate shift. Second, UUIDs and hex blobs are masked before the generic number rule, because a request ID like a1b2c3d4-... contains digits that would otherwise leave a ragged template.

Stage 2 — Frequency baselines per template

Bucket counts into fixed windows (5 minutes is a reasonable default for service logs) and build a baseline from a quiet reference period — typically the same time-of-day band over the preceding 7–14 days, which absorbs diurnal traffic cycles. Store per-template mean and variance of window counts, plus a novelty flag for templates absent from the baseline.

WINDOW_S = 300

def window_counts(events, window_s=WINDOW_S):
    """events: list of (epoch_seconds, template_id) -> {window_start: Counter}"""
    buckets = defaultdict(Counter)
    for ts, tid in events:
        buckets[int(ts // window_s) * window_s][tid] += 1
    return buckets

def build_baseline(buckets, template_ids):
    stats = {}
    for tid in template_ids:
        xs = [b.get(tid, 0) for b in buckets.values()]
        n = len(xs)
        mu = sum(xs) / n if n else 0.0
        var = sum((x - mu) ** 2 for x in xs) / (n - 1) if n > 1 else 0.0
        stats[tid] = {'mu': mu, 'var': var, 'n': n}
    return stats

Stage 3 — Flagging significant shifts

Log counts are over-dispersed relative to Poisson, so a plain Poisson test fires constantly on bursty templates. Two practical guards: require a minimum absolute delta (e.g. ≥ 10 extra events in the window) and use a variance-inflated z-score with a floor on the standard deviation. Novel templates — present in the detection window but absent from the baseline — are flagged separately as novel signatures, since they carry no baseline variance at all.

def score_window(counts, baseline, min_delta=10, sd_floor=1.0, z_thresh=4.0):
    flags = []
    for tid, c in counts.items():
        b = baseline.get(tid)
        if b is None or b['n'] < 20:
            flags.append({'tid': tid, 'kind': 'novel', 'count': c})
            continue
        delta = c - b['mu']
        sd = max(math.sqrt(b['var']), sd_floor)
        z = delta / sd
        if delta >= min_delta and z >= z_thresh:
            flags.append({'tid': tid, 'kind': 'shift', 'count': c,
                          'mu': round(b['mu'], 2), 'z': round(z, 2)})
    return sorted(flags, key=lambda f: -f.get('z', 99))

Reading the output: shift versus novelty

The two flag kinds mean different things and should route differently. A shift on an existing template says a known failure mode is accelerating — check the upstream dependency or config change that template names. A novel template says the code path itself is new — a deploy, a feature flag, or an unhandled exception class — and deserves a look at the raw lines behind it before you trust the template, because a bad masking rule can manufacture novelty.

Validation and failure modes

Validate the workflow against a labelled incident set: for each incident, check whether a flag fired in the 10–60 minute window before onset, and record the lead time. Two failure modes dominate in practice. Over-masking collapses distinct errors into one template — symptom: a shift flag on a template whose raw lines are visibly heterogeneous, fixed by tightening the mask order or lowering the drain similarity threshold. Under-masking fragments one error into many templates — symptom: a flood of "novel" flags on the same day, fixed by adding a mask for the offending variable field. Both are diagnosed by sampling raw lines behind a flagged template, which is why the pipeline should always retain a pointer from template ID back to a few example lines.

Quick reference