Log Architecture

The previous topic followed the machine’s boot from start to finish: firmware called the bootloader, the bootloader called the kernel, the kernel called the first process, and the service manager brought units up in dependency order. Every step of that chain did a job, but none of them did it in front of the operator’s eyes. Once the machine is up, the only witness left is the written trail.

This topic takes up that trail. The first question is architectural: how does a line enter the log, who stamps it, which address is it written to, and what can the person who opens that address not see. The last part of the question ties back to the course’s rule: a log’s value is not how many lines it holds but how many times the diagnosis drawn from those lines turns out wrong.

The scope of this topic is a single machine. Pipelines that collect multiple machines’ records in one place, stores that keep metrics, and alert chains that notify when a threshold is crossed were measured in the Observability and Operations and the Security Operations and Incident Response courses; they are not repeated here. The question here comes earlier: is the record sitting on the machine’s own disk and in its own memory enough to say what happened on that machine.

The Log’s Three Sources

On a single machine, log lines are born from three separate places, and the three do not take the same path.

The first is the kernel. The kernel writes its own messages to a ring buffer in memory; when the buffer fills, the oldest line drops. Device detection, block device errors, and memory pressure warnings come from here. This buffer is not disk: a reboot empties it, so the previous boot’s kernel messages are lost unless a persistent copy was taken.

The second is the service manager. The standard output and standard error the manager gives a unit when it starts are each a pipe; whatever the unit writes to those two streams, the manager captures, stamps with the unit’s name, and puts into the system log (journal). A program needs no special library to write logs; printing to the screen is enough. The standard-output-versus-standard-error distinction built in the Shell Programming course finds its operational counterpart here: data comes from the first stream, diagnostic messages from the second, and the manager can stamp the two with different levels.

The third is the application itself. A program can write to a file of its own choosing, in its own format. This file is outside the service manager’s field of view: it survives even if the unit is stopped, it is not stamped with the unit’s name, and its levels do not have to match the manager’s levels. It is ordinary for the same event to sit in two different forms — once in the system log, once in the application’s own file.

What the three sources have in common is this: none knows what the others write. The practical consequence of the split is that there is no guarantee an event’s trail will be found at a single address.

Persistence: In Memory or on Disk

Where the system log is written is a configuration decision, and the default behavior can vary by distribution. There are three options. The log can be kept in memory only; in that case a reboot erases the entire history, and once the machine recovers, no trace of the failure remains. The log can be written to disk; past boots become queryable, but the file does not grow without limit, and it drops the oldest entries once it reaches a size or duration limit. The third option is a mix of the two: to disk if the directory exists, to memory otherwise.

This decision directly determines the diagnosis. In a log kept in memory, the failure record of a service that recovers by restarting itself is erased along with its own recovery. The situation measured in the Services topic comes up here a second time: a unit with an “always” policy restarted sixty times in six hundred seconds and looked “running”; if that unit has a failure that also reboots the machine, neither the state nor the record survives.

For a log written to disk, the limit is size. Discarding the old part of a file that has reached the limit is called rotation, and this topic’s third lesson is entirely devoted to counting what it deletes. For now, one sentence is enough: the evidence’s lifetime can be shorter than the lifetime of the event that produced it.

A fourth distinction is access. Log files are ordinary files too and follow the permission model built in the Introduction to Linux course; files holding identity events are mostly closed to unprivileged users. A record existing does not mean you can read it.

Timestamp and Sequence

The most trusted field of a log line is time, and yet it is also its most fragile field. There are two separate clocks: a monotonic clock counting time elapsed since the machine booted, and a wall clock showing calendar time. The first never runs backward. The second can: synchronizing with a time server, manual correction, and daylight-saving transitions can jump the wall clock forward or backward.

The consequence is this: in a log sorted by wall clock, an event that actually happened earlier can appear below an event that happened later. Causality is the main tool of a failure investigation, and two reversed lines flip the diagnosis directly. This is why structured records keep, alongside the wall clock, the monotonic clock and a monotonically increasing sequence number; when sorting, trusting the counter is sturdier than trusting the wall clock.

