Structured Logging Best Practices, in depth: event schemas, context propagation, trace correlation, redaction and volume control

From strings to events

Think of each log call as emitting an event: something happened, at a time, in a context, with attributes. The message should be a constant identifier for the kind of event, and every variable part should be a field. A constant event name is what makes logs countable and alertable; a message assembled with f-strings produces a unique string per occurrence that no query can group.

# Unstructured: the facts are trapped in prose
log.warning(f"Payment failed for user {user_id} after {n} retries: {err}")

# Structured (stdlib logging, formatter below): constant event name, typed fields
log.warning("payment.failed", extra={"fields": {"user_id": user_id, "retries": n,
            "error_type": type(err).__name__, "provider": "acme_pay", "amount_minor": 1999, "currency": "EUR"}})

Fields should keep their types. A number logged as a number can be summed and compared; the same number embedded in a string cannot. Pick one representation per concept and keep it: durations as integer milliseconds in a field named with its unit, such as duration_ms, money as integer minor units plus currency, booleans as booleans. A field that is a number in one service and a string in another causes mapping conflicts in most log backends and silently drops data.

A schema every event shares

Agree on a small set of fields that every event from every service carries, and publish it. Most of these come from configuration or context, not from the developer writing the log call.

For naming, adopt an existing vocabulary rather than inventing one. OpenTelemetry's semantic conventions define attribute names such as service.name, http.request.method and http.response.status_code, and its logs data model has dedicated slots for timestamp, severity, body, trace id, span id and attributes. Elastic Common Schema is the other widely used option. Whichever you choose, use it everywhere so a query written for one service works on all of them; see OpenTelemetry semantic conventions.

Event names deserve a convention too: a dotted domain.action or domain.outcome form such as order.created, payment.failed or cache.miss. Keep a registry of the important ones, because alerts and dashboards depend on them, and renaming an event silently breaks every query built on it.

Levels with a written policy

Levels exist to filter and to route, so they only work if everyone means the same thing by them. A policy that fits most services:

Two rules prevent the usual decay. Do not log the same failure at error level at every layer it passes through; log it once where it is handled and let callers add context to the exception instead. And do not use error for client mistakes such as a 404 or a validation failure: those are normal traffic, and if they page someone the pages get ignored. Errors that need a human should usually also become a metric or an alert; logs are for investigating, not for noticing.

Binding context without passing it everywhere

The fields that make a log useful during an incident, request id, tenant, user, trace id, are known at the edge of the request, not deep inside the code that hits the error. Passing them through every function signature does not scale. In Python, contextvars gives each request, thread or asyncio task its own context, which a logging filter can read. The example below uses only the standard library and the OpenTelemetry API.

import json, logging, sys, time, contextvars
from opentelemetry import trace

_ctx = contextvars.ContextVar("log_ctx", default={})

def bind(**fields):
    """Add fields to every log event for the rest of this request or task."""
    return _ctx.set({**_ctx.get(), **fields})        # returns a token for reset()

ALLOWED = {"event", "level", "user_id", "order_id", "retries", "duration_ms", "error_type",
           "provider", "amount_minor", "currency", "request_id", "tenant_id", "http.route",
           "http.response.status_code", "exception", "dropped_fields"}

LEVELS = {logging.DEBUG: "debug", logging.INFO: "info", logging.WARNING: "warn",
          logging.ERROR: "error", logging.CRITICAL: "error"}

class JsonFormatter(logging.Formatter):
    def __init__(self, service, version, env):
        super().__init__()
        self.static = {"service.name": service, "service.version": version,
                       "deployment.environment": env}

    def format(self, record):
        ev = {"timestamp": time.strftime("%Y-%m-%dT%H:%M:%S", time.gmtime(record.created))
                           + f".{int(record.msecs):03d}Z",
              "level": LEVELS.get(record.levelno, "info"), "event": record.getMessage(), **self.static}
        sc = trace.get_current_span().get_span_context()
        if sc.is_valid:
            ev["trace_id"], ev["span_id"] = f"{sc.trace_id:032x}", f"{sc.span_id:016x}"
        fields = {**_ctx.get(), **getattr(record, "fields", {})}
        if record.exc_info:
            fields["exception"] = self.formatException(record.exc_info)   # one field, not many lines
            fields["error_type"] = record.exc_info[0].__name__
        dropped = [k for k in fields if k not in ALLOWED]             # allowlist, see redaction
        ev.update({k: v for k, v in fields.items() if k in ALLOWED})
        if dropped:
            ev["dropped_fields"] = len(dropped)                          # count only: names can leak too
        return json.dumps(ev, default=str, separators=(",", ":"))

handler = logging.StreamHandler(sys.stdout)
handler.setFormatter(JsonFormatter("checkout", "2.14.3", "prod"))
logging.basicConfig(level=logging.INFO, handlers=[handler])
log = logging.getLogger("checkout")

