How a Drain pattern group changes as more lines arrive

Drain3 is the open-source implementation of Drain, a log grouping algorithm published in 2017. It compares each new log line against the text it stored for that group, and blanks out any spot where the two disagree. The blank is permanent. Fed the same line, then two similar lines, then that line again, one copy returns different text and reports no change. Two copies given different halves of one log set disagree on 40% of small groups. A vocabulary built from the application's code gives the same answer everywhere.

The patterns screen in a log platform groups repeated log lines and shows a count beside each group. Drain3 builds groups like these. It is the open-source implementation of Drain, a log grouping algorithm published in 2017 and used as the starting point for most of the open-source work since.

Drain decides which words in a log line stay the same and which change by comparing each new log 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, and the blank is permanent for that group.

Drain3 groups the lines before they reach the log platform. A noisy group can then be dropped, and a rare one alerted on.

A rule like that points at its group by the stored text. When the text changes, the rule stops matching, and Drain3 reports the group as unchanged.

This post feeds 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 different halves of a 197,430-line log set, then given the same lines, disagree on 40% of the groups with two to ten lines.

Drain3 rewrites the stored text every time a log line joins a group

The code takes the incoming log line and the text it stored for that group, and 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, so the blanking is part of the method itself, not one package's quirk.

The stored text only ever loses actual words, never regains one, and which words it loses depends on the log lines that copy happened to see.

One copy of Drain3 gives two answers for the same log line

Three consecutive Grafana provisioning log lines from a public 215 MB sample, fed to one copy in order, then the first one fed again. Each call passes a log line in and reads back the text it stored for that 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', meaning nothing changed, and the report is correct on its own terms: the group last changed on the second call. The group number held across all four calls. The stored text did not, and the stored text is what any name gets computed from.

A saved search written against the earlier text matches zero events, and returns the zero as an ordinary answer.

Two copies of Drain3 give two answers for the same log line

One copy was fed the first half of a 197,430-line log set and the other copy the second half, so neither saw the other's. Handed the same log lines afterwards, the two disagree on the stored text for 40% of the groups with two to ten log lines. That is where a new failure shows up first.

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. 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 removes the numbering problem and keeps every other one. The stored text is still whatever that one copy happened to see.

Getting the same answer from the application's code instead of its traffic

Something has to decide which words in a log line stay the same and which change. An answer worked out by watching traffic go by moves as the traffic moves.

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 in the application's code. An application holds a fixed set of them, and the same few repeat on line after line. Request IDs, timestamps, host addresses and span IDs only exist while the application runs, and nearly every line carries different ones.

The 10x engine reads the first kind out of the application. Its compiler reads the source, or the binaries and container images the application ships as. Every word the application can print goes into a symbol library, settled before any log line arrives.

Keep those words and the punctuation between them, drop the rest, and hash what is left 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. Rebuilding the vocabulary renames the patterns whose words changed, and the build reports which ones changed and what they changed to.

A word the compiler never saw is treated as the second kind. That is usually right, since a word that appears in no code is usually a value. When it is wrong the log line gets a blank pattern, identically blank on every machine, so a miss reads as a miss. Running the engine on its default vocabulary alone, three log lines of invented words produced a blank pattern and the same short code all three times.

Every number here regenerates from one command

Everything measured here is a tool working the fixed words out from traffic as it arrives. The replay is four calls to a PyPI package against a published file, and every number in this post comes back from one command in the benchmark repository, along with the settings each run used and the output it produced.