Authentication Logs

The previous lesson established where a record comes from and which address it is written to; what it measured was a diagnosis looking at a single unit file being wrong on five of six tries. The question asked there was “which unit broke.” A machine has a second set of events that falls into the same system log but serves an entirely different question: who logged in, what did they request, was it granted.

This lesson takes up that set. The records themselves are ordinary; what is hard is the diagnosis drawn from them. In a failure investigation, a log line’s accuracy is not in question, but in a security investigation, which event a line represents is in question, and two different events mostly produce two lines that look very much alike.

One reason for the difference is the position of the party writing the record. A program writing service logs knows its own internal state; it can accurately describe what it did. The party writing identity events, by contrast, does not know who they are facing: who stands behind the incoming request is exactly what it is trying to measure. This is why an identity log is not an observation record but a decision record: it writes the decision the system made, not whether that decision was correct.

Two Separate Questions, One File

Authentication answers a single question: does this request genuinely belong to the account it claims. The answer is given with a password, a key, or some other proof, and its result is binary. Authorization comes after that: does the account, once its identity is proven, have the right to do the operation it is requesting.

The distinction matters, because the two kinds of failure describe entirely different things. An authentication failure means “this person could not prove who they are”; a user who mistypes a password and an attacker trying passwords both produce this line. An authorization failure means “this person proved who they are, but they cannot do this operation”; here, who the account belongs to is not in doubt, the requested work is too much. The first line shows identity being forced from outside; the second shows a missing internal configuration, or an attempted privilege overreach.

There is a third kind of event: session open and close. A session is the context that begins once authentication is accepted and lasts until it closes. A missing close record is ordinary: if the connection drops, the process is force-killed, or the machine reboots, there is an open record but no close record. A diagnosis that derives the open-session count from the log therefore counts more than the number of sessions actually open.

Protecting these records against tampering, signing them, and turning them into an independent audit trail is a separate topic, covered in the Governance, Risk and Compliance course; it is not repeated here. The question here is narrower: what diagnosis follows from the lines sitting in the machine’s own identity log.

The Trail Privilege Elevation Leaves

For an account to do work beyond its own privilege, an elevation step comes in between: a request is made, the rule set is checked, and an accept or deny record is written. The fields the record carries are the account making the request, the target identity, and the command to be run.

What this line does not say is why. An accept record does not write which rule clause accepted the request; a deny record does not write which clause blocked it either. Two different configuration errors — the rule not existing at all, and the rule existing but being shadowed by a narrower one — produce the same deny line. A diagnosis that wants to tell these two apart has to look at the configuration, not the log. The log says an event happened; it does not say why.

The second gap is the command itself. The record writes the command requested to run, but not what the command does. A one-line command that invokes a shell is recorded; what is done in that shell is not, because it happens inside a separate process. The subprocess model built in the Shell Programming course turns into a logging boundary here: the elevation record shows a doorway, not what happens behind it.

The third gap is time. Elevated privilege mostly stays valid for a stretch without being asked for again. Second and third requests made within that stretch do not produce a new authentication record. The log can answer “how many times did the account prove its identity”; it cannot answer “how many times did the account do work with elevated privilege.” Answering both questions with the same number is exactly the kind of wrong diagnosis this lesson measures.

What the Lines Look Like

Identity events are mostly collected in a separate file; the file’s name varies by distribution, and the same lines can also be found in the system log. The dump below is an example and has not been run.

# example dump , not run
[  301.020] sshd[1207]: login failed: account backup, source remote
[  301.900] sshd[1207]: login failed: account backup, source remote
[  318.400] sudo[1214]: privilege check failed: account app, command backup-task
[  342.000] sshd[1207]: login succeeded: account backup, source remote

Three of the four lines carry the word “failed,” but the three do not describe the same event. The first two are authentication failures from a remote source; the third is a local account requesting a command it has no privilege for. A text-matching filter throws all three into the same bucket.

# example dump , not run
$ grep failed /var/log/auth.log
[  301.020] sshd[1207]: login failed: account backup, source remote
[  318.400] sudo[1214]: privilege check failed: account app, command backup-task

A field-aware query, by contrast, can restrict the event type, the account, and the source separately; this is the practical counterpart of the structured-record-versus-plain-text distinction built in the previous lesson.

The text filter has one more fragility. The filter depends on the word the program writing the record happened to choose; a program that writes the same event with a different word drops silently out of the filter. If two programs on the same machine write the same event with two different phrasings, an operator searching with a single pattern never sees one of the two programs’ records at all, and no warning arises to reveal that gap. A query made over fields does not remove this dependency, but it moves the dependency from the body of the text to the field name, and a field name changes far more slowly than message text.

