Log Filtering and Rotation

The previous two lessons worked with the entire log in hand: both the 4000 lines and the 601 lines were complete, and the filters ran over that whole. This assumption holds on a machine only for a limited time. Log files do not grow without limit; disk is finite, and a full disk is a bigger failure than the log itself.

This lesson takes up two mechanisms together. The first is filtering: selecting a subset from the lines you have. The second is rotation: permanently discarding part of the lines you have. The two look similar on the surface — fewer lines remain after either — but one is reversible and the other is not. What is measured is the damage each does to the diagnosis.

The Context Filtering Drops

There are three kinds of filter, and each cuts along a different axis. A level filter keeps only what is above a certain severity. A unit filter keeps only one service’s records; this was what the previous lesson measured, and it produces adjacency loss. A time filter discards everything outside an interval.

The level filter is the most commonly used and the most deceptive. A 4000-line log has 86 errors; a view restricted to errors reduces 4000 lines to 86 and makes them readable. But what came before the error is inside the 3914 lines that drop. The warning a service writes before it fails can say more than the failure itself: retry count, timeout duration, queue fullness. The level filter makes these invisible.

The time filter’s trap is different. Once a failure is noticed, the investigation mostly starts with a narrow window going backward from the moment it was noticed. The failure itself can be in that window, but the event that started it can fall outside it. Widening the window increases the line count and makes reading harder; this is one face of the course’s second claim: more lines do not mean a better diagnosis, but fewer lines do not always give a clearer one either.

The defining property of filtering is that it is reversible. If the filter was chosen wrong, the command is run again. There is no loss, only time spent.

How the filter is built also depends on format. In a structured record, the three axes can be given separately; in plain text, lines are selected by text matching, and the time restriction is parsed out of the text itself. The two dumps below are examples and have not been run.

# example dump , not run
$ journalctl -u process -p warning --since -10min
$ grep -E 'error|warning' /var/log/process/process.log | tail -n 40

The two lines do not do the same job. The first restricts unit, level, and time interval as fields; the second searches for two words in the message text and takes the last forty lines instead of a time restriction. The second silently drops the lines of a program that does not use the word “warning,” and it does not say how many seconds “the last forty lines” spans.

Rotation: A Cut That Cannot Be Undone

Rotation is the mechanism that limits a file’s growth. Once the file reaches the set size or age, it is renamed, a new one is opened in its place, and once the number of old copies kept is exceeded, the oldest is deleted. Compression delays the moment of deletion; it does not remove it. A retention policy consists of these three parameters: threshold, number of copies kept, and compression.

The system log’s own limit works similarly: once the total size or duration limit is exceeded, the oldest records are dropped. What the mechanism is called does not matter; the result is the same. The dump below is an example and has not been run.

# example dump , not run
$ ls -1 /var/log/process/
process.log
process.log.1
process.log.2.gz

The question here is: what happens if the file limit is shorter than the failure’s duration. The answer is the course’s third claim: evidence disappears on its own. Nobody deletes it, nobody decides; the policy runs, and the evidence goes.

The sneakiest part of this loss is its silence. No marker is left in place of the deleted lines; there is no line at the top of the file saying “everything before this was discarded.” What the operator sees on opening the file is not the look of a missing record but of a short history. With filtering, the situation is different: because the operator wrote the filter themselves, they know what they left out. With rotation, the operator is not the one who makes the choice, and the choice was written to a configuration file long before the failure.

What Is Measured: Surviving Evidence and Unanswered Questions

The measurement has two parts. The first part is the surviving-evidence ratio: how many of the errors at the start of the window survive as the file size shrinks. The second part is how many of the answers to the six questions genuinely asked in a failure investigation turn out wrong: total error count, the first error’s second, the first error’s unit, the last error’s second, the error count in the window’s first half, and the number of units that write no error at all. The oracle is the answers read from the full log.

The setup’s assumptions: a rotated file always keeps the last lines, and the discarded part does not come back (GN9); the sizes tested are 4000, 2000, 1000, 500, and 200 lines (GN10); the review question set is the six questions above (GN11); the precursor-warning window is five seconds, and the precursor must come from the same unit (GN12); line rate is constant across the window (GN13).

SEED = 20260218
PERIOD = 600                     # observation window: 600 seconds


def generator(seed):
    d = seed

    def next_val(n):
        nonlocal d
        d = (d * 1103515245 + 12345) % 2147483648
        return d % n
    return next_val


UNIT = {
    "ingest":  {"requires": [], "restart": "always"},
    "queue":   {"requires": ["ingest"], "restart": "always"},
    "process": {"requires": ["queue"], "restart": "on-failure"},
    "report":  {"requires": ["process"], "restart": "no"},
    "metrics": {"requires": ["ingest"], "restart": "always"},
    "backup":  {"requires": [], "restart": "no"},
}


