Logs

What makes a log line useful

A log records one event: a request handled, a reading rejected, a job finished. Metrics tell you that 4% of readings fail; logs tell you which ones, with which error. A log line earns its place when someone can use it at 3 a.m. without the source code open. That takes a few fixed fields on every line:

• A timestamp in ISO 8601, in Coordinated Universal Time (UTC) or with an explicit offset, to the millisecond.
• A level (next section).
• The service and instance that wrote it.
• A short, fixed message such as "reading rejected", with the variable parts in separate fields, not glued into the sentence.
• The context needed to act: a correlation ID, the meter or run it concerns, the error, the duration.

Writing these as named fields instead of free text is structured logging, introduced with Bash and PowerShell in the Scripting topic and for the cloud in Monitoring, Logging and Observability. Two text formats dominate.

logfmt

logfmt is a log format with one event per line as space-separated key=value pairs, where a value containing spaces is put in double quotes. It is readable for people and trivial for machines. Prometheus and Alertmanager use it by default. The first lines of Prometheus starting on Kestrel's test monitoring server:

time=2026-10-06T19:03:13.177+02:00 level=INFO source=main.go:933 msg="Starting Prometheus Server" mode=server version="(version=3.15.0, branch=HEAD, revision=5241a27fe3c6983549fccc32f6e65917408c63cd)"
time=2026-10-06T19:03:13.177+02:00 level=INFO source=main.go:938 msg="operational information" build_context="(go=go1.27.1, platform=linux/arm64, user=root@4635dd007a60, date=20260925-07:36:49, tags=netgo,builtinassets)" host_details="(Linux 6.12.25 … aarch64 monitor01 (none))" fd_limits="(soft=1048576, hard=1048576)" vm_limits="(soft=unlimited, hard=unlimited)"
time=2026-10-06T19:03:13.429+02:00 level=INFO source=web.go:727 msg="Start listening for connections" component=web address=localhost:9090
time=2026-10-06T19:03:13.429+02:00 level=INFO source=main.go:1499 msg="Starting TSDB ..."
time=2026-10-06T19:03:13.431+02:00 level=INFO source=tls_config.go:381 msg="Listening on" component=web address=localhost:9090
time=2026-10-06T19:03:13.431+02:00 level=INFO source=tls_config.go:384 msg="TLS is disabled." component=web http2=false address=localhost:9090

Every line has time, level, source and msg, followed by fields that depend on the event. The time is local time with its offset (+02:00), which is unambiguous; plain UTC is easier to compare across servers in different time zones. A logfmt line takes a few lines of Python to parse. Here are two lines Prometheus wrote after someone typed 15sec instead of 15s in its configuration and asked it to reload:

import re

# Two lines from Prometheus' own log (logfmt), as written after a bad reload
LINES = r'''time=2026-10-06T19:38:10.516+02:00 level=INFO source=main.go:1721 msg="Loading configuration file" filename=prometheus.yml
time=2026-10-06T19:38:10.516+02:00 level=ERROR source=main.go:1420 msg="Error reloading config" err="couldn't load configuration (--config.file=\"prometheus.yml\"): parsing YAML file prometheus.yml: unknown unit \"sec\" in duration \"15sec\""'''

# key=value, where a value with spaces is in double quotes and may contain \" or \\
PAIR = re.compile(r'([^\s=]+)=("(?:[^"\\]|\\.)*"|\S*)')


def parse_logfmt(line):
    fields = {}
    for key, value in PAIR.findall(line):
        if value.startswith('"'):
            value = re.sub(r'\\(.)', r'\1', value[1:-1])   # drop the quotes, undo escapes
        fields[key] = value
    return fields


for line in LINES.splitlines():
    event = parse_logfmt(line)
    if event["level"] in ("WARN", "ERROR"):
        print(event["time"], event["level"], event["msg"])
        print("  err:", event["err"])

2026-10-06T19:38:10.516+02:00 ERROR Error reloading config
  err: couldn't load configuration (--config.file="prometheus.yml"): parsing YAML file prometheus.yml: unknown unit "sec" in duration "15sec"

Note the escaped quotes inside the err value: a parser that splits on spaces and quotes naively breaks on exactly the lines you need most, the ones that carry error messages.

JSON lines

The other common format is one JavaScript Object Notation (JSON) object per line, also called JSON Lines. It is harder to read by eye, but types survive (a number stays a number) and nested data fits. Most log platforms read it without any parsing rules. Alertmanager writes JSON when started with --log.format=json:

$ alertmanager --config.file=alertmanager.yml --storage.path=/home/amara/kestrel-observability/am-data \
    --web.listen-address=localhost:9093 --cluster.listen-address="" --log.format=json

