Logging Security Events Without Logging Secrets

A security log has two jobs: record enough for someone to reconstruct what happened, and record nothing that makes the breach worse. Most applications fail one of the two. OWASP Top 10:2025 lists this as A09, Security Logging and Alerting Failures. This lesson logs failed logins, finds the most common logging bug (the secret in the log line), fixes it, closes a log-forging hole, and ends with a 20-line detector that raises an alert. Every example uses only the standard library on Python 3.12.15 (python:3.12-slim), and every secret is fake.

The bug: the password lands in the log

Logging the whole request is the quickest way to get “enough context”. It also logs everything else in the request.

# login_bad.py
import logging

logging.basicConfig(level=logging.INFO, format="%(levelname)s %(message)s")
log = logging.getLogger("auth")
USERS = {"alice": "FAKE-correct-horse-battery"}

def login(request):
    if USERS.get(request["user"]) == request["password"]:
        log.info("login ok: %s", request)
    else:
        log.warning("login failed: %s", request)

login({"user": "alice", "password": "FAKE-correct-horse-batery", "ip": "10.0.0.5"})
login({"user": "alice", "password": "FAKE-correct-horse-battery", "ip": "10.0.0.5"})

$ python login_bad.py
WARNING login failed: {'user': 'alice', 'password': 'FAKE-correct-horse-batery', 'ip': '10.0.0.5'}
INFO login ok: {'user': 'alice', 'password': 'FAKE-correct-horse-battery', 'ip': '10.0.0.5'}

The successful login writes alice’s real password in plain text. The failed one is nearly as bad: a failed password is usually a typo of the real one (here, one missing t), or the user’s password for another site. Logs are shipped to aggregation systems, kept for months, and readable by people who would never be given the user database. Whoever can read this log now has the credential, and no amount of password hashing in the database helps.

The fix: structured events and a redaction filter

Two changes. Emit one JSON object per event, with named fields, and attach a filter to the handler that replaces any sensitive field before it’s formatted.

# login_json.py
import json, logging

SENSITIVE = {"password", "token", "authorization", "cookie"}

class Redact(logging.Filter):
    def filter(self, record):
        record.fields = {k: "[REDACTED]" if k.lower() in SENSITIVE else v
                         for k, v in getattr(record, "fields", {}).items()}
        return True

class JsonFormatter(logging.Formatter):
    def format(self, record):
        return json.dumps({"level": record.levelname, "event": record.getMessage(),
                           **record.fields})

handler = logging.StreamHandler()
handler.addFilter(Redact())
handler.setFormatter(JsonFormatter())
log = logging.getLogger("auth")
log.addHandler(handler)

request = {"user": "alice", "password": "FAKE-correct-horse-batery", "ip": "10.0.0.5"}
log.warning("login_failed", extra={"fields": request})
print("request still intact:", request["password"])

$ python login_json.py
{"level": "WARNING", "event": "login_failed", "user": "alice", "password": "[REDACTED]", "ip": "10.0.0.5"}
request still intact: FAKE-correct-horse-batery

The event keeps what an investigator needs: who (user), what (login_failed), where from (ip), and the outcome (WARNING). The password field is still visibly present but carries [REDACTED], so a reader can see it was deliberately removed rather than lost. The filter builds a new dict instead of editing the original, which is why the last line shows the request object untouched. The code that checks the password still needs it. Putting the filter on the handler means it runs for every record that handler writes, including records from other loggers that propagate to it. The best fix is still not to pass secrets to the logger at all. The filter is the safety net for when someone does.

Log injection: one event, two lines

Usernames come from the attacker. In a plain-text log, a newline in the username starts a new line, and the attacker gets to write it.

# log_injection.py
import json, logging, sys

logging.basicConfig(level=logging.INFO, format="%(levelname)s %(message)s", stream=sys.stdout)
log = logging.getLogger("auth")

username = "mallory\nINFO login ok: user=admin"    # attacker-chosen

print("--- plain text log ---")
log.warning("login failed: user=%s ip=%s", username, "203.0.113.9")
print("--- JSON log ---")
print(json.dumps({"level": "WARNING", "event": "login_failed",
                  "user": username, "ip": "203.0.113.9"}))

$ python log_injection.py
--- plain text log ---
WARNING login failed: user=mallory
INFO login ok: user=admin ip=203.0.113.9
--- JSON log ---
{"level": "WARNING", "event": "login_failed", "user": "mallory\nINFO login ok: user=admin", "ip": "203.0.113.9"}

The plain-text log now shows a successful admin login that never happened. Anyone grepping for login ok, or a tool that parses one event per line, believes it. The trailing ip=... from the real format string even completes the forgery. The JSON version escapes the newline as \n inside the string, so the event stays on one line and the strange username is visible as data. Structured logging fixes this as a side effect. With plain-text logs, escape or strip control characters from every user-supplied value.

From logs to an alert: 5 failures in 60 seconds

A log nobody reads detects nothing. This counter keeps a sliding window of failure timestamps per user and fires once when the count reaches the limit.