def generate_log(seed=SEED, lines=4000):
    r = generator(seed)
    records = []
    for i in range(lines):
        weight = r(100)
        level = "error" if weight < 3 else ("warning" if weight < 12 else "info")
        records.append({"seq": i, "second": i * (PERIOD / lines),
                         "level": level, "unit": list(UNIT)[r(len(UNIT))]})
    return records


def rotate(records, size):
    """GN9: the file fills at `size` lines and the old part is deleted. What's left."""
    return records[-size:] if size < len(records) else list(records)


def evidence_ratio(records, remaining, level="error"):
    total = [k for k in records if k["level"] == level]
    left = [k for k in remaining if k["level"] == level]
    return {"total": len(total), "remaining": len(left),
            "ratio": round(len(left) / len(total), 4) if total else 0.0}


def preceded_errors(records, window=5.0):
    """GN12: errors that have a warning from the SAME unit in the five seconds before them."""
    u = [k for k in records if k["level"] == "warning"]
    h = [k for k in records if k["level"] == "error"]
    return sum(1 for a in h
               if any(a["unit"] == b["unit"]
                      and 0 <= a["second"] - b["second"] <= window for b in u))


def answers(records):
    """GN11: the review questions, answered from the lines sitting in the file."""
    h = [k for k in records if k["level"] == "error"]
    if not h:
        return {"total": 0, "first": None, "first_unit": None, "last": None,
                "first_half": 0, "silent_units": len(UNIT)}
    d = {b: sum(1 for k in h if k["unit"] == b) for b in UNIT}
    return {"total": len(h), "first": round(h[0]["second"], 1),
            "first_unit": h[0]["unit"], "last": round(h[-1]["second"], 1),
            "first_half": sum(1 for k in h if k["second"] < PERIOD / 2),
            "silent_units": sum(1 for b in d if d[b] == 0)}


for seed in (SEED, 20260219):
    G = generate_log(seed)
    K = answers(G)
    print("seed", seed, "| lines", len(G), "| warning",
          sum(1 for k in G if k["level"] == "warning"), "| error", K["total"])
    print("  level filter: errors hidden by a same-unit preceding warning", preceded_errors(G), "/", K["total"])
    print("  oracle:", K)
    print("  size  remain  error  evidence ratio  wrong answer  first error")
    for size in (4000, 2000, 1000, 500, 200):        # GN10
        remaining = rotate(G, size)
        er = evidence_ratio(G, remaining)
        Y = answers(remaining)
        print(f"  {size:5d}  {len(remaining):5d}  {er['remaining']:4d}  {er['ratio']:11.4f}"
              f"  {sum(1 for a in K if Y[a] != K[a]):12d}  {Y['first']}")

seed 20260218 | lines 4000 | warning 408 | error 86
  level filter: errors hidden by a same-unit preceding warning 63 / 86
  oracle: {'total': 86, 'first': 6.1, 'first_unit': 'process', 'last': 598.0, 'first_half': 44, 'silent_units': 3}
  size  remain  error  evidence ratio  wrong answer  first error
   4000   4000    86       1.0000             0  6.1
   2000   2000    42       0.4884             3  314.2
   1000   1000    19       0.2209             4  461.2
    500    500    12       0.1395             4  527.5
    200    200     5       0.0581             4  573.4
seed 20260219 | lines 4000 | warning 314 | error 163
  level filter: errors hidden by a same-unit preceding warning 99 / 163
  oracle: {'total': 163, 'first': 1.3, 'first_unit': 'report', 'last': 594.0, 'first_half': 80, 'silent_units': 3}
  size  remain  error  evidence ratio  wrong answer  first error
   4000   4000   163       1.0000             0  1.3
   2000   2000    83       0.5092             3  301.8
   1000   1000    35       0.2147             3  451.5
    500    500    12       0.0736             3  528.1
    200    200     3       0.0184             5  578.2

What the Output Says Versus the System’s Truth

Three numbers sit side by side. The oracle: the six-hundred-second window had 86 errors; the first at the sixth second, in the process unit. The tool output: the 1000-line file shows 19 errors, the 200-line file 5. Wrong diagnosis: 4 of the six questions are answered wrong at 1000 lines, and 4 again at 200 lines.

The surviving-evidence ratio falls together with rotation size: 0.4884 at 2000 lines, 0.2209 at 1000, 0.1395 at 500, 0.0581 at 200. Halving the file does not take half the evidence, it takes more than half; because records are not distributed evenly over time, the loss is not linear.

The real damage is not in the number but in the number’s credibility. The operator who opens the 200-line file sees five errors, and all five are genuine; none is fabricated. But the sentence they draw from it — “there were five errors in this window” — is wrong. The tool is not lying; the file is not lying. What is wrong is drawing a complete conclusion from an incomplete file.

The table of six questions details this. In the full file, all six of the six answers are correct. At 2000 lines, three answers break: total error count, the first error’s second, and the error count in the window’s first half. From 1000 lines on, the first error’s unit also comes out wrong: while the real first error is in the process unit, the first error remaining in the file belongs to another unit. The investigation answers “where did the failure start” by pointing to the wrong unit, and there is no sign anywhere in the file showing that answer is wrong.

