Log pattern clustering, explained with real output

An error storm is thousands of log lines that say almost the same thing. Scrolling through them tells you nothing about how many different problems you have. Log pattern clustering fixes that by turning near-identical lines into one template with a count.

This post shows how the clustering works, with real output from the parser ZipLogger runs, where it goes wrong, and how to use patterns in the app.

What a template is

Take these three lines:

Order 83112 processed in 142 ms
Order 83113 processed in 97 ms
Order 83120 processed in 1204 ms

They are the same line with different values. The template is:

Order <*> processed in <*> ms

<*> marks the parts that change. Instead of three rows (or three thousand) you read one row with a count next to it. The values that changed are still kept, so you can see which orders were involved.

How Drain-style clustering works

ZipLogger uses a small version of the Drain algorithm. Drain is a well-known method for parsing logs online, one line at a time, without knowing the formats in advance. Here is what ZipLogger's parser does with each line:

1. Split the message on spaces. Each word is a token.
2. Mask the obvious variables. Tokens that are plain numbers, hex values like 0x1f, GUIDs, IPv4 addresses or long hex strings become <*> straight away.
3. Group by length. Only lines with the same number of tokens are compared. This is Drain's first shortcut and it keeps the comparison cheap.
4. Score against existing templates. For each template of the same length, count the positions where the token matches exactly, ignoring positions that are already <*>. Divide by the number of tokens.
5. Join or start a new template. If the best score is at least 0.5, the line joins that template and every position that differs becomes <*>. If not, the line starts a new template.

That is the whole idea. No machine learning, no training step. Each template also keeps a count, first and last seen times, a severity mix, and a few example lines.

Real before and after

Here is a batch of raw lines, fed through a copy of ZipLogger's parser with its default settings:

Order 83112 processed in 142 ms
Order 83113 processed in 97 ms
Order 83120 processed in 1204 ms
Cache miss for key user:4471:profile
Cache miss for key user:9012:profile
Cache miss for key cart:77:items
Payment declined for order 83112 by stripe
Payment declined for order 83140 by adyen
Connection to 10.0.4.17 refused, retry 3
Connection to 10.0.4.22 refused, retry 1
Timeout calling inventory-api after 5000 ms
Timeout calling payments api after 5000 ms
User 42 logged in
User 42 logged out

And the templates that came out, with counts:

3  Order <*> processed in <*> ms
3  Cache miss for key <*>
2  Connection to <*> refused, retry <*>
2  Payment declined for order <*> by <*>
2  User <*> logged <*>
1  Timeout calling inventory-api after <*> ms
1  Timeout calling payments api after <*> ms

Most of that is what you want. The order ids, cache keys, IP addresses and payment providers all became <*>. Notice that user:4471:profile was not masked up front, because it is not a plain number. It became <*> anyway because it was the only token that differed.

Two results are wrong, and they show the limits of the method.

Where clustering gets it wrong

Different lengths never merge. payments api is two tokens and inventory-api is one, so the two timeout lines have different lengths and end up as separate templates. Any variable that can contain spaces (a customer name, a free-text reason) splits one real pattern into several.

Similar lines can merge when they should not. User 42 logged in and User 42 logged out share half their tokens, which meets the 0.5 threshold. They became User <*> logged <*>, which hides the difference between a login and a logout. The same can happen to any two short messages that differ in one important word.

Groups can shift. Clustering is a heuristic over whatever lines it saw. Run it on a different time range and a borderline line may land in a different template.

Tokens are split on spaces only. 5000ms written without a space is not a plain number, so it is not masked up front. It still becomes <*> if it varies, but only through the similarity step.

Every Drain-style parser trades some accuracy for speed. The fix is to not guess when you do not have to.

Declared templates: when there is nothing to guess

Structured logging libraries already know the template, because you wrote it:

Log.Information("Order {OrderId} processed in {Elapsed} ms", orderId, elapsed);

ZipLogger's .NET packages send that template with every line. ZipLogger.Serilog sends Serilog's message template text, and ZipLogger.Extensions.Logging sends the {OriginalFormat} value from ILogger. Both arrive as fields.messageTemplate. At ingest, ZipLogger hashes the template (the first 16 hex characters of a SHA-256) and stores it on the line as templateHash.

That changes the answer in two ways:

• Counts are exact. Grouping by templateHash is a single aggregation over the whole time range, not a sample.
• Nothing is guessed. Order {OrderId} processed in {Elapsed} ms is shown exactly as you wrote it, and a login line can never merge with a logout line.

Lines with no declared template still get clustered. That covers plain strings, OTLP logs, other shippers, and anything sent before the hash existed. ZipLogger clusters a sample of up to 5,000 of those lines with the parser described above, and says so on the page.

If you log from .NET, see Send .NET logs to ZipLogger with Serilog for the setup.

Using patterns in ZipLogger

Patterns live on the Search page. Use the Patterns / Events toggle at the top right. Patterns is the default view.

The line above the results tells you what you are looking at: how many exact patterns there are and how many lines they cover, then how many more were clustered and how big the sample was. When the sample did not reach every untemplated line, it also says how many untemplated lines there were in total, so you know how much was left out.

Below the histogram there are two sections:

• Exact, grouped by declared template. Counts are exact over the whole window. Each row shows the count, the dominant severity, the template text, the share that were errors, the services that wrote it, and when it was last seen.
• Clustered, lines with no declared template. Counts are within the sample.

The two kinds of row do different things when you click them.

An exact row is a filter. Click it and it becomes a templateHash filter chip. Switch to Events to read the individual lines. Click the row again to remove the filter.

A clustered row expands. You get first seen, last seen and the pattern's hash, then a table of example lines with the columns Time, Severity, Source, Release, Release date, Variable parts (the diff) and Full message. The variable parts column shows the values that filled each <*>. The first example kept for a pattern can show fewer parts than the rest, because it was stored before the pattern had widened. From the expanded row you can:

• open the trace with View trace, when the example carries a trace id, or read the Stack trace when it has one
• click Find the commit that caused this, which blames the stack frames from your own code against a repository connected under Settings → Integrations (the Repositories card) (Find the commit that broke production covers how that works)
• click What were users doing?, which finds the product analytics events sent on the same requests as the error (only if your app sends events and has tracing on)

In both views, Admins and Editors also get Hide matching, which removes the lines that match the current search from every view without deleting them. You can bring them back from Hidden logs.

The Traces and Events pages have a Patterns view too. They use the same table, but there is no clustering: traces group by span name (with an errors column and p95 duration) and events group by event name. Those names already are the pattern.

What it does not do

• It does not merge lines across different token counts, so variables that contain spaces can split a pattern.
• Clustered counts are counts within a sample of up to 5,000 lines, not totals. Only declared templates give exact counts.
• A clustered pattern cannot be used as a filter the way a declared one can. You expand it and read its examples instead.
• An exact pattern does not expand yet, so the example table and Find the commit that caused this only appear on clustered rows. For an exact pattern, filter by it and open the lines in Events.
• There is no setting to change the similarity threshold.

For errors with an exception, the Issues page groups by exception type and stack frames, not by message shape. It falls back to the message only when the stack has no usable frames, as in minified code. See error tracking.

You can read more on the features page, or create a workspace and open the Patterns view on your own logs.