lesson 240 Observability & Operations · advanced

Investigate a failure from the logs

When the alert fires, the evidence is already in the logs. Because they are structured, a short program can follow one request's trace, group the errors by kind and find the first failure, which is usually the cause, rather than the loudest one.

You'll be able to

Parse JSON log lines defensively, skipping lines that aren't JSON
Reconstruct one request's timeline by trace id and time
Separate cause from symptoms: the first error in a trace, and error counts by type

The idea

An alert says the star API's error rate jumped at 09:00. The logs from the API and the database worker hold the story, but thousands of lines of it. Because each line is a JSON object (L01) with a trace id (L03), three small questions get you most of the way:

What happened to one failing request? Filter by its trace id and sort by time.
What kinds of errors are there, and how many? Group the ERROR lines by their error field.
What failed first? In each failing trace, the earliest error is the likely cause; later errors (a 500 returned to the user, a retry giving up) are symptoms.

ISO timestamps like 2025-03-03T09:00:02.150Z sort correctly as text, so no date parsing is needed to order them.

Run each example to see what it prints. Running examples doesn't count toward progress.

example-1.py · One request's timeline

import json

log = [
    '{"time": "2025-03-03T09:00:01.020Z", "level": "INFO", "service": "api", "trace": "t-7f3a", "message": "request started"}',
    '{"time": "2025-03-03T09:00:01.030Z", "level": "INFO", "service": "api", "trace": "t-91c0", "message": "request started"}',
    '{"time": "2025-03-03T09:00:03.045Z", "level": "ERROR", "service": "api", "trace": "t-7f3a", "message": "responded 500", "error": "TimeoutError"}',
    '{"time": "2025-03-03T09:00:01.050Z", "level": "INFO", "service": "db", "trace": "t-7f3a", "message": "query started"}',
    '{"time": "2025-03-03T09:00:03.040Z", "level": "ERROR", "service": "db", "trace": "t-7f3a", "message": "query failed", "error": "OperationalError"}',
    '{"time": "2025-03-03T09:00:01.090Z", "level": "INFO", "service": "api", "trace": "t-91c0", "message": "responded 200"}',
]

entries = [json.loads(line) for line in log]
timeline = sorted((e for e in entries if e["trace"] == "t-7f3a"), key=lambda e: e["time"])
for e in timeline:
    print(e["time"][11:23], e["level"], e["service"], e["message"], e.get("error", ""))

Real log files are never perfectly clean: a library prints a plain warning, a line is cut off when a process dies. A one-line comprehension that parses everything stops at the first such line:

example-2.py · One stray line stops the investigation

import json

log = [
    '{"time": "2025-03-03T09:00:01.020Z", "level": "INFO", "trace": "t-7f3a", "message": "request started"}',
    'WARNING: connection pool is almost full',
    '{"time": "2025-03-03T09:00:03.045Z", "level": "ERROR", "trace": "t-7f3a", "message": "responded 500"}',
]
entries = [json.loads(line) for line in log]
print(len(entries))

With entries parsed safely, counting errors by type shows what is common, and the first error of each trace shows what *starts* failures. They can disagree: here every failing request ends in a TimeoutError at the API, but each one started with a database error.

example-3.py · Symptoms and causes

import json
from collections import Counter

def read_entries(lines):
    entries = []
    for line in lines:
        try:
            entry = json.loads(line)
        except json.JSONDecodeError:
            continue
        if isinstance(entry, dict):
            entries.append(entry)
    return entries

log = [
    '{"time": "09:00:03.040", "level": "ERROR", "service": "db", "trace": "t-7f3a", "error": "OperationalError"}',
    '{"time": "09:00:03.045", "level": "ERROR", "service": "api", "trace": "t-7f3a", "error": "TimeoutError"}',
    'WARNING: connection pool is almost full',
    '{"time": "09:00:04.100", "level": "ERROR", "service": "db", "trace": "t-2b55", "error": "OperationalError"}',
    '{"time": "09:00:04.110", "level": "ERROR", "service": "api", "trace": "t-2b55", "error": "TimeoutError"}',
    '{"time": "09:00:04.200", "level": "ERROR", "service": "api", "trace": "t-c41d", "error": "TimeoutError"}',
    '{"time": "09:00:04.150", "level": "ERROR", "service": "db", "trace": "t-c41d", "error": "OperationalError"}',
    '{"time": "09:00:05.000", "level": "INFO", "service": "api", "trace": "t-e9a2", "message": "responded 200"}',
]

errors = [e for e in read_entries(log) if e["level"] == "ERROR"]
print(Counter(e["error"] for e in errors).most_common())

first = {}
for e in sorted(errors, key=lambda e: e["time"]):
    first.setdefault(e["trace"], (e["service"], e["error"]))
print(Counter(first.values()))

When to use it: during and after any incident, and to check that a fix worked (the first-failure counts drop to zero). Mistakes to avoid: parsing logs with an all-or-nothing comprehension; reading lines in file order instead of time order; treating the most frequent or last error as the cause; and investigating without a trace id, which is why L03 puts one on every record.

Review

Parse log lines one at a time and skip what isn't a JSON object.
Follow a trace by id in time order; ISO times sort as text.
Count errors by type to see what is common, and find each trace's first error to see what starts failures.
Next module: delivering the program itself. The Application Delivery module: dependency locking, containers, CI and deployment checks.

Practise this