Structured Logging for Python Scrapers

A crawl produces more log lines than any other kind of Python program, and almost all of them are worthless unless they can be queried — which is the first practical problem in Monitoring and Alerting for Scrapers.

The whole technique is one logging.Formatter subclass that serialises each record to a JSON object and writes it to stdout. No third-party library is required, the formatter is about twenty lines, and it is the only place in the codebase that knows how a log line is shaped. That last property is what makes redaction reliable: a filter applied at the formatter cannot be forgotten at a call site.

Why One JSON Object per Line

Log collectors are line-oriented. Docker, containerd, systemd's journal, CloudWatch Logs, Loki and every CI runner read stdout, split on newlines, and treat each line as one record. If that line happens to be valid JSON, the collector parses it into fields and you can ask status >= 500 and spider = "books". If it is prose, you get substring search, which stops being useful the moment two different messages contain the word "error".

The format is usually called newline-delimited JSON, and its constraints follow from the transport:

• One object, one line, no pretty-printing. A pretty-printed object becomes twelve unrelated log records.
• Stable key names. status in one event and status_code in another means two columns and no working query.
• Flat, or nearly flat. Most collectors index one or two levels deep. A deeply nested object survives storage but is awkward to filter on.
• Values with consistent types. A field that is sometimes 200 and sometimes "200" will break numeric comparisons in the collector's index.

There is a second, less obvious payoff. Because the fields are typed and named, alert rules can be written against them instead of against text. "More than 5% of parse events in the last hour had items = 0" is a rule a collector can evaluate; "the log contains the word empty" is not, and it silently stops working the day someone rewords a message. Log messages are written for humans and get edited casually; field names are an interface and get treated as one.

The alternative — writing to a rotating file and shipping it with a sidecar — is worth avoiding in a container. The disk is ephemeral, rotation competes with the collector for the file handle, and a crawl that is killed mid-rotation can lose the segment containing the reason it died. Every deployment shape covered in Deploying Scrapers to the Cloud captures stdout for free.

The Formatter

This is the complete, runnable implementation. It merges three sources of fields: the record's own metadata, anything passed as extra={"fields": {...}} at the call site, and contextual values set once per run.

# scraper/logsetup.py
import contextvars
import json
import logging
import sys
from datetime import datetime, timezone
from typing import Any

# Correlation ids: set once per run and once per URL, read by every record.
run_id_var: contextvars.ContextVar[str] = contextvars.ContextVar("run_id", default="-")
req_id_var: contextvars.ContextVar[str] = contextvars.ContextVar("req_id", default="-")

REDACT_KEYS = frozenset({
    "cookie", "cookies", "set-cookie", "authorization", "proxy-authorization",
    "api_key", "apikey", "token", "password", "secret", "body", "html",
})
REDACTED = "[redacted]"

def _scrub(value: Any, depth: int = 0) -> Any:
    if depth > 3:
        return "[truncated]"
    if isinstance(value, dict):
        return {
            k: (REDACTED if k.lower() in REDACT_KEYS else _scrub(v, depth + 1))
            for k, v in value.items()
        }
    if isinstance(value, (list, tuple)):
        return [_scrub(v, depth + 1) for v in value][:20]
    if isinstance(value, str) and len(value) > 512:
        return value[:512] + "…"
    return value

class JsonFormatter(logging.Formatter):
    """Serialise one LogRecord to a single line of JSON."""

    def format(self, record: logging.LogRecord) -> str:
        payload: dict[str, Any] = {
            "ts": datetime.fromtimestamp(record.created, tz=timezone.utc).isoformat(timespec="milliseconds"),
            "level": record.levelname,
            "event": record.getMessage(),
            "logger": record.name,
            "run_id": run_id_var.get(),
            "req_id": req_id_var.get(),
        }
        fields = getattr(record, "fields", None)
        if isinstance(fields, dict):
            payload.update(_scrub(fields))
        if record.exc_info:
            payload["exc_type"] = record.exc_info[0].__name__ if record.exc_info[0] else "Unknown"
            payload["exc"] = self.formatException(record.exc_info)[-2000:]
        return json.dumps(payload, ensure_ascii=False, default=str, separators=(",", ":"))

