Logging and Monitoring

At 3:40 AM the API returned 500 Internal Server Error to an agent in eu-west. You open the server output and find ten thousand lines of print("here"), print(data), and print("done")—no timestamps, no severity levels, no request IDs, and no way to turn off the debug noise without editing code and redeploying. print() is for learning and CLI output. In a running service, logging and structured telemetry are how you know what broke and why.

Python’s logging module categorizes messages into five standard severity levels, ordered by numeric weight:

• DEBUG (10): step-by-step diagnostics needed only when troubleshooting
• INFO (20): normal lifecycle milestones (service started, batch completed)
• WARNING (30): something unexpected happened (retry 1/3), but the job recovered
• ERROR (40): an operation failed and could not complete
• CRITICAL (50): the whole service cannot continue

Create a module-level logger with logger = logging.getLogger(__name__). When the threshold level is set to INFO, logger.debug(...) calls are skipped automatically without you deleting a single line of code.

import logging
import sys

handler = logging.StreamHandler(sys.stdout)
handler.setFormatter(logging.Formatter("%(levelname)s [%(name)s] %(message)s"))

logger = logging.getLogger("ops.scanner")
logger.handlers = [handler]
logger.setLevel(logging.INFO)

logger.debug("Raw payload bytes: 1024")            # ignored when level is INFO
logger.info("Sweep started for 3 hosts")
logger.warning("srv-02 responded slowly (940ms)")
logger.error("srv-07 connection refused")

Human-readable log lines like "srv-02 responded slowly (940ms)" force you right back into Week 7’s regex parsing the moment you want to filter by latency_ms > 500 across a million lines.

Structured logging formats every log event as a single-line JSON object with consistent keys (timestamp, level, event, host, latency_ms). Log aggregators index those keys automatically so you can query level == "ERROR" and region == "eu" without writing a single regular expression.

import json

def log_event(level: str, event: str, **fields) -> str:
    record = {"level": level.upper(), "event": event, **fields}
    line = json.dumps(record, sort_keys=True)
    print(line)
    return line

log_event("info", "probe_completed", host="srv-01", latency_ms=42.5, status="OK")
log_event("error", "probe_failed", host="srv-07", reason="timeout", timeout_s=10)

Watch out: The Trap

• Logging sensitive fields like password, api_key, or Authorization headers when dumping **fields or request dictionaries. Redact secrets before serializing.
• Calling logger.error(f"Failed: {exc}") instead of logger.exception("Failed") inside an except block. logger.exception() attaches the full stack trace automatically; str(exc) throws away the line number where the error happened.
• Configuring logging.basicConfig() at the top of a shared library module. Only the application entrypoint should configure handlers and levels.

When fifty async requests run concurrently on the same event loop (Week 16), their log lines interleave. How do you know which database query log belonged to which incoming HTTP request?

Attach a unique correlation ID (request_id) to each incoming request using Python’s contextvars.ContextVar. Unlike a global variable that concurrent tasks would overwrite, a ContextVar keeps an isolated value per async task or call chain automatically, so every log helper can read current_request_id.get() without you threading request_id through fifteen function signatures.

from contextvars import ContextVar

request_id_var: ContextVar[str] = ContextVar("request_id", default="system")

def log_step(step: str) -> str:
    rid = request_id_var.get()
    msg = f"[{rid}] {step}"
    print(msg)
    return msg

token = request_id_var.set("req-409")
try:
    log_step("validated payload")
    log_step("updated ops.db")
finally:
    request_id_var.reset(token)

log_step("background cleanup")

Logs tell you what happened to one request; metrics tell you the health of the whole system in numbers: total requests, error rate, and latency percentiles.

When measuring elapsed time in Python, never use time.time(). System clocks can jump backward or forward when NTP syncs the server’s clock. Always use time.perf_counter() (or time.monotonic()), which is guaranteed to move forward at a steady rate. Combine a @contextmanager timer with an in-memory metrics collector to track call counts, error counts, and elapsed milliseconds.

import time
from contextlib import contextmanager

class MetricsCollector:
    def __init__(self) -> None:
        self.counters: dict[str, int] = {}
        self.timings_ms: list[float] = []

    def inc(self, name: str, amount: int = 1) -> None:
        self.counters[name] = self.counters.get(name, 0) + amount

    @contextmanager
    def timer(self, metric_name: str):
        start = time.perf_counter()
        try:
            yield
            self.inc(f"{metric_name}.ok")
        except Exception:
            self.inc(f"{metric_name}.err")
            raise
        finally:
            elapsed_ms = (time.perf_counter() - start) * 1000
            self.timings_ms.append(round(elapsed_ms, 2))

metrics = MetricsCollector()
with metrics.timer("db_write"):
    pass

print(metrics.counters, len(metrics.timings_ms))

Watch out: The Trap

• Using time.time() to measure duration. A clock sync mid-request can produce a negative latency (-12.4ms) and corrupt your metrics. Use time.perf_counter().
• Unbounded metric labels (putting a unique request_id or timestamp inside a counter name like metrics.inc(f"req_{request_id}")). Your dictionary grows forever until the process runs out of memory. Keep counter names to a small fixed vocabulary ("db_write.ok", "db_write.err") and put high-cardinality IDs in logs.

Your service no longer flies blind. It emits severity-leveled logs, serializes structured JSON events with secrets redacted, stamps concurrent operations with a ContextVar correlation ID, and measures latency with monotonic timers. Next week we move slow work—like sending webhook alerts and generating PDF/CSV digests—out of the HTTP request path using background queues and idempotent workers.