DEV Community

Sir Max
Sir Max

Posted on

I Stopped Grepping Logs and Started Querying Them — My 3-Step Structured Logging Setup

#python #tutorial #webdev #api

I Stopped Grepping Logs and Started Querying Them — My 3-Step Structured Logging Setup

Two months ago, our production API went down at 2 AM. The on-call engineer spent 40 minutes grepping through 200 MB of plaintext logs before finding the root cause: a database connection pool exhaustion triggered by a slow upstream service.

The worst part? The information was in the logs the whole time. We just couldn't find it fast enough.

That night, I promised myself I'd fix our logging. Here's the 3-step setup that now catches issues in under a minute — with real code.

Step 1: Stop Writing Logs as Strings, Start Writing JSON

The old way:

2026-07-21 02:14:03 INFO [worker-3] POST /api/orders 500 1247ms database_error
2026-07-21 02:14:03 INFO [worker-7] POST /api/orders 200 89ms
2026-07-21 02:14:04 WARN [worker-3] Connection pool exhausted (active=20, max=20, waiting=3)
Enter fullscreen mode Exit fullscreen mode

To find how many 500s happened in the last hour? Grep for 500, count lines, hope the format is consistent. To correlate "connection pool exhausted" with the endpoint that caused it? Good luck — those two lines aren't even adjacent.

Here's the same information, structured:

{"timestamp":"2026-07-21T02:14:03.421Z","level":"INFO","worker":"worker-3","event":"request_completed","method":"POST","path":"/api/orders","status":500,"duration_ms":1247,"error":"database_error","request_id":"req-abc123"}
{"timestamp":"2026-07-21T02:14:03.822Z","level":"INFO","worker":"worker-7","event":"request_completed","method":"POST","path":"/api/orders","status":200,"duration_ms":89,"request_id":"req-abc124"}
{"timestamp":"2026-07-21T02:14:04.155Z","level":"WARN","worker":"worker-3","event":"connection_pool_exhausted","active":20,"max":20,"waiting":3,"request_id":"req-abc123"}
Enter fullscreen mode Exit fullscreen mode

Now I can query with jq:

# All 500 errors in the last hour
jq 'select(.status == 500 and .timestamp >= "2026-07-21T01:14:00Z")' app.log

# Find all logs for a specific request
jq 'select(.request_id == "req-abc123")' app.log

# Count errors by endpoint
jq -s 'group_by(.path) | map({path: .[0].path, errors: [.[] | select(.status >= 500)] | length})' app.log
Enter fullscreen mode Exit fullscreen mode

Step 2: Use structlog (Python), Not print()

Here's the setup that took 20 minutes and changed everything:

import structlog
import logging

# Configure structlog to output JSON
structlog.configure(
    processors=[
        structlog.contextvars.merge_contextvars,
        structlog.processors.add_log_level,
        structlog.processors.TimeStamper(fmt="iso"),
        structlog.dev.ConsoleRenderer()  # Pretty output in dev
        if __import__('os').environ.get('ENV') != 'production'
        else structlog.processors.JSONRenderer()
    ],
    wrapper_class=structlog.make_filtering_bound_logger(logging.INFO),
    context_class=dict,
    logger_factory=structlog.PrintLoggerFactory(),
)

logger = structlog.get_logger()
Enter fullscreen mode Exit fullscreen mode

Now every log entry carries context:

# Bind request-scoped context once
log = logger.bind(request_id="req-abc123", user_agent="curl/8.4")

log.info("auth_check_passed", user_id=42, method="api_key")
log.info("db_query_completed", query="SELECT orders", rows=15, duration_ms=12)
log.warning("connection_pool_exhausted", active=20, max=20, waiting=3)
Enter fullscreen mode Exit fullscreen mode

The request_id is automatically injected into every log line from that scope. No more guessing which lines belong together.

One thing I learned the hard way: always use structlog.processors.UnicodeDecoder() in the processor chain. Without it, log entries with non-ASCII characters (think user-submitted names with accents or emoji) crash the JSON serializer silently. Add it right after the TimeStamper:

structlog.processors.TimeStamper(fmt="iso"),
structlog.processors.UnicodeDecoder(),  # <-- save yourself a headache
Enter fullscreen mode Exit fullscreen mode

Step 3: Add a /health Endpoint That Tells the Truth

Our old health check:

@app.get("/health")
async def health():
    return {"status": "ok"}
Enter fullscreen mode Exit fullscreen mode

This returns 200 even when the database is unreachable and Redis is on fire. It lied to our load balancer for three months before we found out.

The new one:

@app.get("/health")
async def health():
    checks = {}

    # Check database
    try:
        await db.execute("SELECT 1")
        checks["database"] = "ok"
    except Exception as e:
        checks["database"] = f"error: {e}"
        logger.error("health_check_failed", component="database", error=str(e))

    # Check Redis
    try:
        await redis.ping()
        checks["redis"] = "ok"
    except Exception as e:
        checks["redis"] = f"error: {e}"
        logger.error("health_check_failed", component="redis", error=str(e))

    all_ok = all(v == "ok" for v in checks.values())
    status_code = 200 if all_ok else 503

    return JSONResponse(
        content={"status": "ok" if all_ok else "degraded", "components": checks},
        status_code=status_code,
    )
Enter fullscreen mode Exit fullscreen mode

Now our load balancer actually knows when to stop sending traffic. And the structured error logs from this endpoint — with component and error fields — make it trivially searchable:

jq 'select(.event == "health_check_failed") | {component, error, timestamp}' app.log
Enter fullscreen mode Exit fullscreen mode

What Changed (Numbers)

Before After
40 min to find root cause at 2 AM Under 2 min
200 MB plaintext logs / day 60 MB structured JSON (gzip compresses better)
Guessing which lines belong to one request request_id links everything
`grep 500 app.log wc -l`
"Everything is fine" health check Real component-level health

The disk savings surprised me. Structured JSON looks bigger, but since identical keys repeat across lines, gzip compression is much more effective. Our daily log volume dropped by 70% after switching.

What I'd Do Differently Next Time

  • Don't log request bodies by default. We logged full POST bodies for debugging and accidentally logged a credit card number. Use a middleware that redacts known sensitive fields before the logger sees them.
  • Standardize event names. "request_completed", "db_query_completed", "auth_check_passed" — pick a naming convention and stick to it. Inconsistent event names make queries useless.
  • Log context, not narratives. Don't write "The user tried to log in but the password was wrong." Write {"event": "login_failed", "reason": "invalid_password"}. Let the dashboard compose the story.

Structured logging won't win you a promotion, but it will save you from 2 AM panic-grepping. That's a win in my book.

What's your logging setup? Still grepping, or have you switched to something better? Let me know in the comments.

Top comments (0)