In this lesson’s measurement and in the lessons that follow, time is the shared definition’s model second: the observation window is six hundred seconds, and every duration is counted within that window. A real timestamp is written nowhere, because a real timestamp is machine-dependent and cannot be reproduced.

Level, Field, and Format

Every record has a level. The common ordering is eight steps, ranging from debug messages to emergency messages; three steps are enough for this topic: info, warning, error. The level is the writer’s own declaration, not an independent measurement. If a program writes a fatal condition at the info level, every tool that filters by level drops that line.

The level’s second problem is the threshold. A system log mostly works with a floor: lines below the set level are not written. Keeping the debug level off shrinks the log, but the detail that would be most useful at the moment of failure sits exactly there. Opening the threshold after the failure does not bring the past back; the threshold determines what gets written while the event is happening. This is the plainest form of the course’s third claim: looking late sees little.

The difference between a structured record and plain text also shows up here. A plain text line is a single string; reading it requires parsing. A structured record consists of fields: unit name, level, process ID, time. Because fields are queryable, filtering rests on field comparison, not text matching. This distinction determines what will be measured in the next lesson: a text-matching filter and a field-aware filter give different answers to the same question.

The Same Event, Two Addresses

The system log keeps every unit’s records in a single stream, in time order. The dump below is an example and has not been run; the number in brackets is the number of seconds elapsed since boot.

# example dump , not run
[  461.250] process[1043]: error: no response from queue
[  461.400] process[1043]: info: retry 1/5
[  463.100] metrics[1092]: warning: sampling window exceeded
[  466.050] ingest[1014]: error: stream closed

If the same events are stored in files split per unit, the picture changes. The process unit’s own file looks like this; this dump is also an example and has not been run.

# example dump , not run
[  461.250] error: no response from queue
[  461.400] info: retry 1/5
[  527.500] error: no response from queue

The second dump has no metrics or ingest lines. What is lost is not a line but the adjacency between lines: the fact that ingest’s stream closed five seconds after process’s error sits only in the combined stream.

The second difference between the two dumps is the stamp. In the combined stream, every line has the unit name in front of it; in the unit file, it does not, because the file’s name already states the unit. This looks like savings while the file is small, but once two files are merged, which line came from where is lost. Merging dumps from different sources onto a single time axis is an ordinary step in a failure investigation; unstamped lines stay unidentified at that step.

The third difference is that the service manager places the stamp itself. The unit name, process ID, and level come not from the line’s content but from context the manager already knows. When a program writes to its own file, this context does not exist: the same event’s counterpart in the application’s own file carries no unit name, the process ID is only whatever the program chose to write, and the level is marked on the program’s own scale. The same event is represented with two different levels of accuracy at two addresses.

What Is Measured: A Diagnosis That Looks at One File

The measurement is built on the shared definition’s log generator. The setup’s assumptions are these: the observation window is six hundred seconds, the log has 4000 lines, and level weights come from the shared definition (GN1); records are spread across six units (GN2); the adjacency window is five seconds (GN3); the operator decides by looking at the single file they opened (GN4).

The oracle is how many errors the six units actually wrote; it is known because we built the setup. The tool output is the single unit file the operator opened. The diagnosis is the “this unit is the source of the error” decision made by looking at that file.

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 unit_errors(records):
    d = {b: 0 for b in UNIT}
    for k in records:
        if k["level"] == "error":
            d[k["unit"]] += 1
    return d


def single_log_diagnosis(records):
    """GN4: operator looking at only ONE unit file: 'the source is this unit'."""
    d = unit_errors(records)
    culprit = max(d, key=lambda b: d[b])
    return {"actual_source": culprit, "silent_files": sum(1 for b in d if d[b] == 0),
            "tried": len(d), "wrong_diagnosis": sum(1 for b in d if b != culprit)}


def neighboring_error(records, window=5.0):
    """GN3: errors that have an error from ANOTHER unit within five seconds."""
    h = [k for k in records if k["level"] == "error"]
    return sum(1 for i, a in enumerate(h)
               if any(abs(b["second"] - a["second"]) <= window
                      and b["unit"] != a["unit"] for j, b in enumerate(h) if i != j))