def configure(level: int = logging.INFO) -> None:
    handler = logging.StreamHandler(stream=sys.stdout)
    handler.setFormatter(JsonFormatter())
    root = logging.getLogger()
    root.handlers.clear()
    root.addHandler(handler)
    root.setLevel(level)
    logging.getLogger("httpx").setLevel(logging.WARNING)
    logging.getLogger("urllib3").setLevel(logging.WARNING)

Using it in a crawl looks like this — note that the ids are set once and never passed as arguments again:

# scraper/crawl.py
import logging
import uuid
import httpx
from scraper.logsetup import configure, run_id_var, req_id_var

configure()
log = logging.getLogger("scraper")
HEADERS = {"User-Agent": "Mozilla/5.0 (X11; Linux x86_64) monitoring-example/1.0"}

def crawl(urls: list[str]) -> int:
    run_id_var.set(uuid.uuid4().hex[:12])
    log.info("run_start", extra={"fields": {"urls": len(urls)}})
    saved = 0
    with httpx.Client(headers=HEADERS, timeout=15, follow_redirects=True) as client:
        for url in urls:
            req_id_var.set(uuid.uuid4().hex[:8])
            try:
                response = client.get(url)
            except httpx.HTTPError:
                log.exception("fetch_failed", extra={"fields": {"url": url}})
                continue
            log.info("fetch", extra={"fields": {
                "url": url,
                "status": response.status_code,
                "elapsed_ms": int(response.elapsed.total_seconds() * 1000),
                "bytes": len(response.content),
            }})
            saved += 1
    log.info("run_end", extra={"fields": {"pages": saved}})
    return saved

if __name__ == "__main__":
    crawl(["https://books.toscrape.com/", "https://books.toscrape.com/catalogue/page-2.html"])

Every line that run produces carries the same run_id and its own req_id, so run_id = "a1f9…" reconstructs the whole crawl and req_id = "c7b2…" reconstructs one URL's fetch, parse and store. contextvars rather than a global is deliberate: it is the only mechanism that keeps ids correct when the crawl is asynchronous, because each task inherits a copy of the context at creation instead of racing over a shared variable.

What Goes In, and What Must Never

The include list is short because a log line is a schema, not a diary. Timestamp in UTC, level, event name, the two correlation ids, and then the handful of fields specific to the event: URL, status, elapsed milliseconds, byte count, attempt number, item count, and the names of any expected fields that were missing. Add the spider name and a code version — a git SHA from the build — so a regression can be tied to a deploy.

The deny list matters more, because a log store is usually the least-protected place data ends up. It is replicated, retained for months, and readable by anyone with dashboard access.

• Cookie and Set-Cookie headers. A session cookie in a log is a live credential for as long as it is valid, and log retention outlives sessions.
• Authorization and Proxy-Authorization headers, API keys, tokens. Logging the request headers dict is the usual way this happens by accident, which is why _scrub matches on key name rather than on call site.
• Full response bodies. They dominate storage cost, and for logged-in pages they contain other people's data. Log the byte count and a hash if you need to detect change.
• Proxy URLs. http://user:pass@host:port is a credential in a field named proxy. Log the host only.
• Personal data you scraped. Names, emails and addresses in a log store are outside whatever retention and deletion policy the actual dataset has.
• Form fields you posted. Login payloads contain passwords by definition.

The _scrub function above handles all of these by key name, truncates any string over 512 characters, caps lists at twenty elements, and stops recursing at depth three so a hostile or malformed structure cannot make one log line megabytes long.

Log Levels That Mean Something in a Crawl

Levels are only useful if they partition events by what you would do about them, and in a crawl that mapping is unusually clean:

• DEBUG — one line per response. Enormous volume, invaluable when reproducing a specific failure, off in production.
• INFO — run lifecycle and phase transitions: run start, run end, shard finished, checkpoint written. Tens of lines per run, not tens of thousands.
• WARNING — something recoverable and suspicious happened: a retry, a page that parsed to zero items, a redirect to a login page, a field that was missing. This is the level that catches degradation, and it is the one most scrapers misuse.
• ERROR — a URL was abandoned after exhausting retries, or an exception escaped a handler. One per lost URL, not one per attempt.
• CRITICAL — the run cannot continue: the database is unreachable, the proxy pool is empty, credentials were rejected.