{"time":"2026-10-06T19:44:00.570998285+02:00","level":"INFO","source":"app.go:194","msg":"Starting Alertmanager","version":"(version=0.34.1, branch=HEAD, revision=73c6bfe7393929211294c1954f30d8ed78e4d0ad)"}
{"time":"2026-10-06T19:44:00.571112619+02:00","level":"INFO","source":"app.go:196","msg":"Build context","build_context":"(go=go1.26.8, platform=linux/arm64, user=root@d3b71085e163, date=20260917-07:45:14, tags=netgo)"}
{"time":"2026-10-06T19:44:00.609331402+02:00","level":"INFO","source":"tls_config.go:372","msg":"Listening on","address":"localhost:9093"}
{"time":"2026-10-06T19:44:00.609392328+02:00","level":"INFO","source":"tls_config.go:375","msg":"TLS is disabled.","http2":false,"address":"localhost:9093"}

Same fields, different syntax. Pick one format per organization so that every service can be searched the same way; Kestrel's own services write JSON.

Log levels as a policy

A log level is the importance a program assigns to a log message, such as DEBUG, INFO, WARNING or ERROR. It lets you filter what is stored and what is read, and it should mean the same thing in every service. The levels themselves come from the logging library; what they mean is a team agreement. Kestrel's:

The syslog column maps Python's names onto the eight syslog severity levels of RFC 5424, which network devices and many Linux daemons use. Python's root logger shows WARNING and above unless you configure it otherwise, which is why a forgotten logging.basicConfig makes INFO lines silently disappear.

Alertmanager shows a good level policy in action. When a notification could not be delivered, it logged one WARN line at the first failed attempt and kept retrying; five minutes later it gave up and logged one ERROR line with the number of attempts:

time=2026-10-06T19:38:50.525+02:00 level=WARN source=retry_stage.go:165 msg="Notify attempt failed, will retry later" component=dispatcher receiver=ops-tickets integration=webhook[0] aggrGroup="{}:{alertname=\"TestNotification\", job=\"alertmanager-test\"}" attempts=1 err="Post \"<redacted>\": dial tcp 127.0.0.1:5001: connect: connection refused"
time=2026-10-06T19:43:50.530+02:00 level=ERROR source=dispatch.go:589 msg="Notify for alerts failed" component=dispatcher aggrGroup="{}:{alertname=\"TestNotification\", job=\"alertmanager-test\"}" num_alerts=1 err="ops-tickets/webhook[0]: notify retry canceled after 14 attempts: Post \"<redacted>\": dial tcp 127.0.0.1:5001: connect: connection refused"

One WARN while there is still hope, one ERROR when it really failed, and no line for each of the 14 attempts in between. Note also that Alertmanager writes the webhook address as <redacted>: webhook URLs often contain a secret.

Structured logging with Python's logging module

Python's standard library has no JSON formatter, but writing one is short. The formatter below turns each log record into one JSON object, with a UTC timestamp and every field the caller passes with extra={…}. It also adds a correlation ID, which the next section explains.

import contextvars
import json
import logging
import sys
from datetime import datetime, timezone

# The correlation ID of the request this code is working on right now
request_id = contextvars.ContextVar("request_id", default="-")


class JsonFormatter(logging.Formatter):
    """One JSON object per line, UTC timestamps, extra fields included."""

    STANDARD = set(vars(logging.makeLogRecord({}))) | {"message"}

    def format(self, record):
        event = {
            "time": datetime.fromtimestamp(record.created, timezone.utc)
            .isoformat(timespec="milliseconds")
            .replace("+00:00", "Z"),
            "level": record.levelname,
            "service": "meter-api",
            "logger": record.name,
            "msg": record.getMessage(),
            "request_id": request_id.get(),
        }
        # anything passed with extra={...} becomes a field of its own
        event.update({k: v for k, v in vars(record).items() if k not in self.STANDARD})
        return json.dumps(event)


class FixedClock(logging.Filter):
    """For this page only: a fixed time, so the output never changes."""

    def filter(self, record):
        record.created = datetime(2026, 10, 6, 17, 9, 12, 345000, timezone.utc).timestamp()
        return True


handler = logging.StreamHandler(sys.stdout)
handler.setFormatter(JsonFormatter())
handler.addFilter(FixedClock())
logging.basicConfig(level=logging.INFO, handlers=[handler])
log = logging.getLogger("meterapi.readings")


def store_reading(meter):
    # no ID passed in: the context variable carries it
    log.warning("database slow, retrying", extra={"meter": meter, "attempt": 2})


def handle_request(incoming_id, meter):
    request_id.set(incoming_id)
    log.info("reading received", extra={"meter": meter})
    store_reading(meter)


