refactor: align repo layout and logging safeguards
This commit is contained in:
qzl
@@ -0,0 +1,3 @@
|
||||
from .settings import Settings, config
|
||||
|
||||
__all__ = ["Settings", "config"]
|
||||
@@ -0,0 +1,113 @@
|
||||
from __future__ import annotations
|
||||
|
||||
from pathlib import Path
|
||||
from typing import ClassVar, Literal
|
||||
|
||||
from pydantic import BaseModel, Field, computed_field
|
||||
from pydantic_settings import BaseSettings, SettingsConfigDict
|
||||
|
||||
|
||||
class RuntimeSettings(BaseModel):
|
||||
environment: Literal["dev", "test", "prod"] = "dev"
|
||||
debug: bool = True
|
||||
log_level: str = "INFO"
|
||||
log_json: bool = True
|
||||
log_rotation: Literal["time", "size", "none"] = "time"
|
||||
log_rotation_when: str = "midnight"
|
||||
log_rotation_interval: int = 1
|
||||
log_rotation_backup_count: int = 14
|
||||
log_rotation_max_bytes: int = 10_000_000
|
||||
log_dir: str = "logs"
|
||||
log_error_dir: str = "logs/errors"
|
||||
log_file_name: str = "app.log"
|
||||
log_error_file_name: str = "error.log"
|
||||
log_sensitive_fields: list[str] = Field(
|
||||
default_factory=lambda: [
|
||||
"password",
|
||||
"secret",
|
||||
"token",
|
||||
"api_key",
|
||||
"authorization",
|
||||
"cookie",
|
||||
"client_ip",
|
||||
"user_id",
|
||||
]
|
||||
)
|
||||
sql_log_queries: bool = False
|
||||
|
||||
|
||||
class AppSettings(BaseModel):
|
||||
host: str = "0.0.0.0"
|
||||
port: int = Field(default=8000, ge=1, le=65535)
|
||||
reload: bool = True
|
||||
|
||||
|
||||
class CorsSettings(BaseModel):
|
||||
allow_origins: list[str] = Field(
|
||||
default_factory=lambda: [
|
||||
"http://localhost",
|
||||
"http://localhost:3000",
|
||||
]
|
||||
)
|
||||
allow_credentials: bool = True
|
||||
allow_methods: list[str] = Field(default_factory=lambda: ["*"])
|
||||
allow_headers: list[str] = Field(default_factory=lambda: ["*"])
|
||||
|
||||
|
||||
class SupabaseSettings(BaseModel):
|
||||
url: str = "http://localhost:8001"
|
||||
anon_key: str = "CHANGE_ME"
|
||||
service_role_key: str = "CHANGE_ME"
|
||||
jwt_secret: str | None = None
|
||||
|
||||
|
||||
class InfraSupabaseSettings(BaseModel):
|
||||
public_url: str = "http://localhost:8001"
|
||||
anon_key: str = "CHANGE_ME"
|
||||
service_role_key: str = "CHANGE_ME"
|
||||
|
||||
|
||||
class InfraJwtSettings(BaseModel):
|
||||
secret: str = "CHANGE_ME"
|
||||
|
||||
|
||||
class InfraSettings(BaseModel):
|
||||
api_external_url: str = "http://localhost:8001"
|
||||
supabase: InfraSupabaseSettings = Field(default_factory=InfraSupabaseSettings)
|
||||
jwt: InfraJwtSettings = Field(default_factory=InfraJwtSettings)
|
||||
|
||||
|
||||
def _resolve_env_file() -> str:
|
||||
current = Path(__file__).resolve()
|
||||
for parent in [current, *current.parents]:
|
||||
candidate = parent / ".env"
|
||||
if candidate.is_file():
|
||||
return str(candidate)
|
||||
return ".env"
|
||||
|
||||
|
||||
class Settings(BaseSettings):
|
||||
runtime: RuntimeSettings = RuntimeSettings()
|
||||
app: AppSettings = AppSettings()
|
||||
cors: CorsSettings = CorsSettings()
|
||||
infra: InfraSettings = Field(default_factory=InfraSettings)
|
||||
|
||||
@computed_field
|
||||
def supabase(self) -> SupabaseSettings:
|
||||
return SupabaseSettings(
|
||||
url=self.infra.supabase.public_url or self.infra.api_external_url,
|
||||
anon_key=self.infra.supabase.anon_key,
|
||||
service_role_key=self.infra.supabase.service_role_key,
|
||||
jwt_secret=self.infra.jwt.secret,
|
||||
)
|
||||
|
||||
model_config: ClassVar[SettingsConfigDict] = SettingsConfigDict(
|
||||
env_file=_resolve_env_file(),
|
||||
env_prefix="SOCIAL_",
|
||||
env_nested_delimiter="__",
|
||||
case_sensitive=False,
|
||||
extra="ignore",
|
||||
)
|
||||
|
||||
|
||||
config = Settings()
|
||||
@@ -0,0 +1,15 @@
|
||||
from __future__ import annotations
|
||||
|
||||
from core.logging import celery
|
||||
from core.logging.config import configure_logging
|
||||
from core.logging.context import bind_context, clear_context, get_context
|
||||
from core.logging.logger import get_logger
|
||||
|
||||
__all__ = [
|
||||
"bind_context",
|
||||
"celery",
|
||||
"clear_context",
|
||||
"configure_logging",
|
||||
"get_context",
|
||||
"get_logger",
|
||||
]
|
||||
@@ -0,0 +1,57 @@
|
||||
from __future__ import annotations
|
||||
|
||||
from collections.abc import Callable
|
||||
from dataclasses import dataclass
|
||||
from typing import cast
|
||||
|
||||
from celery import Celery, signals
|
||||
|
||||
from core.config.settings import Settings
|
||||
from core.logging.config import configure_logging
|
||||
from core.logging.context import bind_context, clear_context
|
||||
|
||||
|
||||
@dataclass(frozen=True)
|
||||
class CelerySignalHandlers:
|
||||
on_setup_logging: Callable[..., None]
|
||||
on_after_setup_task_logger: Callable[..., None]
|
||||
on_task_prerun: Callable[..., None]
|
||||
on_task_postrun: Callable[..., None]
|
||||
|
||||
|
||||
def build_celery_signal_handlers(
|
||||
settings: Settings | None = None,
|
||||
) -> CelerySignalHandlers:
|
||||
def on_setup_logging(*_args: object, **_kwargs: object) -> None:
|
||||
configure_logging(settings)
|
||||
|
||||
def on_after_setup_task_logger(*_args: object, **_kwargs: object) -> None:
|
||||
configure_logging(settings)
|
||||
|
||||
def on_task_prerun(*_args: object, **kwargs: object) -> None:
|
||||
task_id = cast(str | None, kwargs.get("task_id"))
|
||||
task = kwargs.get("task")
|
||||
task_name = getattr(task, "name", None)
|
||||
bind_context(task_id=task_id, task_name=task_name)
|
||||
|
||||
def on_task_postrun(*_args: object, **_kwargs: object) -> None:
|
||||
clear_context()
|
||||
|
||||
return CelerySignalHandlers(
|
||||
on_setup_logging=on_setup_logging,
|
||||
on_after_setup_task_logger=on_after_setup_task_logger,
|
||||
on_task_prerun=on_task_prerun,
|
||||
on_task_postrun=on_task_postrun,
|
||||
)
|
||||
|
||||
|
||||
def configure_celery_app(app: Celery, settings: Settings | None = None) -> None:
|
||||
app.conf.worker_hijack_root_logger = False
|
||||
|
||||
handlers = build_celery_signal_handlers(settings)
|
||||
signals.setup_logging.connect(handlers.on_setup_logging, weak=False)
|
||||
signals.after_setup_task_logger.connect(
|
||||
handlers.on_after_setup_task_logger, weak=False
|
||||
)
|
||||
signals.task_prerun.connect(handlers.on_task_prerun, weak=False)
|
||||
signals.task_postrun.connect(handlers.on_task_postrun, weak=False)
|
||||
@@ -0,0 +1,103 @@
|
||||
from __future__ import annotations
|
||||
|
||||
import logging
|
||||
from logging.config import dictConfig
|
||||
from pathlib import Path
|
||||
|
||||
import structlog
|
||||
|
||||
from core.config.settings import RuntimeSettings, Settings
|
||||
from core.logging.formatters import (
|
||||
build_plain_formatter,
|
||||
build_processor_formatter,
|
||||
ensure_message_key,
|
||||
)
|
||||
from core.logging.filters import build_sensitive_data_processor
|
||||
from core.logging.handlers import build_file_handler_config
|
||||
|
||||
|
||||
def _ensure_log_dirs(runtime: RuntimeSettings) -> None:
|
||||
Path(runtime.log_dir).mkdir(parents=True, exist_ok=True)
|
||||
Path(runtime.log_error_dir).mkdir(parents=True, exist_ok=True)
|
||||
|
||||
|
||||
def build_logging_config(runtime: RuntimeSettings) -> dict[str, object]:
|
||||
log_dir = Path(runtime.log_dir)
|
||||
error_dir = Path(runtime.log_error_dir)
|
||||
formatter_name = "json" if runtime.log_json else "plain"
|
||||
|
||||
file_handler = build_file_handler_config(
|
||||
runtime,
|
||||
file_path=log_dir / runtime.log_file_name,
|
||||
level=runtime.log_level,
|
||||
formatter=formatter_name,
|
||||
)
|
||||
error_handler = build_file_handler_config(
|
||||
runtime,
|
||||
file_path=error_dir / runtime.log_error_file_name,
|
||||
level="ERROR",
|
||||
formatter=formatter_name,
|
||||
filters=["error_only"],
|
||||
)
|
||||
|
||||
return {
|
||||
"version": 1,
|
||||
"disable_existing_loggers": False,
|
||||
"filters": {
|
||||
"error_only": {
|
||||
"()": "core.logging.filters.ErrorLevelFilter",
|
||||
}
|
||||
},
|
||||
"formatters": {
|
||||
"json": {
|
||||
"()": build_processor_formatter,
|
||||
"sensitive_fields": runtime.log_sensitive_fields,
|
||||
},
|
||||
"plain": {
|
||||
"()": build_plain_formatter,
|
||||
"sensitive_fields": runtime.log_sensitive_fields,
|
||||
},
|
||||
},
|
||||
"handlers": {
|
||||
"file": file_handler,
|
||||
"error": error_handler,
|
||||
},
|
||||
"root": {
|
||||
"handlers": ["file", "error"],
|
||||
"level": runtime.log_level,
|
||||
},
|
||||
}
|
||||
|
||||
|
||||
def configure_logging(settings: Settings | None = None) -> None:
|
||||
active_settings = settings or Settings()
|
||||
runtime = active_settings.runtime
|
||||
|
||||
try:
|
||||
_ensure_log_dirs(runtime)
|
||||
dictConfig(build_logging_config(runtime))
|
||||
except (OSError, ValueError) as exc:
|
||||
logging.basicConfig(level=runtime.log_level)
|
||||
logging.getLogger(__name__).error("Logging setup failed", exc_info=exc)
|
||||
|
||||
structlog.configure(
|
||||
processors=[
|
||||
structlog.contextvars.merge_contextvars,
|
||||
structlog.processors.add_log_level,
|
||||
structlog.processors.TimeStamper(fmt="iso", utc=True),
|
||||
structlog.processors.CallsiteParameterAdder(
|
||||
parameters=[
|
||||
structlog.processors.CallsiteParameter.MODULE,
|
||||
structlog.processors.CallsiteParameter.FUNC_NAME,
|
||||
structlog.processors.CallsiteParameter.LINENO,
|
||||
]
|
||||
),
|
||||
build_sensitive_data_processor(runtime.log_sensitive_fields),
|
||||
ensure_message_key,
|
||||
structlog.processors.format_exc_info,
|
||||
structlog.processors.UnicodeDecoder(),
|
||||
structlog.stdlib.ProcessorFormatter.wrap_for_formatter,
|
||||
],
|
||||
logger_factory=structlog.stdlib.LoggerFactory(),
|
||||
cache_logger_on_first_use=True,
|
||||
)
|
||||
@@ -0,0 +1,15 @@
|
||||
from __future__ import annotations
|
||||
|
||||
from structlog import contextvars
|
||||
|
||||
|
||||
def bind_context(**values: object) -> None:
|
||||
contextvars.bind_contextvars(**values)
|
||||
|
||||
|
||||
def clear_context() -> None:
|
||||
contextvars.clear_contextvars()
|
||||
|
||||
|
||||
def get_context() -> dict[str, object]:
|
||||
return contextvars.get_contextvars()
|
||||
@@ -0,0 +1,56 @@
|
||||
from __future__ import annotations
|
||||
|
||||
import logging
|
||||
import re
|
||||
from collections.abc import Callable
|
||||
from typing import cast
|
||||
|
||||
from structlog.types import EventDict
|
||||
|
||||
|
||||
_NORMALIZE_PATTERN = re.compile(r"[^a-z0-9]")
|
||||
|
||||
|
||||
def _normalize_key(value: str) -> str:
|
||||
return _NORMALIZE_PATTERN.sub("", value.lower())
|
||||
|
||||
|
||||
def _is_sensitive_key(key: object, sensitive_fields: set[str]) -> bool:
|
||||
normalized_key = _normalize_key(str(key))
|
||||
return normalized_key in sensitive_fields or any(
|
||||
fragment in normalized_key for fragment in sensitive_fields
|
||||
)
|
||||
|
||||
|
||||
def _redact_value(value: object, sensitive_fields: set[str]) -> object:
|
||||
if isinstance(value, dict):
|
||||
typed_value = cast(dict[str, object], value)
|
||||
return {
|
||||
key: (
|
||||
"[REDACTED]"
|
||||
if _is_sensitive_key(key, sensitive_fields)
|
||||
else _redact_value(inner, sensitive_fields)
|
||||
)
|
||||
for key, inner in typed_value.items()
|
||||
}
|
||||
if isinstance(value, list):
|
||||
return [_redact_value(item, sensitive_fields) for item in value]
|
||||
return value
|
||||
|
||||
|
||||
def build_sensitive_data_processor(
|
||||
sensitive_fields: list[str],
|
||||
) -> Callable[[object, str, EventDict], EventDict]:
|
||||
normalized = {_normalize_key(field) for field in sensitive_fields}
|
||||
|
||||
def processor(
|
||||
_logger: object, _method_name: str, event_dict: EventDict
|
||||
) -> EventDict:
|
||||
return cast(EventDict, _redact_value(event_dict, normalized))
|
||||
|
||||
return processor
|
||||
|
||||
|
||||
class ErrorLevelFilter(logging.Filter):
|
||||
def filter(self, record: logging.LogRecord) -> bool:
|
||||
return record.levelno >= logging.ERROR
|
||||
@@ -0,0 +1,81 @@
|
||||
from __future__ import annotations
|
||||
|
||||
from structlog.dev import ConsoleRenderer
|
||||
from structlog.processors import JSONRenderer
|
||||
from structlog.stdlib import ProcessorFormatter
|
||||
from structlog.types import EventDict
|
||||
import structlog
|
||||
|
||||
from core.logging.filters import build_sensitive_data_processor
|
||||
|
||||
|
||||
def ensure_message_key(
|
||||
_logger: object, _method_name: str, event_dict: EventDict
|
||||
) -> EventDict:
|
||||
if "message" in event_dict:
|
||||
return event_dict
|
||||
if "event" not in event_dict:
|
||||
return event_dict
|
||||
|
||||
without_event = {key: value for key, value in event_dict.items() if key != "event"}
|
||||
return {**without_event, "message": event_dict["event"]}
|
||||
|
||||
|
||||
def build_processor_formatter(
|
||||
sensitive_fields: list[str] | None = None,
|
||||
) -> ProcessorFormatter:
|
||||
redact = build_sensitive_data_processor(sensitive_fields or [])
|
||||
return ProcessorFormatter(
|
||||
foreign_pre_chain=[
|
||||
structlog.contextvars.merge_contextvars,
|
||||
structlog.processors.add_log_level,
|
||||
structlog.processors.TimeStamper(fmt="iso", utc=True),
|
||||
structlog.processors.CallsiteParameterAdder(
|
||||
parameters=[
|
||||
structlog.processors.CallsiteParameter.MODULE,
|
||||
structlog.processors.CallsiteParameter.FUNC_NAME,
|
||||
structlog.processors.CallsiteParameter.LINENO,
|
||||
]
|
||||
),
|
||||
structlog.stdlib.ExtraAdder(),
|
||||
ensure_message_key,
|
||||
],
|
||||
processors=[
|
||||
redact,
|
||||
ensure_message_key,
|
||||
ProcessorFormatter.remove_processors_meta,
|
||||
structlog.processors.format_exc_info,
|
||||
structlog.processors.UnicodeDecoder(),
|
||||
JSONRenderer(sort_keys=True),
|
||||
],
|
||||
)
|
||||
|
||||
|
||||
def build_plain_formatter(
|
||||
sensitive_fields: list[str] | None = None,
|
||||
) -> ProcessorFormatter:
|
||||
redact = build_sensitive_data_processor(sensitive_fields or [])
|
||||
return ProcessorFormatter(
|
||||
foreign_pre_chain=[
|
||||
structlog.contextvars.merge_contextvars,
|
||||
structlog.processors.add_log_level,
|
||||
structlog.processors.TimeStamper(fmt="iso", utc=True),
|
||||
structlog.processors.CallsiteParameterAdder(
|
||||
parameters=[
|
||||
structlog.processors.CallsiteParameter.MODULE,
|
||||
structlog.processors.CallsiteParameter.FUNC_NAME,
|
||||
structlog.processors.CallsiteParameter.LINENO,
|
||||
]
|
||||
),
|
||||
structlog.stdlib.ExtraAdder(),
|
||||
ensure_message_key,
|
||||
],
|
||||
processors=[
|
||||
redact,
|
||||
ensure_message_key,
|
||||
ProcessorFormatter.remove_processors_meta,
|
||||
structlog.processors.format_exc_info,
|
||||
structlog.processors.UnicodeDecoder(),
|
||||
ConsoleRenderer(colors=False),
|
||||
],
|
||||
)
|
||||
@@ -0,0 +1,46 @@
|
||||
from __future__ import annotations
|
||||
|
||||
from pathlib import Path
|
||||
|
||||
from core.config.settings import RuntimeSettings
|
||||
|
||||
|
||||
def build_file_handler_config(
|
||||
runtime: RuntimeSettings,
|
||||
file_path: Path,
|
||||
level: str,
|
||||
formatter: str,
|
||||
filters: list[str] | None = None,
|
||||
) -> dict[str, object]:
|
||||
filter_list = list(filters or [])
|
||||
base_config: dict[str, object] = {
|
||||
"level": level,
|
||||
"formatter": formatter,
|
||||
"filename": str(file_path),
|
||||
"encoding": "utf-8",
|
||||
}
|
||||
|
||||
if filter_list:
|
||||
base_config = {**base_config, "filters": filter_list}
|
||||
|
||||
if runtime.log_rotation == "time":
|
||||
return {
|
||||
**base_config,
|
||||
"class": "logging.handlers.TimedRotatingFileHandler",
|
||||
"when": runtime.log_rotation_when,
|
||||
"interval": runtime.log_rotation_interval,
|
||||
"backupCount": runtime.log_rotation_backup_count,
|
||||
}
|
||||
|
||||
if runtime.log_rotation == "size":
|
||||
return {
|
||||
**base_config,
|
||||
"class": "logging.handlers.RotatingFileHandler",
|
||||
"maxBytes": runtime.log_rotation_max_bytes,
|
||||
"backupCount": runtime.log_rotation_backup_count,
|
||||
}
|
||||
|
||||
return {
|
||||
**base_config,
|
||||
"class": "logging.FileHandler",
|
||||
}
|
||||
@@ -0,0 +1,7 @@
|
||||
from __future__ import annotations
|
||||
|
||||
import structlog
|
||||
|
||||
|
||||
def get_logger(name: str) -> structlog.stdlib.BoundLogger:
|
||||
return structlog.get_logger(name)
|
||||
@@ -0,0 +1,84 @@
|
||||
from __future__ import annotations
|
||||
|
||||
import re
|
||||
from collections.abc import MutableMapping
|
||||
from typing import cast
|
||||
from uuid import uuid4
|
||||
|
||||
from fastapi import FastAPI, Request
|
||||
from starlette.requests import Request as StarletteRequest
|
||||
from starlette.responses import JSONResponse, Response
|
||||
from starlette.types import ASGIApp, Receive, Scope, Send
|
||||
|
||||
from core.logging.context import bind_context, clear_context
|
||||
from core.logging.logger import get_logger
|
||||
|
||||
|
||||
class RequestContextMiddleware:
|
||||
app: ASGIApp
|
||||
_header_name: str
|
||||
_request_id_pattern: re.Pattern[str]
|
||||
|
||||
def __init__(self, app: ASGIApp, header_name: str = "X-Request-ID") -> None:
|
||||
self.app = app
|
||||
self._header_name = header_name
|
||||
self._request_id_pattern = re.compile(r"^[A-Za-z0-9_-]{8,64}$")
|
||||
|
||||
async def __call__(self, scope: Scope, receive: Receive, send: Send) -> None:
|
||||
if scope.get("type") != "http":
|
||||
await self.app(scope, receive, send)
|
||||
return
|
||||
|
||||
request = StarletteRequest(scope, receive=receive)
|
||||
request_id = self._normalize_request_id(request.headers.get(self._header_name))
|
||||
client_ip = request.client.host if request.client else None
|
||||
user_id = getattr(request.state, "user_id", None)
|
||||
|
||||
request.state.request_id = request_id
|
||||
|
||||
bind_context(
|
||||
request_id=request_id,
|
||||
method=request.method,
|
||||
path=request.url.path,
|
||||
client_ip=client_ip,
|
||||
user_id=user_id,
|
||||
)
|
||||
|
||||
async def send_wrapper(message: MutableMapping[str, object]) -> None:
|
||||
if message.get("type") == "http.response.start":
|
||||
raw_headers = message.get("headers")
|
||||
headers = list(cast(list[tuple[bytes, bytes]], raw_headers or []))
|
||||
header_key = self._header_name.lower().encode()
|
||||
if not any(item[0].lower() == header_key for item in headers):
|
||||
headers.append((header_key, request_id.encode()))
|
||||
message = {**message, "headers": headers}
|
||||
await send(message)
|
||||
|
||||
try:
|
||||
await self.app(scope, receive, send_wrapper)
|
||||
finally:
|
||||
clear_context()
|
||||
|
||||
def _normalize_request_id(self, request_id: str | None) -> str:
|
||||
if request_id and self._request_id_pattern.match(request_id):
|
||||
return request_id
|
||||
return str(uuid4())
|
||||
|
||||
|
||||
def register_exception_handlers(app: FastAPI) -> None:
|
||||
logger = get_logger("core.logging.exception")
|
||||
|
||||
@app.exception_handler(Exception)
|
||||
async def unhandled_exception_handler(request: Request, exc: Exception) -> Response:
|
||||
request_id = getattr(request.state, "request_id", None)
|
||||
logger.exception(
|
||||
"Unhandled exception",
|
||||
error_type=exc.__class__.__name__,
|
||||
request_id=request_id,
|
||||
)
|
||||
headers = {"X-Request-ID": request_id} if request_id else None
|
||||
return JSONResponse(
|
||||
status_code=500,
|
||||
content={"detail": "Internal Server Error"},
|
||||
headers=headers,
|
||||
)
|
||||
@@ -0,0 +1,11 @@
|
||||
from __future__ import annotations
|
||||
|
||||
import sys
|
||||
from pathlib import Path
|
||||
|
||||
|
||||
def pytest_configure() -> None:
|
||||
root = Path(__file__).resolve().parents[2]
|
||||
src_path = root / "api" / "src"
|
||||
if str(src_path) not in sys.path:
|
||||
sys.path.append(str(src_path))
|
||||
@@ -0,0 +1,96 @@
|
||||
from __future__ import annotations
|
||||
|
||||
import json
|
||||
import socket
|
||||
import threading
|
||||
import time
|
||||
from pathlib import Path
|
||||
|
||||
from fastapi import FastAPI
|
||||
from playwright.sync_api import sync_playwright
|
||||
import uvicorn
|
||||
|
||||
from core.config.settings import Settings
|
||||
from core.logging.config import configure_logging
|
||||
from core.logging.middleware import (
|
||||
RequestContextMiddleware,
|
||||
register_exception_handlers,
|
||||
)
|
||||
|
||||
|
||||
def _read_json_lines(path: Path) -> list[dict[str, object]]:
|
||||
return [json.loads(line) for line in path.read_text().splitlines() if line.strip()]
|
||||
|
||||
|
||||
def _find_free_port() -> int:
|
||||
with socket.socket(socket.AF_INET, socket.SOCK_STREAM) as sock:
|
||||
sock.bind(("127.0.0.1", 0))
|
||||
return sock.getsockname()[1]
|
||||
|
||||
|
||||
def _wait_for_port(host: str, port: int, timeout: float = 5.0) -> None:
|
||||
deadline = time.time() + timeout
|
||||
while time.time() < deadline:
|
||||
with socket.socket(socket.AF_INET, socket.SOCK_STREAM) as sock:
|
||||
if sock.connect_ex((host, port)) == 0:
|
||||
return
|
||||
time.sleep(0.05)
|
||||
raise RuntimeError("Server did not start in time")
|
||||
|
||||
|
||||
def _start_server(app: FastAPI, host: str, port: int):
|
||||
config = uvicorn.Config(app, host=host, port=port, log_level="info")
|
||||
server = uvicorn.Server(config)
|
||||
thread = threading.Thread(target=server.run, daemon=True)
|
||||
thread.start()
|
||||
_wait_for_port(host, port)
|
||||
return server, thread
|
||||
|
||||
|
||||
def test_e2e_error_logging(tmp_path: Path) -> None:
|
||||
settings = Settings()
|
||||
runtime = settings.runtime.model_copy(
|
||||
update={
|
||||
"log_dir": str(tmp_path),
|
||||
"log_error_dir": str(tmp_path / "errors"),
|
||||
"log_rotation": "size",
|
||||
"log_rotation_max_bytes": 2048,
|
||||
}
|
||||
)
|
||||
configure_logging(settings.model_copy(update={"runtime": runtime}))
|
||||
|
||||
app = FastAPI()
|
||||
app.add_middleware(RequestContextMiddleware) # type: ignore[arg-type]
|
||||
register_exception_handlers(app)
|
||||
|
||||
@app.get("/boom")
|
||||
async def boom() -> dict[str, str]:
|
||||
raise RuntimeError("boom")
|
||||
|
||||
host = "127.0.0.1"
|
||||
port = _find_free_port()
|
||||
server, thread = _start_server(app, host, port)
|
||||
|
||||
try:
|
||||
with sync_playwright() as playwright:
|
||||
request_context = playwright.request.new_context(
|
||||
base_url=f"http://{host}:{port}"
|
||||
)
|
||||
response = request_context.get(
|
||||
"/boom",
|
||||
headers={"X-Request-ID": "e2e-5000"},
|
||||
)
|
||||
assert response.status == 500
|
||||
request_context.dispose()
|
||||
finally:
|
||||
server.should_exit = True
|
||||
thread.join(timeout=5)
|
||||
|
||||
error_entries = _read_json_lines(Path(tmp_path) / "errors" / "error.log")
|
||||
entry = next(
|
||||
item for item in error_entries if item.get("message") == "Unhandled exception"
|
||||
)
|
||||
|
||||
assert entry["request_id"] == "e2e-5000"
|
||||
exception = str(entry["exception"])
|
||||
assert "Traceback" in exception
|
||||
@@ -0,0 +1,126 @@
|
||||
from __future__ import annotations
|
||||
|
||||
import json
|
||||
import logging
|
||||
from pathlib import Path
|
||||
|
||||
from fastapi import FastAPI
|
||||
from fastapi.testclient import TestClient
|
||||
|
||||
from core.config.settings import Settings
|
||||
from core.logging.config import configure_logging
|
||||
from core.logging.logger import get_logger
|
||||
from core.logging.middleware import (
|
||||
RequestContextMiddleware,
|
||||
register_exception_handlers,
|
||||
)
|
||||
|
||||
|
||||
def _read_json_lines(path: Path) -> list[dict[str, object]]:
|
||||
return [json.loads(line) for line in path.read_text().splitlines() if line.strip()]
|
||||
|
||||
|
||||
def _configure_test_logging(tmp_path: Path) -> None:
|
||||
settings = Settings()
|
||||
runtime = settings.runtime.model_copy(
|
||||
update={
|
||||
"log_dir": str(tmp_path),
|
||||
"log_error_dir": str(tmp_path / "errors"),
|
||||
"log_rotation": "size",
|
||||
"log_rotation_max_bytes": 2048,
|
||||
}
|
||||
)
|
||||
test_settings = settings.model_copy(update={"runtime": runtime})
|
||||
|
||||
configure_logging(test_settings)
|
||||
|
||||
|
||||
def test_middleware_binds_request_context(tmp_path: Path) -> None:
|
||||
_configure_test_logging(tmp_path)
|
||||
|
||||
app = FastAPI()
|
||||
app.add_middleware(RequestContextMiddleware) # type: ignore[arg-type]
|
||||
|
||||
@app.get("/ok")
|
||||
async def ok() -> dict[str, str]:
|
||||
logger = get_logger("tests.ok")
|
||||
logger.info("request accepted", context_key="context_value")
|
||||
return {"status": "ok"}
|
||||
|
||||
client = TestClient(app)
|
||||
response = client.get("/ok", headers={"X-Request-ID": "req-1234"})
|
||||
|
||||
assert response.status_code == 200
|
||||
assert response.headers["X-Request-ID"] == "req-1234"
|
||||
|
||||
log_entries = _read_json_lines(Path(tmp_path) / "app.log")
|
||||
entry = next(
|
||||
item for item in log_entries if item.get("message") == "request accepted"
|
||||
)
|
||||
assert entry["message"] == "request accepted"
|
||||
assert entry["request_id"] == "req-1234"
|
||||
assert entry["method"] == "GET"
|
||||
assert entry["path"] == "/ok"
|
||||
assert entry["context_key"] == "context_value"
|
||||
|
||||
logging.shutdown()
|
||||
|
||||
|
||||
def test_exception_handler_logs_stack_and_sends_500(tmp_path: Path) -> None:
|
||||
_configure_test_logging(tmp_path)
|
||||
|
||||
app = FastAPI()
|
||||
app.add_middleware(RequestContextMiddleware)
|
||||
register_exception_handlers(app)
|
||||
|
||||
@app.get("/boom")
|
||||
async def boom() -> dict[str, str]:
|
||||
raise RuntimeError("boom")
|
||||
|
||||
client = TestClient(app, raise_server_exceptions=False)
|
||||
response = client.get("/boom", headers={"X-Request-ID": "req-5000"})
|
||||
|
||||
assert response.status_code == 500
|
||||
assert response.json()["detail"] == "Internal Server Error"
|
||||
|
||||
error_entries = _read_json_lines(Path(tmp_path) / "errors" / "error.log")
|
||||
assert error_entries
|
||||
entry = error_entries[-1]
|
||||
assert entry["level"] == "error"
|
||||
assert entry["request_id"] == "req-5000"
|
||||
exception = str(entry["exception"])
|
||||
assert "Traceback" in exception
|
||||
assert "test_fastapi_logging_integration" in exception
|
||||
|
||||
logging.shutdown()
|
||||
|
||||
|
||||
def test_invalid_request_id_is_replaced_and_used_in_error_context(
|
||||
tmp_path: Path,
|
||||
) -> None:
|
||||
_configure_test_logging(tmp_path)
|
||||
|
||||
app = FastAPI()
|
||||
app.add_middleware(RequestContextMiddleware)
|
||||
register_exception_handlers(app)
|
||||
|
||||
@app.get("/boom")
|
||||
async def boom() -> dict[str, str]:
|
||||
raise RuntimeError("boom")
|
||||
|
||||
client = TestClient(app, raise_server_exceptions=False)
|
||||
response = client.get("/boom", headers={"X-Request-ID": "bad"})
|
||||
|
||||
assert response.status_code == 500
|
||||
|
||||
response_request_id = response.headers["X-Request-ID"]
|
||||
assert response_request_id != "bad"
|
||||
|
||||
error_entries = _read_json_lines(Path(tmp_path) / "errors" / "error.log")
|
||||
assert error_entries
|
||||
entry = error_entries[-1]
|
||||
assert entry["request_id"] == response_request_id
|
||||
exception = str(entry["exception"])
|
||||
assert "Traceback" in exception
|
||||
|
||||
logging.shutdown()
|
||||
@@ -0,0 +1,45 @@
|
||||
from __future__ import annotations
|
||||
|
||||
from celery import Celery
|
||||
from pytest import MonkeyPatch
|
||||
|
||||
from core.logging import celery as celery_logging
|
||||
from core.logging.context import clear_context, get_context
|
||||
|
||||
|
||||
class DummyTask:
|
||||
name: str = "tasks.sample"
|
||||
|
||||
|
||||
def test_celery_prerun_binds_task_context() -> None:
|
||||
handlers = celery_logging.build_celery_signal_handlers()
|
||||
|
||||
handlers.on_task_prerun(task_id="task-123", task=DummyTask())
|
||||
context = get_context()
|
||||
|
||||
assert context["task_id"] == "task-123"
|
||||
assert context["task_name"] == "tasks.sample"
|
||||
|
||||
clear_context()
|
||||
|
||||
|
||||
def test_celery_setup_logging_calls_configure(monkeypatch: MonkeyPatch) -> None:
|
||||
called = {"value": False}
|
||||
|
||||
def fake_configure_logging(settings: object | None = None) -> None:
|
||||
called["value"] = True
|
||||
|
||||
monkeypatch.setattr(celery_logging, "configure_logging", fake_configure_logging)
|
||||
handlers = celery_logging.build_celery_signal_handlers()
|
||||
|
||||
handlers.on_setup_logging()
|
||||
|
||||
assert called["value"] is True
|
||||
|
||||
|
||||
def test_configure_celery_app_disables_hijack() -> None:
|
||||
app = Celery("test")
|
||||
|
||||
celery_logging.configure_celery_app(app)
|
||||
|
||||
assert app.conf.worker_hijack_root_logger is False
|
||||
@@ -0,0 +1,140 @@
|
||||
from __future__ import annotations
|
||||
|
||||
import json
|
||||
import logging
|
||||
from collections.abc import Iterator
|
||||
from pathlib import Path
|
||||
from typing import cast
|
||||
|
||||
import pytest
|
||||
import structlog
|
||||
|
||||
from core.config.settings import Settings
|
||||
from core.logging.config import build_logging_config, configure_logging
|
||||
|
||||
|
||||
def _get_handlers(config: dict[str, object]) -> dict[str, dict[str, object]]:
|
||||
return cast(dict[str, dict[str, object]], config["handlers"])
|
||||
|
||||
|
||||
def test_build_logging_config_time_rotation(tmp_path: Path) -> None:
|
||||
settings = Settings()
|
||||
runtime = settings.runtime.model_copy(
|
||||
update={
|
||||
"log_dir": str(tmp_path),
|
||||
"log_error_dir": str(tmp_path / "errors"),
|
||||
"log_rotation": "time",
|
||||
}
|
||||
)
|
||||
|
||||
config = build_logging_config(runtime)
|
||||
handlers = _get_handlers(config)
|
||||
|
||||
assert handlers["file"]["class"] == "logging.handlers.TimedRotatingFileHandler"
|
||||
assert handlers["error"]["class"] == "logging.handlers.TimedRotatingFileHandler"
|
||||
assert handlers["error"]["level"] == "ERROR"
|
||||
|
||||
|
||||
def test_build_logging_config_size_rotation(tmp_path: Path) -> None:
|
||||
settings = Settings()
|
||||
runtime = settings.runtime.model_copy(
|
||||
update={
|
||||
"log_dir": str(tmp_path),
|
||||
"log_error_dir": str(tmp_path / "errors"),
|
||||
"log_rotation": "size",
|
||||
"log_rotation_max_bytes": 2048,
|
||||
}
|
||||
)
|
||||
|
||||
config = build_logging_config(runtime)
|
||||
handlers = _get_handlers(config)
|
||||
|
||||
assert handlers["file"]["class"] == "logging.handlers.RotatingFileHandler"
|
||||
assert handlers["error"]["class"] == "logging.handlers.RotatingFileHandler"
|
||||
assert handlers["file"]["maxBytes"] == 2048
|
||||
|
||||
|
||||
def test_build_logging_config_plain_formatter_when_disabled(tmp_path: Path) -> None:
|
||||
settings = Settings()
|
||||
runtime = settings.runtime.model_copy(
|
||||
update={
|
||||
"log_dir": str(tmp_path),
|
||||
"log_error_dir": str(tmp_path / "errors"),
|
||||
"log_json": False,
|
||||
}
|
||||
)
|
||||
|
||||
config = build_logging_config(runtime)
|
||||
handlers = _get_handlers(config)
|
||||
|
||||
assert handlers["file"]["formatter"] == "plain"
|
||||
assert handlers["error"]["formatter"] == "plain"
|
||||
|
||||
|
||||
def _read_last_log_entry(log_path: Path) -> dict[str, object]:
|
||||
assert log_path.exists(), f"Expected log file at {log_path}"
|
||||
entries = [
|
||||
json.loads(line) for line in log_path.read_text().splitlines() if line.strip()
|
||||
]
|
||||
assert entries, "Expected at least one log entry in app.log"
|
||||
return entries[-1]
|
||||
|
||||
|
||||
def _flush_root_handlers() -> None:
|
||||
root_logger = logging.getLogger()
|
||||
for handler in root_logger.handlers:
|
||||
if hasattr(handler, "flush"):
|
||||
handler.flush()
|
||||
|
||||
|
||||
@pytest.fixture
|
||||
def configured_logging(tmp_path: Path) -> Iterator[Path]:
|
||||
settings = Settings()
|
||||
runtime = settings.runtime.model_copy(
|
||||
update={
|
||||
"log_dir": str(tmp_path),
|
||||
"log_error_dir": str(tmp_path / "errors"),
|
||||
"log_rotation": "size",
|
||||
"log_rotation_max_bytes": 2048,
|
||||
"log_json": True,
|
||||
}
|
||||
)
|
||||
root_logger = logging.getLogger()
|
||||
original_handlers = root_logger.handlers[:]
|
||||
original_level = root_logger.level
|
||||
|
||||
configure_logging(settings.model_copy(update={"runtime": runtime}))
|
||||
|
||||
yield tmp_path
|
||||
|
||||
for handler in root_logger.handlers:
|
||||
handler.close()
|
||||
root_logger.handlers = original_handlers
|
||||
root_logger.setLevel(original_level)
|
||||
structlog.reset_defaults()
|
||||
|
||||
|
||||
def test_stdlib_logging_redacts_sensitive_fields(configured_logging: Path) -> None:
|
||||
logger = logging.getLogger("tests.stdlib")
|
||||
logger.info("login", extra={"password": "secret", "token": "abc"})
|
||||
|
||||
_flush_root_handlers()
|
||||
|
||||
log_path = configured_logging / "app.log"
|
||||
entry = _read_last_log_entry(log_path)
|
||||
|
||||
assert entry["password"] == "[REDACTED]"
|
||||
assert entry["token"] == "[REDACTED]"
|
||||
|
||||
|
||||
def test_structlog_redacts_sensitive_fields(configured_logging: Path) -> None:
|
||||
logger = structlog.get_logger("tests.structlog")
|
||||
logger.info("login", password="secret", token="abc")
|
||||
|
||||
_flush_root_handlers()
|
||||
|
||||
log_path = configured_logging / "app.log"
|
||||
entry = _read_last_log_entry(log_path)
|
||||
|
||||
assert entry["password"] == "[REDACTED]"
|
||||
assert entry["token"] == "[REDACTED]"
|
||||
@@ -0,0 +1,30 @@
|
||||
from __future__ import annotations
|
||||
|
||||
from core.logging.filters import build_sensitive_data_processor
|
||||
|
||||
|
||||
def test_redact_sensitive_fields_masks_values() -> None:
|
||||
processor = build_sensitive_data_processor(
|
||||
["password", "token", "api_key", "cookie"]
|
||||
)
|
||||
|
||||
event: dict[str, object] = {
|
||||
"message": "login",
|
||||
"password": "secret",
|
||||
"access_token": "token-123",
|
||||
"apiKey": "apikey-123",
|
||||
"set-cookie": "cookie-1",
|
||||
"nested": {"token": "abc", "safe": "ok"},
|
||||
"list": [{"password": "x"}],
|
||||
}
|
||||
|
||||
redacted = processor(None, "info", event)
|
||||
|
||||
assert redacted["password"] == "[REDACTED]"
|
||||
assert redacted["access_token"] == "[REDACTED]"
|
||||
assert redacted["apiKey"] == "[REDACTED]"
|
||||
assert redacted["set-cookie"] == "[REDACTED]"
|
||||
assert redacted["nested"]["token"] == "[REDACTED]"
|
||||
assert redacted["nested"]["safe"] == "ok"
|
||||
assert redacted["list"][0]["password"] == "[REDACTED]"
|
||||
assert event["password"] == "secret"
|
||||
@@ -0,0 +1,35 @@
|
||||
from __future__ import annotations
|
||||
|
||||
from pytest import MonkeyPatch
|
||||
|
||||
from core.config.settings import Settings
|
||||
|
||||
|
||||
def test_runtime_settings_defaults() -> None:
|
||||
settings = Settings()
|
||||
|
||||
assert settings.runtime.log_json is True
|
||||
assert settings.runtime.log_rotation == "time"
|
||||
assert settings.runtime.log_rotation_when == "midnight"
|
||||
assert settings.runtime.log_rotation_interval == 1
|
||||
assert settings.runtime.log_rotation_backup_count == 14
|
||||
assert settings.runtime.log_rotation_max_bytes == 10_000_000
|
||||
assert settings.runtime.log_dir == "logs"
|
||||
assert settings.runtime.log_error_dir == "logs/errors"
|
||||
assert settings.runtime.log_file_name == "app.log"
|
||||
assert settings.runtime.log_error_file_name == "error.log"
|
||||
assert "password" in settings.runtime.log_sensitive_fields
|
||||
|
||||
|
||||
def test_runtime_settings_env_override(monkeypatch: MonkeyPatch) -> None:
|
||||
monkeypatch.setenv("SOCIAL_RUNTIME__LOG_DIR", "var/logs")
|
||||
monkeypatch.setenv("SOCIAL_RUNTIME__LOG_ERROR_DIR", "var/logs/errors")
|
||||
monkeypatch.setenv("SOCIAL_RUNTIME__LOG_ROTATION", "size")
|
||||
monkeypatch.setenv("SOCIAL_RUNTIME__LOG_ROTATION_MAX_BYTES", "2048")
|
||||
|
||||
settings = Settings()
|
||||
|
||||
assert settings.runtime.log_dir == "var/logs"
|
||||
assert settings.runtime.log_error_dir == "var/logs/errors"
|
||||
assert settings.runtime.log_rotation == "size"
|
||||
assert settings.runtime.log_rotation_max_bytes == 2048
|
||||
Reference in New Issue
Block a user