What Is Measured: Three Filters and One Field

The measurement is made with an identity log built on the shared definition’s generator. The setup’s assumptions: the machine has five accounts (GN5); 560 background events are generated and event-type weights are fixed (GN6); the attack starts at second three hundred and contains forty failed remote logins followed two seconds later by one successful remote login (GN7); the field-aware filter’s threshold is ten failed logins, its window sixty seconds (GN8).

The oracle is the attack placed into the setup: forty failed lines and one successful remote login at the end of the sequence — 41 lines in total. The tool output is the line set each of four separate filters returns. Wrong diagnosis is the sum of lines read for nothing and attack lines never read.

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


ACCOUNT = ("root", "app", "backup", "monitor", "operator")     # GN5


def auth_log(seed=SEED, background=560, attempts=40, target="backup", start=300):
    """GN6 background events + GN7 ORACLE: password-attempt sequence starting
    at second `start` and a SUCCESSFUL login at the end. Attack lines are marked."""
    r = generator(seed)
    records = []
    for _ in range(background):
        t = r(100)
        h = ACCOUNT[r(len(ACCOUNT))]
        remote = r(10) < 4
        if t < 6:
            kind, result = "login", "failed"          # password mistyped
        elif t < 18:
            kind, result = "privilege", "failed"      # identity correct , no privilege
        elif t < 26:
            kind, result = "session", "closed"
        elif t < 34:
            kind, result = "privilege", "succeeded"
        else:
            kind, result = "login", "succeeded"
        records.append({"second": r(PERIOD), "account": h, "kind": kind, "result": result,
                         "source": "remote" if remote else "local", "attack": False})
    for i in range(attempts):
        records.append({"second": start + i, "account": target, "kind": "login",
                         "result": "failed", "source": "remote", "attack": True})
    records.append({"second": start + attempts + 2, "account": target, "kind": "login",
                     "result": "succeeded", "source": "remote", "attack": True})
    records.sort(key=lambda k: k["second"])
    return records


def account_window(records, threshold=10, window=60):
    """GN8 field-aware filter: an account's `threshold`-or-more failed remote
    logins within the window, plus any successful remote login following that cluster."""
    selected = set()
    for h in ACCOUNT:
        d = [i for i, k in enumerate(records) if k["account"] == h
             and k["kind"] == "login" and k["result"] == "failed"
             and k["source"] == "remote"]
        cluster = set()
        for i in d:
            within = [j for j in d
                      if 0 <= records[j]["second"] - records[i]["second"] <= window]
            if len(within) >= threshold:
                cluster.update(within)
        if not cluster:
            continue
        last = max(records[j]["second"] for j in cluster)
        cluster.update(j for j, k in enumerate(records)
                        if k["account"] == h and k["kind"] == "login"
                        and k["result"] == "succeeded" and k["source"] == "remote"
                        and 0 <= k["second"] - last <= window)
        selected |= cluster
    return [records[j] for j in sorted(selected)]


def measure(records, matched):
    """Wrong diagnosis = lines read for nothing + attack lines never read."""
    actual = sum(1 for k in records if k["attack"])
    correct = sum(1 for k in matched if k["attack"])
    success = sum(1 for k in matched if k["attack"] and k["result"] == "succeeded")
    return {"matched": len(matched), "correct": correct, "success_found": success,
            "wrong_diagnosis": (len(matched) - correct) + (actual - correct)}


FILTER = (
    ("failed", lambda k: k["result"] == "failed"),
    ("failed login", lambda k: k["kind"] == "login" and k["result"] == "failed"),
    ("failed remote login", lambda k: k["kind"] == "login"
     and k["result"] == "failed" and k["source"] == "remote"),
)

for seed in (SEED, 20260219):
    K = auth_log(seed)
    print("seed", seed, "| lines", len(K), "| attack lines",
          sum(1 for k in K if k["attack"]))
    for name, f in FILTER:
        print(f"  {name:22s}", measure(K, [k for k in K if f(k)]))
    print(f"  {'account window':22s}", measure(K, account_window(K)))

seed 20260218 | lines 601 | attack lines 41
  failed                 {'matched': 153, 'correct': 40, 'success_found': 0, 'wrong_diagnosis': 114}
  failed login           {'matched': 67, 'correct': 40, 'success_found': 0, 'wrong_diagnosis': 28}
  failed remote login    {'matched': 51, 'correct': 40, 'success_found': 0, 'wrong_diagnosis': 12}
  account window         {'matched': 43, 'correct': 41, 'success_found': 1, 'wrong_diagnosis': 2}