# alert.py
from collections import defaultdict, deque

WINDOW, LIMIT = 60, 5                     # 5 failures within 60 seconds
recent = defaultdict(deque)

def on_login_failed(user, ts):
    q = recent[user]
    q.append(ts)
    while ts - q[0] >= WINDOW:            # forget failures older than the window
        q.popleft()
    if len(q) == LIMIT:
        print(f"ALERT user={user} {LIMIT} failures in {WINDOW}s (t={ts})")

events = ([("alice", t) for t in (0, 8, 15, 21, 30, 34)] +
          [("bob", t) for t in (0, 50, 100, 150, 200, 250)])
for user, ts in sorted(events, key=lambda e: e[1]):
    on_login_failed(user, ts)
print("bob's failures in his last window:", len(recent["bob"]))

$ python alert.py
ALERT user=alice 5 failures in 60s (t=30)
bob's failures in his last window: 2

alice’s fifth failure arrives at t=30, inside the window, and the alert fires exactly once. The sixth, at t=34, takes the count to 6, not 5, so it doesn’t fire again. bob fails six times too, but 50 seconds apart, so his window never holds more than two. That’s the gap in any single-threshold rule: a patient attacker stays under it. The third practice task closes it with a second, longer window. In production, this logic runs in a SIEM or log pipeline over the JSON events above, and the alert goes to an on-call channel. Alerting and Runbooks covers the step from firing to delivered.

Practice

1. Secrets in free text. Key-based redaction misses a token embedded in a message string, such as "Authorization: Bearer ...", or a password in a logged URL. Write a filter that redacts by pattern, and show a line before and after adding it.

# redact_text.py
import logging, re

PATTERN = re.compile(r"(Bearer\s+|password=)\S+", re.IGNORECASE)

class RedactText(logging.Filter):
    def filter(self, record):
        record.msg = PATTERN.sub(r"\1[REDACTED]", record.getMessage())
        record.args = ()
        return True

logging.basicConfig(format="%(levelname)s %(message)s")
log = logging.getLogger("http")
log.warning("upstream 401, sent %s", "Authorization: Bearer FAKE-tok-123abc")

log.addFilter(RedactText())
log.warning("upstream 401, sent %s", "Authorization: Bearer FAKE-tok-123abc")
log.warning("retrying with url=https://api.test/login?user=alice&password=FAKE-pw1")

$ python redact_text.py
WARNING upstream 401, sent Authorization: Bearer FAKE-tok-123abc
WARNING upstream 401, sent Authorization: Bearer [REDACTED]
WARNING retrying with url=https://api.test/login?user=alice&password=[REDACTED]

2. Detect password spraying. A spray tries one common password against many accounts, so no single user reaches 5 failures. Alert when one source IP fails logins for 5 different users within 60 seconds.

# spray.py
from collections import defaultdict, deque

WINDOW, DISTINCT = 60, 5                  # 5 different users from one IP in 60 s
recent = defaultdict(deque)               # ip -> deque of (ts, user)

def on_login_failed(user, ip, ts):
    q = recent[ip]
    q.append((ts, user))
    while ts - q[0][0] >= WINDOW:
        q.popleft()
    users = {u for _, u in q}
    if len(users) == DISTINCT:
        print(f"ALERT ip={ip} failed logins for {DISTINCT} users in {WINDOW}s: {sorted(users)}")

events = [(u, "203.0.113.9", t) for t, u in enumerate(["ann", "ben", "cy", "dee", "eve"], 1)]
events += [("alice", "10.0.0.5", t) for t in (2, 4)]
for user, ip, ts in sorted(events, key=lambda e: e[2]):
    on_login_failed(user, ip, ts)

$ python spray.py
ALERT ip=203.0.113.9 failed logins for 5 users in 60s: ['ann', 'ben', 'cy', 'dee', 'eve']

3. Catch the slow attacker. Run two rules at once over the same events: the 5-in-60s burst rule, and a 5-in-300s “slow” rule. Does bob trigger anything now?

# two_rules.py
from collections import defaultdict, deque

RULES = [(60, 5, "burst"), (300, 5, "slow")]       # (window seconds, limit, name)
recent = defaultdict(deque)

def on_login_failed(user, ts):
    q = recent[user]
    q.append(ts)
    while ts - q[0] >= max(w for w, _, _ in RULES):
        q.popleft()
    for window, limit, name in RULES:
        count = sum(1 for t in q if ts - t < window)
        if count == limit:
            print(f"ALERT[{name}] user={user} {limit} failures in {window}s (t={ts})")

events = ([("alice", t) for t in (0, 8, 15, 21, 30, 34)] +
          [("bob", t) for t in (0, 50, 100, 150, 200, 250)])
for user, ts in sorted(events, key=lambda e: e[1]):
    on_login_failed(user, ts)

$ python two_rules.py
ALERT[burst] user=alice 5 failures in 60s (t=30)
ALERT[slow] user=alice 5 failures in 300s (t=30)
ALERT[slow] user=bob 5 failures in 300s (t=200)