Clustering Log Messages for Faster Triage

You have 200,000 lines from the last hour and fifteen minutes to work out what broke. The useful first move is not searching — it is collapsing the pile into the twenty distinct things it actually says, ordered by how unusual they are.

What triage clustering is for

This is a different job from template extraction, even though both group similar lines. Template mining is a permanent, online, low-parameter process that assigns stable ids for counting. Triage clustering is a one-shot batch operation over a slice you already suspect, tuned for a human reading the output once. It can afford to be slower, it can afford to be approximate, and it should be tuned for recall of distinct shapes rather than for stable identity.

The output you want is a list like “41,000 lines of this; 38,000 of this; 12 of this one, which appeared for the first time eleven minutes ago”. The last entry is usually the answer, and it is invisible in a search interface because you do not know what to search for.

Choosing a distance

Levenshtein edit distance — the minimum number of single-character insertions, deletions and substitutions to turn one string into another — is the obvious measure and it costs O(n·m) per pair for strings of length n and m. On 200-character log lines that is 40,000 cell evaluations per comparison, which is fine for thousands of comparisons and hopeless for billions.

Two adjustments make it behave. First, normalise: a raw distance of 12 means something different on a 30-character line and a 300-character one, so use a ratio in [0, 1]. Python’s standard library gives you one for free — difflib.SequenceMatcher(None, a, b).ratio() — which is a Ratcliff/Obershelp similarity rather than Levenshtein, but ranks log lines similarly and needs no dependency. Second, compare tokens rather than characters. Token-level distance treats a substituted request id as one edit rather than as thirty-two, which is exactly the invariance you want, and it shortens the sequences by roughly a factor of six.

Masking before you measure matters more than the choice of metric. If you replace every run of digits, every hex string and every quoted value with a placeholder first, most lines that belong together become byte-identical and never reach the distance function at all. In practice a masking pass plus exact grouping does 90% of the work, and edit distance cleans up the rest.

Blocking, or it never finishes

Comparing every line with every other line is O(n²). For 200,000 lines that is 2 × 10¹⁰ comparisons, which at a microsecond each is over five hours. The fix is standard in record linkage and it is called blocking: partition the input on a cheap key such that lines with different keys are never compared, and only run the expensive comparison within a block.

For log lines two blocking keys work well together: the token count, bucketed, and the first token. Both are O(1) to compute and both are almost always shared by lines from the same log statement. A third trick, greedy leader clustering, avoids all-pairs work inside a block too: keep a list of representatives, compare each new line only against those, and stop at the first one over the threshold. That makes the cost proportional to lines × representatives, and representatives is a few dozen, not 200,000.

The script

1. Save the script below as logcluster.py. It needs Python 3.8 or later and nothing else.
2. Feed it lines on stdin: tail -n 200000 /var/log/app.log | python3 logcluster.py. It reads stdin, so it works equally well with kubectl logs or journalctl -o cat in front of the pipe.
3. Tune the one threshold. --sim 0.7 is the default; lower it to 0.55 if you see the same message split into several clusters, raise it to 0.85 if unrelated messages have merged.
4. Read the tail of the output first. The script prints clusters smallest-first, so the rare shapes — the ones you have never seen — are at the bottom next to your prompt.

#!/usr/bin/env python3
"""Group similar log lines. Reads stdin, writes a ranked cluster summary."""
import argparse, re, sys
from difflib import SequenceMatcher

MASKS = [
    (re.compile(r"\b(?:\d{1,3}\.){3}\d{1,3}(?::\d+)?"), "<IP>"),
    (re.compile(r"\b[0-9a-fA-F]{8,}\b"), "<HEX>"),
    (re.compile(r"\b\d{4}-\d{2}-\d{2}[T ]\d{2}:\d{2}:\d{2}\S*"), "<TS>"),
    (re.compile(r"/[\w./-]{2,}"), "<PATH>"),
    (re.compile(r"\b\d+(?:\.\d+)?\b"), "<NUM>"),
    (re.compile(r'"[^"]*"'), "<STR>"),
]

def mask(line):
    for pattern, placeholder in MASKS:
        line = pattern.sub(placeholder, line)
    return line.strip()

def similar(a, b, threshold):
    # cheap reject before the expensive comparison
    if abs(len(a) - len(b)) / max(len(a), len(b), 1) > 1 - threshold:
        return False
    return SequenceMatcher(None, a, b).ratio() >= threshold

def main():
    ap = argparse.ArgumentParser()
    ap.add_argument("--sim", type=float, default=0.7)
    ap.add_argument("--top", type=int, default=40)
    args = ap.parse_args()

    # stage 1: mask, then exact-group. This does most of the work.
    exact = {}
    for raw in sys.stdin:
        key = mask(raw)
        if not key:
            continue
        slot = exact.setdefault(key, [0, raw.rstrip()])
        slot[0] += 1

    # stage 2: greedy leader clustering inside blocks
    blocks = {}
    for key, (count, sample) in exact.items():
        tokens = key.split()
        block = (len(tokens) // 3, tokens[0] if tokens else "")
        blocks.setdefault(block, []).append((key, count, sample))

    clusters = []
    for members in blocks.values():
        leaders = []
        for key, count, sample in members:
            for leader in leaders:
                if similar(leader["key"], key, args.sim):
                    leader["count"] += count
                    leader["variants"] += 1
                    break
            else:
                leaders.append({"key": key, "count": count,
                                "variants": 1, "sample": sample})
        clusters.extend(leaders)

    clusters.sort(key=lambda c: c["count"], reverse=True)
    total = sum(c["count"] for c in clusters)
    print(f"{total} lines -> {len(clusters)} clusters\n")
    for c in clusters[: args.top][::-1]:
        share = 100.0 * c["count"] / total
        print(f"{c['count']:>9,}  {share:5.1f}%  ({c['variants']} variants)")
        print(f"           {c['sample'][:160]}")

if __name__ == "__main__":
    main()

Reading the output

The variants column is the one people ignore and should not. A cluster with 40,000 lines and one variant is a single log statement firing a lot — normal. A cluster with 40,000 lines and 900 variants means the masking did not catch a variable, so 900 masked forms were merged by edit distance; that cluster is probably several statements and is worth splitting with a tighter threshold before you trust its count.

The rare clusters at the bottom are where triage actually happens, but rarity alone is not suspicion — a nightly job that logs once an hour is rare and fine. What makes a rare cluster interesting is that it is rare and new. Run the same script over the equivalent window from yesterday, diff the cluster keys, and the clusters present today and absent yesterday are a short list that very often contains the cause.

Two limits to keep in mind. Greedy leader clustering is order-dependent: the same input in a different order can produce slightly different groupings, because the first line to arrive becomes the representative. And the blocking key means a message that changed token count between versions — because someone added a field — appears as two clusters no matter how low you set the threshold. Both are acceptable for triage and would not be acceptable for the persistent template ids that deduplication and long-running frequency models depend on.

When a cluster does look like the cause, the next question is always when it started, and the script as written throws timestamps away during masking. The smallest useful extension is to keep the parsed timestamp alongside each line, and to print, for each cluster, the first and last time it was seen plus a coarse histogram — counts per minute across the window. A cluster whose histogram is flat for fifty minutes and then vertical for three is a different story from one that ramped over the whole hour, and the shape distinguishes a triggered failure from a saturation failure without any further analysis. That histogram is also the input to a threshold you can derive rather than guess, which is the subject of burst detection. Keep the per-cluster counts from each run in a file, and after a week you have the baseline that turns “this looks unusual” into a number.