The diagnostic value comes from the ratios. A crawl with 12,000 URLs and 38 WARNING lines is healthy. The same crawl with 4,000 WARNING lines is telling you that a quarter of its pages parsed to nothing, and no exception was raised anywhere — exactly the pattern examined in Detecting Silent Scraper Failures.

Edge Cases and Caveats

• Buffered stdout truncates the ending. Python buffers stdout when it is not a terminal, so a crawl killed by SIGKILL or an OOM killer loses up to 8 KB — usually the lines explaining why. Set PYTHONUNBUFFERED=1 in the container image.
• Multi-line exceptions break the one-line rule. The formatter above puts the traceback inside a JSON string field, so newlines are escaped as \n and the record stays on one line. Never let logging.exception() write a raw traceback through a plain formatter alongside JSON lines.
• Non-ASCII in scraped text. ensure_ascii=False keeps accented characters readable and the line shorter, but requires the collector to read UTF-8. If a collector mangles them, flip it to True and accept \uXXXX escapes.
• Objects that are not JSON-serialisable. default=str prevents a TypeError from a datetime, Decimal or bytes value taking down the run. Losing type fidelity in a log is always preferable to raising inside the logging call.
• Scrapy has its own logging setup. It configures the root logger during CrawlerProcess startup, so install this formatter in a spider_opened handler or set LOG_FORMATTER rather than calling configure() at import time. The framework's own logger names — scrapy.core.engine, scrapy.extensions.logstats — are worth keeping at INFO when running Scrapy.
• Threads inherit context, spawned processes do not. A ThreadPoolExecutor copies the current context per submitted task, so ids survive. A multiprocessing worker starts with fresh defaults and will log run_id: "-" unless you pass the id explicitly and set it in the child.
• Log volume has a cost per gigabyte. Hosted collectors bill on ingest. At 41,000 DEBUG lines per crawl and roughly 200 bytes a line, an hourly crawl ingests about 200 GB a year from DEBUG alone. Sample it.
• logging calls are synchronous even in an async crawl. StreamHandler.emit acquires a lock and writes on the calling thread, so a slow or blocked stdout pipe stalls the event loop. If stdout is being consumed by something that can back up, wrap the handler in logging.handlers.QueueHandler with a QueueListener on a background thread.
• URLs can themselves be secrets. A pre-signed download link or an API URL with a token in the query string leaks the moment you log the URL, and _scrub will not catch it because the key is url. Strip the query string before logging when a target uses signed links, and log the path plus a hash of the parameters instead.
• Do not log the same event twice at different levels. The common version is a WARNING at the retry site and an ERROR at the give-up site describing the same URL. It doubles the apparent failure count in any level-based aggregation. Log one event per state transition and let the attempt field carry the rest.

Frequently Asked Questions

Do I need structlog or loguru for this? No. The stdlib formatter above covers the whole requirement in about twenty lines and adds no dependency to a container image. Those libraries are worth it when you want bound-context helpers, processor chains or nicer local development output, but they solve ergonomics rather than capability.

How do I read JSON logs while developing? Pipe them through jq: python -m scraper.crawl | jq -c '{ts, event, status, url}' gives a compact readable stream, and jq 'select(.level=="WARNING")' filters. Alternatively, switch the handler to a plain formatter when sys.stdout.isatty() is true, so the same code prints prose locally and JSON in production.

Should the correlation id come from the scheduler or be generated in the process? Prefer one supplied by the scheduler when there is one — a GitHub Actions run id or a workflow execution id — because it links your logs to the platform's own record of the job. Fall back to a generated UUID so the code still works when run by hand.

Does the redaction filter slow down logging?_scrub walks the fields dict once, which is a few microseconds for the small dictionaries a scraper logs. It only becomes measurable if you pass large nested structures as fields, which the depth and length caps are there to discourage.

Related

• Monitoring and Alerting for Scrapers — the topic this page belongs to
• Detecting Silent Scraper Failures — turning WARNING-level yield signals into a failed run
• Exporting Scrapy Metrics to Prometheus — the counter side of the same instrumentation
• Running Scrapers on AWS Lambda — where stdout goes when there is no container