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 text moves. Both Drain3 and grouping from the application's own code are then checked against the statement that wrote each line.

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.

Measured against the source statement that wrote each event, on a LogHub ZooKeeper capture (74,380 events, labels frozen before one run of each tool), 10x puts 0.21% of events (153) in a pattern that mostly holds a different statement, against 0.55% to 1.12% for Drain3 across three settings, its factory defaults included.

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.

Scoring both tools against the code that wrote each line

A group can keep its text and still hold the wrong lines. To check for that, every event of a LogHub ZooKeeper capture, 74,380 lines from a three-server ensemble, was labelled with the file and line of the logging statement that wrote it, read from ZooKeeper's own source. The labels were frozen before either tool ran on the capture, and each tool then ran once.

An event is merged when its group mostly holds a different statement. That is the defect that matters, since a cap, a sample rate or a route set on the group acts on both statements. An event is split when its statement spreads over several groups, which costs extra rules and keeps one statement per group. Exact grouping counts events whose statement has one group of its own.

10x ran as its published container image with its shipped configuration, and Drain3 in both masking arms of the two-copy test and at its factory defaults.

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.

Drain3's two masking arms split fewer events, 0.32% against 1.21%, and Drain3 builds fewer groups, 58, 64 or 72 against 97. 10x gives the Server environment: line one pattern per environment key, and each of those patterns still holds a single statement.

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. The scores against the code come from its intent folder: the method shows how each label was made, and the README lists which events each score covers. One more command reruns 10x and Drain3 against the frozen labels:

git clone https://github.com/log-10x/benchmarks && cd benchmarks/intent && ./run.sh

That run needs Docker, curl and Python 3, and takes about 45 minutes on a laptop.