How a Drain pattern group changes as more lines arrive

A log platform groups repeated lines and shows a count beside each group. A saved search or an alert points at one of those groups by its stored text. Drain3, the open-source implementation of the Drain algorithm, rewrites that text as new lines arrive. This post measures how far that stored text moves as lines arrive. A second part shows, on the OpenTelemetry demo's cart service, how one group comes to hold two different statements.

The patterns screen in a log platform groups repeated log lines and shows a count beside each group. Drain3 builds groups like these. Most of the open-source work since has started from the same place: Drain, a log grouping algorithm published in 2017.

Drain decides which words in a log line stay the same and which change by comparing each new line against the text it already stored for that group:

Session opened for user alice from 10.0.0.1     first line, stored exactly as it arrived
Session opened for user bob   from 10.0.0.2     next line into the same group
Session opened for user <*>   from <*>          what Drain stores from then on

Every spot where the two lines differ is blanked out. The blank is permanent for that group.

Grouping happens before the lines reach the log platform, which is the point of running it there: a noisy group gets dropped at the edge, a rare one raises an alert. Either rule points at its group by the stored text. When that text changes the rule stops matching. Drain3 reports the group as unchanged.

I fed one copy of Drain3 the same log line, then two similar lines, then the same line again. The text it returns has changed. Two copies fed random halves of a 197,430-line log set, then handed the same lines, disagree on the stored text for 39.78% of probed events whose shape occurs two to ten times.

How Drain3 stores a group

The code takes the incoming log line and the text stored for that group, then hands back the text to store next:

# drain3 0.9.11, drain3/drain.py:267-275
def create_template(self, seq1, seq2):
    assert len(seq1) == len(seq2)
    ret_val = list(seq2)

    for i, (token1, token2) in enumerate(zip(seq1, seq2)):
        if token1 != token2:
            ret_val[i] = self.param_str

    return ret_val

Every word where the two differ is blanked out, and line 338 of the same file saves the result back over the group's stored text. The published algorithm specifies the same step. Blanking belongs to the method itself.

Stored text only ever loses words, never regains one. Which words it loses depends on the log lines that copy happened to see.

The same line twice

Three consecutive Grafana provisioning log lines out of a public 215 MB sample, fed to one copy (0.9.11, stock settings) in order, then the first one fed again. Each call passes a log line in and reads back the text stored for its group:

tm = TemplateMiner(config=cfg)            # stock settings, unchanged
first = tm.add_log_message(line_1109)["template_mined"]
tm.add_log_message(line_1110)
tm.add_log_message(line_1111)
again = tm.add_log_message(line_1109)["template_mined"]
first == again                            # False

The text stored for that group on the first call and on the fourth, with <*> marking the blanked spots where the datasource name and its uid stood:

first   ... msg="inserting datasource from configuration" name=Jaeger uid=webstore-traces
again   ... msg="inserting datasource from configuration" <*> <*>

On the fourth call the tool reports change_type='none', and on its own terms that report is correct: the group last changed back on the second call. The group number held across all four calls too. What moved was the stored text, which is the input to any name computed for the group.

A saved search written against the earlier text now matches zero events. The zero comes back looking like any other count.

Two copies of Drain3

The 197,430 lines were shuffled, then split down the middle, one random half to each copy, so neither saw the other's. The benchmark calls that random split the friendliest division available to Drain. Handed the same log lines afterwards, the two disagree on the stored text for 39.78% of probed events whose shape occurs two to ten times.

A reference pass over the same stream resolved it into 1,481 distinct shapes, 921 of them seen once. The baseline arm of that pass reported 1,465 shapes, 949 of them seen once.

On those same test log lines the two copies pick the same group number 6 times in 100. An alert check looks a log line up rather than feeding it in, and asked that way a log line seen once has no group at all in one of the two copies, 999 times out of 1,000.

Naming a group after its stored text rather than its number does fix the numbering. But the name is then whatever that one copy happened to see.

Reading the words from code

Something has to decide which words in a log line stay the same and which change. Drain decides from traffic. The words themselves were settled earlier than that, in the code.

Two kinds of word show up in a log line. Class names, method names, enum values like ERROR and the message text itself are written into the application's code, which holds a fixed set of them and prints the same few over and over, while request IDs, timestamps, host addresses and span IDs exist only while the application runs, and nearly every line carries different ones.

The 10x engine reads the first kind out of the application itself. Its compiler takes the source, or the binaries and container images the application ships as. The message text and the names the compiler links land in a symbol library that is settled before the first log line arrives.

From the words a line shares with that library, the engine selects the ones that make up its message and hashes them into a short code. That code is the log line's pattern ID. The same log line gets the same pattern ID on every machine running the same vocabulary and engine version, including a log line no machine has seen before.

The price is running that compiler over the code that prints the logs, which watching traffic never asks for. Rebuilding the vocabulary also renames the patterns whose words changed, though the build reports which ones moved and what they moved to.

A word the compiler never saw gets treated as the second kind. That is usually right, since a word that appears in no code is usually a value. When no word in a line is in the library, 10x gives the line a pattern from its shape: template_ followed by a hash of its punctuation and of where its values sit. Every machine running the same engine, library and configuration computes the same hash, so two machines still agree.

Checking groups against the code that wrote each line

A group can keep its text and still hold the wrong lines. Labelling every event with the file and line of the logging statement that wrote it, read from the program's own source, shows which groups hold more than one statement. Such a group is the defect that matters, since a cap, a sample rate or a route set on it acts on every statement inside.

A header line shows how a merge happens. On the OpenTelemetry demo, the cart service's .NET logger prints one above every message, so its three statements start the same way:

info: cart.cartstore.ValkeyCartStore[0]
      GetCartAsync called with userId=02fec73e-9f03-11f0-9b9e-a666c4b68b87

Fed line by line, Drain3 groups all the cart events under that header. 10x takes the pattern from the first line of an event that holds a message, which gives the three statements three patterns: GetCartAsync_called_with_userId, AddItemAsync_called_with_userId_productId_quantity and Successfully_connected_to_Redis.

Per-capture scores for both tools, labelled this way, are in the intent benchmark.

Reproducing these numbers

The Drain3 replay is four calls to a PyPI package against a published file. The two-copy figures come back from one command in the benchmark repository, with the settings each run used and the output it produced.