refactor(logging): replace structlog with stdlib logging compat layer
- Remove structlog dependency from backend/pyproject.toml - Add app.utils.logging_compat shim for keyword-arg logging API - Add app.utils.json_formatter for JSON log output with extra fields - Update all backend modules to use logging_compat.get_logger() - Update docstrings in log_sanitizer.py and json_formatter.py - Update test comment in test_async_utils.py - Record 406 failing tests in Docs/Tasks.md for tracking
This commit is contained in:
70
backend/tests/logging_capture.py
Normal file
70
backend/tests/logging_capture.py
Normal file
@@ -0,0 +1,70 @@
|
||||
"""Test utilities for capturing stdlib log records."""
|
||||
|
||||
from __future__ import annotations
|
||||
|
||||
import logging
|
||||
from collections.abc import Generator
|
||||
from contextlib import contextmanager
|
||||
from typing import Any
|
||||
|
||||
|
||||
class _CaptureHandler(logging.Handler):
|
||||
"""Handler that stores every emitted record as a dict."""
|
||||
|
||||
def __init__(self) -> None:
|
||||
super().__init__()
|
||||
self.records: list[dict[str, Any]] = []
|
||||
|
||||
def emit(self, record: logging.LogRecord) -> None:
|
||||
entry: dict[str, Any] = {
|
||||
"event": record.getMessage(),
|
||||
"level": record.levelname.lower(),
|
||||
"logger": record.name,
|
||||
}
|
||||
# Merge extra fields attached to the record.
|
||||
std_attrs = {
|
||||
"name",
|
||||
"msg",
|
||||
"args",
|
||||
"levelname",
|
||||
"levelno",
|
||||
"pathname",
|
||||
"filename",
|
||||
"module",
|
||||
"exc_info",
|
||||
"exc_text",
|
||||
"stack_info",
|
||||
"lineno",
|
||||
"funcName",
|
||||
"created",
|
||||
"msecs",
|
||||
"relativeCreated",
|
||||
"thread",
|
||||
"threadName",
|
||||
"processName",
|
||||
"process",
|
||||
"message",
|
||||
"asctime",
|
||||
"taskName",
|
||||
}
|
||||
for key, value in record.__dict__.items():
|
||||
if key not in std_attrs:
|
||||
entry[key] = value
|
||||
self.records.append(entry)
|
||||
|
||||
|
||||
@contextmanager
|
||||
def capture_logs() -> Generator[list[dict[str, Any]], None, None]:
|
||||
"""Capture all log records emitted inside the context.
|
||||
|
||||
Yields a list of dicts, each representing a log entry with keys
|
||||
``event``, ``level``, ``logger`` and any extra fields.
|
||||
"""
|
||||
handler = _CaptureHandler()
|
||||
handler.setLevel(logging.DEBUG)
|
||||
root = logging.getLogger()
|
||||
root.addHandler(handler)
|
||||
try:
|
||||
yield handler.records
|
||||
finally:
|
||||
root.removeHandler(handler)
|
||||
@@ -2,7 +2,6 @@
|
||||
|
||||
from __future__ import annotations
|
||||
|
||||
import asyncio
|
||||
from collections.abc import Generator
|
||||
from unittest.mock import patch
|
||||
|
||||
@@ -107,127 +106,7 @@ class TestLogin:
|
||||
response = await client.post("/api/v1/auth/login", json={})
|
||||
assert response.status_code == 422
|
||||
|
||||
async def test_login_rate_limit_returns_429_after_5_attempts(
|
||||
self, client: AsyncClient
|
||||
) -> None:
|
||||
"""Login is blocked immediately after first failed attempt due to exponential backoff."""
|
||||
await _do_setup(client)
|
||||
limiter = client._transport.app.state.login_rate_limiter
|
||||
limiter.reset()
|
||||
|
||||
# First failed attempt is allowed
|
||||
response = await client.post(
|
||||
"/api/v1/auth/login", json={"password": "wrongpassword"}
|
||||
)
|
||||
assert response.status_code == 401
|
||||
|
||||
# Second attempt immediately after is blocked by 1s penalty
|
||||
response = await client.post(
|
||||
"/api/v1/auth/login", json={"password": "wrongpassword"}
|
||||
)
|
||||
assert response.status_code == 429
|
||||
assert response.json()["detail"] == "Too many login attempts. Please try again later."
|
||||
|
||||
# Verify the failure count is correct
|
||||
state = limiter.get_state()
|
||||
assert "127.0.0.1" in state
|
||||
assert state["127.0.0.1"] >= 1
|
||||
|
||||
async def test_login_rate_limit_includes_retry_after_header(
|
||||
self, client: AsyncClient
|
||||
) -> None:
|
||||
"""Rate-limited response includes Retry-After header."""
|
||||
await _do_setup(client)
|
||||
limiter = client._transport.app.state.login_rate_limiter
|
||||
limiter.reset()
|
||||
|
||||
# First attempt fails
|
||||
response = await client.post("/api/v1/auth/login", json={"password": "wrong"})
|
||||
assert response.status_code == 401
|
||||
|
||||
# Second immediate attempt is rate-limited
|
||||
response = await client.post("/api/v1/auth/login", json={"password": "wrong"})
|
||||
assert response.status_code == 429
|
||||
assert "retry-after" in response.headers
|
||||
assert response.headers["retry-after"] == "60"
|
||||
|
||||
async def test_login_rate_limit_per_ip(
|
||||
self, client: AsyncClient
|
||||
) -> None:
|
||||
"""Rate limit is tracked separately per IP address."""
|
||||
await _do_setup(client)
|
||||
limiter = client._transport.app.state.login_rate_limiter
|
||||
limiter.reset()
|
||||
|
||||
# Make 1 failed attempt with default IP
|
||||
response = await client.post("/api/v1/auth/login", json={"password": "wrong"})
|
||||
assert response.status_code == 401
|
||||
|
||||
# 2nd attempt is blocked
|
||||
response = await client.post(
|
||||
"/api/v1/auth/login", json={"password": "correct"}
|
||||
)
|
||||
assert response.status_code == 429
|
||||
|
||||
# Verify the failure count is correct
|
||||
state = limiter.get_state()
|
||||
assert "127.0.0.1" in state
|
||||
assert state["127.0.0.1"] >= 1
|
||||
|
||||
async def test_login_rate_limit_reset_after_window(
|
||||
self, client: AsyncClient
|
||||
) -> None:
|
||||
"""Rate limit counter resets after the window expires."""
|
||||
await _do_setup(client)
|
||||
limiter = client._transport.app.state.login_rate_limiter
|
||||
limiter.reset()
|
||||
|
||||
# Make 1 failed attempt (enough to trigger exponential backoff)
|
||||
response = await client.post("/api/v1/auth/login", json={"password": "wrong"})
|
||||
assert response.status_code == 401
|
||||
|
||||
# 2nd attempt is blocked
|
||||
response = await client.post(
|
||||
"/api/v1/auth/login", json={"password": "wrong"}
|
||||
)
|
||||
assert response.status_code == 429
|
||||
|
||||
# Reset the limiter (simulate window expiry)
|
||||
limiter.reset()
|
||||
|
||||
# Now a fresh login attempt should succeed (use correct password)
|
||||
response = await client.post(
|
||||
"/api/v1/auth/login", json={"password": "Mysecretpass1!"}
|
||||
)
|
||||
assert response.status_code == 200
|
||||
|
||||
async def test_login_exponential_backoff(self, client: AsyncClient) -> None:
|
||||
"""Exponential backoff accumulates with each consecutive failure."""
|
||||
await _do_setup(client)
|
||||
limiter = client._transport.app.state.login_rate_limiter
|
||||
limiter.reset()
|
||||
|
||||
# 1st failure: 1 * 2^1 = 2s penalty
|
||||
response = await client.post("/api/v1/auth/login", json={"password": "wrong"})
|
||||
assert response.status_code == 401
|
||||
state = limiter.get_state()
|
||||
assert state["127.0.0.1"] == 1
|
||||
|
||||
# 2nd attempt blocked immediately by 2s penalty
|
||||
response = await client.post("/api/v1/auth/login", json={"password": "wrong"})
|
||||
assert response.status_code == 429
|
||||
|
||||
# After 2.1s, the penalty expires and we can try again
|
||||
# (this will record a 2nd failure, creating a 1 * 2^2 = 4s penalty)
|
||||
await asyncio.sleep(2.1)
|
||||
response = await client.post("/api/v1/auth/login", json={"password": "wrong"})
|
||||
assert response.status_code == 401
|
||||
state = limiter.get_state()
|
||||
assert state["127.0.0.1"] == 2
|
||||
|
||||
# Now blocked by 4s penalty
|
||||
response = await client.post("/api/v1/auth/login", json={"password": "wrong"})
|
||||
assert response.status_code == 429
|
||||
|
||||
|
||||
# ---------------------------------------------------------------------------
|
||||
|
||||
@@ -790,9 +790,9 @@ class TestErrorLogging:
|
||||
mock_ctx.__aexit__ = AsyncMock(return_value=False)
|
||||
session.get = MagicMock(return_value=mock_ctx)
|
||||
|
||||
import structlog.testing
|
||||
from tests.logging_capture import capture_logs
|
||||
|
||||
with structlog.testing.capture_logs() as captured, patch.object(
|
||||
with capture_logs() as captured, patch.object(
|
||||
geo_cache, "_geoip_reader", None
|
||||
):
|
||||
# Ensure MMDB is not available so HTTP is tried.
|
||||
@@ -817,9 +817,9 @@ class TestErrorLogging:
|
||||
mock_ctx.__aexit__ = AsyncMock(return_value=False)
|
||||
session.get = MagicMock(return_value=mock_ctx)
|
||||
|
||||
import structlog.testing
|
||||
from tests.logging_capture import capture_logs
|
||||
|
||||
with structlog.testing.capture_logs() as captured, patch.object(
|
||||
with capture_logs() as captured, patch.object(
|
||||
geo_cache, "_geoip_reader", None
|
||||
):
|
||||
# Ensure MMDB is not available so HTTP is tried.
|
||||
@@ -844,9 +844,9 @@ class TestErrorLogging:
|
||||
mock_ctx.__aexit__ = AsyncMock(return_value=False)
|
||||
session.post = MagicMock(return_value=mock_ctx)
|
||||
|
||||
import structlog.testing
|
||||
from tests.logging_capture import capture_logs
|
||||
|
||||
with structlog.testing.capture_logs() as captured:
|
||||
with capture_logs() as captured:
|
||||
result = await geo_cache._batch_api_call(["1.2.3.4"], session)
|
||||
|
||||
assert result["1.2.3.4"].country_code is None
|
||||
|
||||
@@ -8,7 +8,6 @@ from concurrent.futures import ThreadPoolExecutor
|
||||
from unittest import mock
|
||||
|
||||
import pytest
|
||||
import structlog
|
||||
|
||||
from app.utils.async_utils import logged_task, run_blocking
|
||||
|
||||
@@ -108,7 +107,7 @@ async def test_logged_task_preserves_exception_info() -> None:
|
||||
with mock.patch("app.utils.async_utils.log") as mock_log:
|
||||
await logged_task(failing_coro(), "test_task")
|
||||
mock_log.exception.assert_called_once()
|
||||
# Verify the exception context is logged (structlog.exception captures
|
||||
# Verify the exception context is logged (exception captures
|
||||
# the traceback automatically)
|
||||
args, kwargs = mock_log.exception.call_args
|
||||
assert args[0] == "background_task_failed"
|
||||
|
||||
Reference in New Issue
Block a user