# middleware
token = bind(request_id="req_01J9ZK4", tenant_id="t_552")
try:
    log.warning("payment.failed", extra={"fields": {"retries": 3, "provider": "acme_pay"}})
finally:
    _ctx.reset(token)

The output is one line of JSON per event, which matters: a stack trace printed across thirty lines becomes thirty separate events in most collectors unless multiline parsing is configured, and that parsing is fragile. Serialising the trace into one field avoids the problem. Writing to stdout and letting the platform's agent collect it keeps the application free of shipping logic and back-pressure; see the OpenTelemetry Collector for the agent side.

Go's standard library has had structured logging since Go 1.21 in log/slog, with a JSON handler and typed attributes:

logger := slog.New(slog.NewJSONHandler(os.Stdout, &slog.HandlerOptions{Level: slog.LevelInfo})).
    With("service.name", "checkout", "service.version", "2.14.3")

// per request: derive a logger carrying request context
reqLog := logger.With("request_id", reqID, "tenant_id", tenantID)
reqLog.Warn("payment.failed", "retries", 3, "provider", "acme_pay", "duration_ms", elapsed.Milliseconds())

In Go the idiom is to pass the derived logger, or a context carrying it, explicitly; a custom handler can extract the trace and span id from the context.Context when you use the ...Context logging methods.

Correlating logs with traces

Logs say what happened; traces say where the time went and which services were involved. Joining them on trace id turns an error log into a click-through to the whole request across services, and lets a slow trace show the log events emitted inside each span. Two conditions must hold. The trace context must actually propagate across every hop, including queues and background jobs, which is covered in trace context propagation. And the ids must be logged in the same format the trace backend uses: W3C trace context ids are lower-case hex, 32 characters for the trace id and 16 for the span id, which is what the formatter above produces.

A subtle failure: when traces are head-sampled, most requests have a valid trace id but no stored trace. The log still carries the id, so the link appears and leads nowhere. Log the sampled flag as well, or make your log viewer check before offering the link.

Keeping secrets and personal data out

Logs are copied widely: to the collector, the backend, backups, and often to vendors and support tools, with access controls far looser than the production database. Anything logged should be assumed readable by many people for the whole retention period. The safe default is an allowlist: the formatter emits only fields that have been declared safe, and anything else is dropped and counted, so developers notice and declare it. A denylist of known-dangerous names such as password or authorization always misses the next one, for example a token inside a URL query string or a full request body logged "temporarily".

Some identifiers are needed for correlation but are personal data. Replace them with a keyed hash (HMAC with a secret held outside the log system) so events for the same user can still be grouped without exposing the value, and note that this is pseudonymisation, not anonymisation, for regulatory purposes. Never log full request or response bodies by default, and treat log retention as a data-protection decision with an owner, not just a storage setting.

Controlling volume and cost

Log cost scales with bytes ingested and indexed, so volume control is part of the design. Do not log inside tight loops; emit one summary event with counts. Rate-limit repeated identical events, such as the same connection error a thousand times a second, by logging the first occurrences and then a periodic count of suppressed ones. Sample high-volume success events, for example 1 in 100 health-check or cache-hit events, and record the sample rate in a field so counts can be scaled back up. Never sample errors.

Keep debug logging off in production by default but switchable at runtime, per service or per tenant, without a redeploy. A useful pattern is to buffer debug events in memory per request and flush them only if the request ends in an error, which gives full detail for failed requests at almost no cost for successful ones.

Testing log output

If alerts and dashboards depend on events, those events are an interface and deserve tests. Capture the handler's output in unit tests and assert on parsed fields, not on strings: the event name, the presence of trace and request ids, field types, and that a value marked secret never appears. A contract test in CI can validate sample events against the published schema, catching a field that changed type before the backend starts rejecting it.

def test_payment_failure_event(caplog_json):          # fixture capturing JSON lines from the handler
    charge(order, provider=failing_provider)
    ev = next(e for e in caplog_json if e["event"] == "payment.failed")
    assert ev["level"] == "warn" and isinstance(ev["retries"], int)
    assert "card_number" not in json.dumps(ev)

Failure modes

Trade-offs

What to do next

1. Publish a shared field schema with required fields, naming convention and types, based on OpenTelemetry or ECS.
2. Replace interpolated messages with constant event names and typed fields, starting with the events your alerts use.
3. Bind request id, tenant and trace and span ids once in middleware so every event carries them.
4. Switch the formatter to an allowlist and replace personal identifiers with keyed hashes.
5. Serialise exceptions into one field and emit one JSON event per line to stdout.
6. Write down the level policy and stop logging handled client errors at error level.
7. Add duplicate suppression and success sampling with the sample rate recorded in a field.
8. Add tests and a CI schema check for the events that dashboards and alerts depend on.