A notable detail is that the wrong-answer count does not grow past 1000: it stays at four. The reason is that the remaining two questions — the last error’s second and the silent-unit count — can be answered from records near the end of the window. Rotation does not hit every question equally: questions that look at the past die first, questions that look at the present survive.

Another detail is that the evidence ratio can preserve the error rate even while it does not preserve the error count. The 200-line file has five errors, and this, in terms of errors per line, is close to the full log’s rate. A diagnosis that looks only at the rate sees nothing strange: the file looks like a healthy slice of a healthy system. What is lost is not the rate but the duration; how long the event lasted, when it started, and how it spread can only be read from the long window.

The measure of filtering is in the same output too. 63 of the 86 errors have a warning from the same unit in the five seconds before them. A view showing only errors hides all 63 of these precursors; the lines sit in the file, but not where they are being looked at. The difference with filtering is this: relaxing the filter brings the 63 lines back; relaxing rotation does not bring back a line already deleted in the past.

How Many Seconds of History a File Holds

The rotation threshold is in lines, while what the investigation asks about is time. The conversion between the two is done with line rate, and in this setup the rate is taken as constant (GN13): 4000 lines in six hundred seconds, that is, 0.15 seconds per line. From this, the history each threshold holds follows directly. A 2000-line file holds 300 seconds, a 1000-line file 150 seconds, a 200-line file only 30 seconds of history.

The output’s last column confirms this calculation. In the 1000-line file, the first error seen is at second 461.2; the window the file covers starts at second 450. In the 200-line file, the first error is at second 573.4; the window started at 570. The real first error, however, is at second 6.1, and it is found in none of the small files.

This conversion determines the question to ask when choosing a threshold. The question “how many lines should we keep” has no meaningful answer; the meaningful question is “how many seconds of history are needed,” and if the line rate is known, the conversion between the two is a multiplication. Line rate is not constant either: services write more at the moment of failure, so the file fills exactly faster at the moment producing the most evidence, and rotates faster. The moment evidence concentrates is the moment evidence is deleted fastest.

What the Policy Means

This yields two decisions on the operations side. First, the rotation threshold looks like a storage decision but is actually an investigation decision: the threshold should not be shorter than the longest reasonable duration of a failure. The surviving-evidence ratio is the measure of this and can be computed in advance; if the log’s line rate is known, how many seconds of history a threshold holds is a division.

Second, “keep everything just in case” is not a solution. If the disk fills, writing fails, and that failure is a worse problem than the lost evidence. The Storage topic will show that this limit comes in two separate forms. The right decision is to decide in advance which question needs to stay answerable and to choose the threshold for that question.

A third decision is when rotation happens. Time-based rotation runs at fixed intervals and rotates even if the file stays small; size-based rotation runs when the file fills and may never rotate on a quiet machine. When the two are used together, whichever triggers first wins. The result is this: how much history a threshold holds varies with how talkative the machine is, and on a busy day it is shorter than expected.

The fourth decision is how rotation is done. If the file is renamed and a new one opened in its place, a process still holding the file open keeps writing to the old file, and the new file stays empty; this is why, after rotation, a signal is sent to the writer telling it to reopen the file. The signal model built in the Process Management topic is part of a logging mechanism here. If the signal is not sent, the failure is silent: files rotate, the size limit works, but records keep falling into a file nobody is looking at anymore.

The Second Seed

In the second seed, the log is noisier: 163 errors and 314 warnings come out. The evidence ratio falls similarly — 0.2147 at 1000 lines, 0.0184 at 200. The wrong-answer count is 3 at 2000, 1000, and 500 lines, 5 at 200. The exact values depend on the setup; what does not depend on the setup is that the surviving-evidence ratio falls rapidly with rotation size and that questions looking at the past go unanswered first.

Summary

• Filtering is reversible, rotation is not; both reduce lines, but only one produces no loss.
• While 4000 lines have 86 errors, a 1000-line file keeps 19 (0.2209) and a 200-line file keeps 5 (0.0581); the loss is not linear.
• 4 of six review questions are answered wrong at 1000 lines, and one of them is “where did the failure start”; there is no sign of the wrongness anywhere in the file.
• Rotation does not hit questions equally: questions looking at the past die first, questions looking at the present survive.
• 63 of the 86 errors have a preceding warning from the same unit; the level filter hides them, but relaxing the filter brings them back.

Next Step

The loss measured in this lesson belonged to the past: a deleted line did not come back. The second kind of data describing a machine’s state is not lines but numbers — load, memory, disk fullness — and there, loss shows up in a different form. These numbers do not belong to a single moment; they are produced by averaging a past window, and the average smooths the spike. The next lesson takes up system health metrics and shows numerically that load average is a lagging indicator: while the instantaneous load is 7.36, the sixty-second average stays at 6.22.