handle_request("4bf92f3577b34da6a3ce929d0e0e4736", "M-104317")

{"time": "2026-10-06T17:09:12.345Z", "level": "INFO", "service": "meter-api", "logger": "meterapi.readings", "msg": "reading received", "request_id": "4bf92f3577b34da6a3ce929d0e0e4736", "meter": "M-104317"}
{"time": "2026-10-06T17:09:12.345Z", "level": "WARNING", "service": "meter-api", "logger": "meterapi.readings", "msg": "database slow, retrying", "request_id": "4bf92f3577b34da6a3ce929d0e0e4736", "meter": "M-104317", "attempt": 2}

store_reading never receives the request ID, yet its line carries it: the formatter reads it from a contextvars.ContextVar, which holds a separate value per request even in threaded or asyncio code. The FixedClock filter is only there so this page shows the same output every time; leave it out in real code.

Correlation IDs

A correlation ID is a unique identifier assigned to one request or job when it enters the system, passed along to every service it reaches and written on every log line about it. Searching for that one value then returns the whole story, from the portal on web01 through meter-api to the database query on db01, in order. Without it, correlating logs means matching timestamps by hand and hoping.

• Create the ID at the edge: the load balancer or the first service that receives the request. Reuse an incoming ID if the caller sent one you trust.
• Pass it on in a header with every outgoing call and message. The best choice is the trace ID of the W3C traceparent header, as in the example above: then every log line links straight to the trace (see context propagation).
• Show it to users on error pages ("Reference: 4bf92f35"). When a customer calls the service desk, Mei Chen's team puts the reference in the ticket, and the engineer finds the exact request in seconds.
• Batch jobs need one too. Joost Bakker's billing export writes a run_id on every line, so the 02:30 run of 6 October can be followed through every step and service it touches.

What not to log

Logs are copied to central storage, read by many people, backed up, and kept for weeks or months. Anything in a log line is effectively published to everyone with log access. Never log:

• Passwords, also not the wrong ones (a mistyped password is often one character away from the real one).
• Access tokens, API keys, session cookies, the Authorization header, and URLs with secrets in them.
• Full payment card numbers and national identification numbers, such as the Dutch BSN, the US Social Security number or the UK National Insurance number.
• Complete request bodies of forms with personal data, such as a change of address or a payment arrangement.

Most leaks are not deliberate. A developer logs "the whole request for debugging", or an exception message includes the database connection string. The defense is a redaction step that runs on every line, whatever the developer wrote.

Redaction

Log redaction is removing or masking sensitive values from log data before it is stored or shipped, usually by a filter in the application's logging setup or in the log shipper. Kestrel's portal once logged failed logins with the whole form. The redaction step drops the password, masks the token, truncates the IP address to its /24 network and replaces the customer number with a pseudonym:

import hashlib
import hmac
import ipaddress
import json

# In real use the key comes from a secret store, never from the code
PSEUDONYM_KEY = b"demo-key-for-this-page-only"
DROP = {"password", "session_cookie"}          # never stored, not even masked
MASK = {"authorization", "token"}              # keep that it was there, not what it was


def pseudonymize(value):
    """Same input, same output, so lines can still be grouped by customer."""
    digest = hmac.new(PSEUDONYM_KEY, value.encode(), hashlib.sha256).hexdigest()
    return "cust-" + digest[:12]


def redact(event):
    clean = {}
    for key, value in event.items():
        if key in DROP:
            continue
        if key in MASK:
            clean[key] = "[REDACTED]"
        elif key == "customer_number":
            clean["customer"] = pseudonymize(value)
        elif key == "client_ip":
            network = ipaddress.ip_network(f"{value}/24", strict=False)
            clean["client_net"] = str(network)
        else:
            clean[key] = value
    return clean


failed_login = {
    "time": "2026-10-06T17:21:04Z",
    "level": "INFO",
    "event": "login_failed",
    "customer_number": "900-555-0142",
    "password": "not-a-real-password",
    "client_ip": "198.51.100.77",
    "authorization": "Bearer example-token-123",
    "reason": "wrong_password",
}
print(json.dumps(redact(failed_login)))

{"time": "2026-10-06T17:21:04Z", "level": "INFO", "event": "login_failed", "customer": "cust-37c2d2c2319b", "client_net": "198.51.100.0/24", "authorization": "[REDACTED]", "reason": "wrong_password"}

The pseudonym is a keyed hash (HMAC), not a plain hash. Customer numbers have a small, predictable format; without a secret key, anyone could hash every possible number and reverse the pseudonym in minutes. With the key, the same customer still gets the same pseudonym, so you can count failed logins per customer without seeing who it is.

Retention and privacy