seed 20260219 | lines 601 | attack lines 41
  failed                 {'matched': 156, 'correct': 40, 'success_found': 0, 'wrong_diagnosis': 117}
  failed login           {'matched': 79, 'correct': 40, 'success_found': 0, 'wrong_diagnosis': 40}
  failed remote login    {'matched': 60, 'correct': 40, 'success_found': 0, 'wrong_diagnosis': 21}
  account window         {'matched': 47, 'correct': 41, 'success_found': 1, 'wrong_diagnosis': 6}

What the Output Says Versus the System’s Truth

Three numbers sit side by side. The oracle: the 601-line log has 41 lines belonging to the attack. The tool output: the crudest filter returns 153 lines, the narrowest text filter 51, the field-aware filter 43. Wrong diagnosis: 114, 28, 12, and 2, respectively.

The numbers improve as the filter narrows, but the source of the improvement is not the line count. The filter searching for the word “failed” brings back 153 lines; only 40 of them belong to the attack, the remaining 113 are authorization denials and scattered password errors. The second filter, which restricts event type, brings wrong diagnosis down to 28; the third, which also restricts source, to 12. All three have something in common: none finds more than 40 of the 41 lines.

The field-aware filter returns 43 lines and includes all 41 of the attack’s 41 lines; the two extra lines are the same account’s other records within the window. Wrong diagnosis drops to 2. What produces the gain is not reading more lines but which field the lines are grouped by: not individual lines but the same account’s density within a sixty-second window is queried.

The two kinds of miss do not carry the same weight either. A line read for nothing wastes time; an attack line never read misdirects the diagnosis. In the measurement, the two are summed into one number, but their operational counterparts are separate. 113 of the crude filter’s 114 wrong diagnoses are of the first kind: the result points the right way, it is just expensive. The three text filters’ shared 1 shortfall is of the second kind, and it does not just cost more — it changes the result.

Narrowing the filter has a limit too. The third filter, which restricts the source to “remote,” would have found nothing if the attack had come from a local session; narrowing does not always improve — it only improves in this setup. A filter’s accuracy comes not from its own logic but from where the thing it is looking for actually sits.

The Most Important Line of Evidence

The last column of the output carries the real point. The three text filters’ success_found value is 0, the field-aware filter’s is 1. That single successful login line following the forty failed attempts is the line that determines the event’s outcome: if the attempts stayed failed, the event is noise; if the last one succeeded, the event is a breach. No filter searching for failure brings it back, because that line is not a failure.

This is the form the course’s rule takes in identity logs. However correct the answer to “how many failed logins are there” might be, it is not the question that determines the diagnosis. The correct question is: after this attempt sequence, could that account log in. The same distinction works in session records too: instead of counting sessions left open, which open has no matching close is asked.

The shape of the question determines the shape of the filter too. A filter that searches for failure produces a counter; a counter is compared against a threshold, and the threshold is always debatable. A filter that searches for a sequence produces a pattern: the same account, the same source, a narrow window, and a result that changes at the end. The measurement’s account_window function does exactly this; what brings wrong diagnosis down from 12 to 2 is not a smarter threshold but turning the question from a counter into a pattern.

The pattern has a cost. The counter is computed in a single pass; the pattern requires a window scan per account and gets more expensive as the log grows. If the records sit in field-separated form, this scan can be done on the query side; if there is only plain text, parsing has to happen first. The cost of the format distinction built in the previous lesson is paid here: plain text forces the question to be asked as a counter.

The Second Seed

With the second seed, the background noise changes; the attack stays at 41 lines because it is placed into the setup that way. The crude filter brings back 156 lines and produces 117 wrong diagnoses, the event-type filter 40, the source filter 21, the field-aware filter 6. The numbers grow, the ranking does not change, and the success_found column is again 1 only for the field-aware filter. The exact value of the wrong-diagnosis counts depends on the setup; what does not depend on the setup is that text matching structurally misses the successful line.

Summary

• Authentication failure and authorization failure are two separate events; a text-matching filter throws both into one bucket.
• A missing session-close record is ordinary; a diagnosis deriving the open-session count from the log counts more than are actually open.
• The oracle holds 41 attack lines; the crude filter brings back 153 lines and produces 114 wrong diagnoses, the field-aware filter brings back 43 lines and produces 2.
• None of the three text filters finds the attack’s successful login line; the field-aware filter finds it, and that line is what separates the diagnosis between breach and noise.
• The gain comes not from changing the line count but from grouping lines by account and time window.

Next Step

This lesson’s filters worked with the entire log in hand: all 601 lines could be read. On a real machine this assumption does not always hold, because log files do not grow without limit. Once a file reaches a certain size, the old part is discarded, and the discarded part does not come back. The next lesson takes up filtering and rotation together and counts how far the 86 errors in a 4000-line log drop as the rotation size shrinks.