for seed in (SEED, 20260219):
    G = generate_log(seed)
    d = unit_errors(G)
    print("seed", seed, "| lines", len(G), "| errors", sum(d.values()),
          "| per unit", list(d.values()))
    print("  ", single_log_diagnosis(G), "| neighboring errors", neighboring_error(G))

seed 20260218 | lines 4000 | errors 86 | per unit [28, 0, 31, 0, 27, 0]
   {'actual_source': 'process', 'silent_files': 3, 'tried': 6, 'wrong_diagnosis': 5} | neighboring errors 50
seed 20260219 | lines 4000 | errors 163 | per unit [0, 50, 0, 51, 0, 62]
   {'actual_source': 'backup', 'silent_files': 3, 'tried': 6, 'wrong_diagnosis': 5} | neighboring errors 135

What the Output Says Versus the System’s Truth

Three numbers sit side by side. The oracle: the 4000-line window has 86 errors, and 31 of them belong to the process unit; that is the real source. The tool output: the six unit files hold, in order, 28, 0, 31, 0, 27, and 0 errors. Wrong diagnosis: 5. The operator opens one of six files and says “this unit is the source of the error”; they are wrong on five of six tries.

Three of these five misses are not the same kind. Three files are completely silent: they hold no error line at all. The operator who opens that file concludes “there is no problem here,” and that conclusion, even if true for their own unit, is wrong about the system — the system has 86 errors. The remaining two files show errors but not the most; the operator there looks at the problem and blames the wrong unit. Silence and innocence are not the same thing.

The second number measures adjacency: 50 of the 86 errors have a neighboring error from another unit within five seconds. None of these 50 lines appears next to its neighbor in a single unit file. Files split per unit do not lose lines; they lose order, and order is itself evidence.

This yields an architectural decision: a per-unit file is useful when examining a single unit in depth; finding where a failure started requires a combined, time-ordered stream. Choosing one of the two addresses is not mandatory, but it must be known that which one is looked at determines the diagnosis.

The limit of the measurement must also stand clearly. Here, the oracle is the setup itself; on a real machine, no party knows which unit is truly the source, and the only thing that tests the diagnosis is whether the repair made afterward actually works. What the setup provides is being able to see where the “five of six” number comes from: the number arises not from a flaw in the tool but from the choice of address looked at. If the same 4000 lines had been read in the combined stream, the error distribution would have been visible with a single query and the wrong diagnosis would have dropped to zero. The tool is not lying; what is missing is where the question was asked.

The operational conclusion has two parts. First, a failure investigation starts not from the unit file but from the combined stream; the unit file is opened for detail once the source unit has been determined. Second, a silent file does not count as evidence: that unit writing no record at all shows only that it did not write, not that the unit is healthy. A failure in which a unit goes quiet and a window in which it has no problem at all are represented identically by the log.

The Second Seed

With the second seed, the setup changes: the error count rises to 163, the errors spread across different units, and the real source becomes backup. The wrong-diagnosis count stays 5 again, the silent-file count stays 3 again; in both seeds, only three units write errors. The neighboring-error ratio does change: in the first seed, 50 of 86 errors are adjacent; in the second, 135 of 163. The ratio itself depends on the setup; what does not depend on the setup is that a diagnosis looking at a single file is wrong on five of six, and that adjacency never appears in a single file.

Summary

• Log lines are born from three separate sources: the kernel’s ring buffer, the standard output and standard error the service manager captures, and the application’s own file.
• Level is the writer’s own declaration, not an independent measurement. Every tool that filters by level drops a line stamped wrong.
• The oracle knows the real source of the 86 errors; a diagnosis looking at a single unit file is wrong on five of six tries, and three files are completely silent.
• 50 of the 86 errors are adjacent to an error from another unit within five seconds; this adjacency is visible only in a combined, time-ordered stream.
• Files split per unit do not lose lines, they lose order; order is evidence too.

Next Step

Every record looked at in this lesson was a message services produced themselves. A machine also keeps a separate set of events recording who logged in when, which account requested which privilege, and which request was denied. Those records fall into the same system log but are read differently: the question asked is not “which unit broke” but “who did it.” The next lesson takes up authentication logs and counts how many lines a text-matching filter’s answer to that question turns out wrong.