Logs about people are personal data, and privacy law applies to them like to any other database. That includes data you might not think of as personal: customer numbers, meter IDs that belong to a household, user agents, and IP addresses.

In practice: treat IP addresses in logs as personal data.

Two data protection principles matter most for logs. Data minimization: log what you need for operating and securing the service, nothing more. Storage limitation: keep it no longer than that purpose requires. Privacy law (the GDPR, the UK GDPR or the CCPA) sets no fixed number of days; you choose a period, write down why, and make sure deletion really happens.

A retention period is how long a kind of log is kept before it is deleted automatically. Set one per log type, not one for everything. Kestrel's policy (a policy choice made with its privacy officer, not a legal rule):

Security logs follow their own rules and live in a separate, protected store; see what to log in the Security topic. For how a central store applies retention and what it costs, see Logs at Scale and the retention and deletion section of the privacy page.

Volume, cost and log sampling

Logs are the most expensive signal. meter-api receives hundreds of readings per second; three lines per reading make tens of millions of lines a day, nearly all of them saying "fine". Central log services charge per gigabyte ingested and stored, and a search over too much data is slow just when you are in a hurry.

Log sampling means keeping only a fraction of routine log lines, while keeping every warning and error. Done naively ("keep each line with 10% chance"), you get fragments: line 1 of a request but not line 2. Decide per request instead, by hashing its correlation ID, so all lines of a request are kept or dropped together, on every server:

import hashlib
import random

KEEP_PERCENT = 10      # keep 10% of ordinary requests


def keep(request_id, level):
    """Keep every warning and error; keep a fixed 10% of the rest, per request."""
    if level in ("WARNING", "ERROR", "CRITICAL"):
        return True
    # Hash the ID instead of rolling a die: every line of the same request
    # gets the same answer, on every server, so a kept request is complete.
    bucket = int(hashlib.sha256(request_id.encode()).hexdigest(), 16) % 100
    return bucket < KEEP_PERCENT


rng = random.Random(42)                     # seeded: same "traffic" on every run
lines = kept = errors = errors_kept = 0
for _ in range(20_000):
    request_id = f"{rng.getrandbits(128):032x}"
    failed = rng.random() < 0.004           # 0.4% of requests fail
    for level in ("INFO", "INFO", "ERROR" if failed else "INFO"):
        lines += 1
        errors += level == "ERROR"
        if keep(request_id, level):
            kept += 1
            errors_kept += level == "ERROR"

print(f"log lines written: {lines:,}")
print(f"log lines kept:    {kept:,} ({kept / lines:.1%})")
print(f"error lines kept:  {errors_kept} of {errors}")

log lines written: 60,000
log lines kept:    6,058 (10.1%)
error lines kept:  78 of 78

All 78 error lines survive. Note one limit: a failed request outside the 10% keeps its ERROR line, but not the INFO lines that led up to it. When those matter, use a trace with tail sampling instead (see sampling in Distributed Tracing), or count routine events as metrics and log only the exceptions.

Getting logs off the machine

A log that exists only on the server that wrote it is lost when the container is replaced, cannot be searched together with the logs of the other servers, and can be wiped by an attacker who gains access. Logs must leave the machine while they are written.

A log shipper is an agent that collects log lines on a host (from files, the systemd journal or container output), optionally parses, enriches and redacts them, and forwards them to a central log store, buffering them while that store is unreachable.

Common choices, as of October 2026:

• syslog forwarding with rsyslog or systemd-journald's own forwarding, the traditional route for Linux hosts and network devices (see syslog).
• Grafana Alloy, Fluent Bit, Vector and the OpenTelemetry Collector (see OpenTelemetry) for modern pipelines that also parse, redact and route.
• In containers, write logs to standard output and let the platform collect them (see docker logs).

Two details decide whether shipped logs are trustworthy. Clocks: all hosts must run NTP, or the merged timeline lies about the order of events. And the shipper itself needs monitoring: a shipper that silently stopped a week ago looks exactly like a quiet week.

Using logs during an incident

In INC-22047 on 6 October (recorded here on the test setup), the meter-api error ratio climbed from 0.02% to 8% within minutes after 17:09 UTC. The alert comes from a metric; the explanation is usually in the logs. An order that works:

1. Start from the metric and narrow the time window and service: meter-api, from 17:05 UTC.
2. Filter on level ERROR and group by the msg field. Fixed messages make this possible: one message repeated thousands of times is one problem, not thousands.
3. Find the first error of the incident; later errors are often consequences.
4. Pick one failed request and search its correlation ID across all services to see the whole path, or open its trace.

Logs are good at detail and bad at overview. To answer "how many, how fast, how often", turn the question into a metric. To answer "where did this one request spend its time", use a trace.