014 add json logging

2026-03-13 17:19:03 +03:00
parent 2bd884c8d5
commit 7c5be003c1
10 changed files with 224 additions and 14 deletions
@@ -1,9 +1,9 @@
 """CDEK HTTP client and provider adapter."""

 import asyncio
-import sys
 from collections.abc import Awaitable, Callable
 from typing import Any
+import logging

 import httpx

@@ -13,16 +13,7 @@ from app.adapters.delivery_providers.cdek.mapper import map_cdek_response
 from app.config import AdapterConfig
 from app.schemas.request import DeliveryRequest
 from app.schemas.response import DeliveryPrice
-import logging
-
-
-logging.basicConfig(
-    level=logging.INFO,
-    format="%(asctime)s [%(levelname)s] %(name)s: %(message)s",
-    handlers=[logging.StreamHandler(sys.stdout)]  # важно: stdout, не stderr
-)
 log = logging.getLogger(__name__)
-log.info("test")


 class CDEKClientError(RuntimeError):
@@ -4,9 +4,11 @@ from fastapi import FastAPI

 from app.config import Settings, get_settings
 from app.controllers.v1.delivery import router as delivery_router
+from app.runtime.logging import configure_logging


 def create_app(settings: Settings | None = None) -> FastAPI:
+    configure_logging()
    resolved_settings = settings or get_settings()

    application = FastAPI(title="G2S Aggregator", version="0.1.0")
@@ -0,0 +1 @@
+"""Runtime support modules."""
@@ -0,0 +1,78 @@
+"""Centralized runtime logging bootstrap."""
+
+import logging
+import sys
+from collections.abc import Iterable
+from typing import TextIO
+
+import structlog
+
+
+_UVICORN_LOGGER_NAMES = ("uvicorn", "uvicorn.error", "uvicorn.access")
+
+
+def configure_logging(
+    *,
+    log_level: int = logging.INFO,
+    stream: TextIO | None = None,
+) -> None:
+    resolved_stream = sys.stdout if stream is None else stream
+    formatter = structlog.stdlib.ProcessorFormatter(
+        foreign_pre_chain=list(_shared_processors()),
+        processors=[
+            structlog.stdlib.ProcessorFormatter.remove_processors_meta,
+            structlog.processors.JSONRenderer(sort_keys=True),
+        ],
+    )
+    handler = logging.StreamHandler(resolved_stream)
+    handler.setLevel(log_level)
+    handler.setFormatter(formatter)
+
+    structlog.reset_defaults()
+    structlog.configure(
+        processors=[
+            *_shared_processors(),
+            structlog.stdlib.PositionalArgumentsFormatter(),
+            structlog.processors.StackInfoRenderer(),
+            structlog.processors.format_exc_info,
+            structlog.stdlib.ProcessorFormatter.wrap_for_formatter,
+        ],
+        logger_factory=structlog.stdlib.LoggerFactory(),
+        wrapper_class=structlog.stdlib.BoundLogger,
+        cache_logger_on_first_use=True,
+    )
+
+    _configure_logger(logging.getLogger(), handler=handler, log_level=log_level)
+    for logger_name in _UVICORN_LOGGER_NAMES:
+        _configure_logger(
+            logging.getLogger(logger_name),
+            handler=handler,
+            log_level=log_level,
+            propagate=False,
+        )
+
+
+def _shared_processors() -> tuple[structlog.types.Processor, ...]:
+    return (
+        structlog.stdlib.add_logger_name,
+        structlog.stdlib.add_log_level,
+        structlog.processors.TimeStamper(fmt="iso", utc=True),
+    )
+
+
+def _configure_logger(
+    logger: logging.Logger,
+    *,
+    handler: logging.Handler,
+    log_level: int,
+    propagate: bool = True,
+) -> None:
+    _clear_handlers(logger.handlers)
+    logger.setLevel(log_level)
+    logger.handlers = [handler]
+    logger.propagate = propagate
+
+
+def _clear_handlers(handlers: Iterable[logging.Handler]) -> None:
+    for existing_handler in list(handlers):
+        existing_handler.close()
@@ -682,6 +682,26 @@ wrapt = ">=1.0.0,<2.0.0"
 [package.extras]
 instruments = ["httpx (>=0.18.0)"]

+[[package]]
+name = "opentelemetry-instrumentation-redis"
+version = "0.61b0"
+description = "OpenTelemetry Redis instrumentation"
+optional = false
+python-versions = ">=3.9"
+files = [
+    {file = "opentelemetry_instrumentation_redis-0.61b0-py3-none-any.whl", hash = "sha256:8d4e850bbb5f8eeafa44c0eac3a007990c7125de187bc9c3659e29ff7e091172"},
+    {file = "opentelemetry_instrumentation_redis-0.61b0.tar.gz", hash = "sha256:ae0fbb56be9a641e621d55b02a7d62977a2c77c5ee760addd79b9b266e46e523"},
+]
+
+[package.dependencies]
+opentelemetry-api = ">=1.12,<2.0"
+opentelemetry-instrumentation = "0.61b0"
+opentelemetry-semantic-conventions = "0.61b0"
+wrapt = ">=1.12.1"
+
+[package.extras]
+instruments = ["redis (>=2.6)"]
+
 [[package]]
 name = "opentelemetry-proto"
 version = "1.40.0"
@@ -1592,4 +1612,4 @@ type = ["pytest-mypy"]
 [metadata]
 lock-version = "2.0"
 python-versions = "^3.14"
-content-hash = "954a8ff26e6abe5321bb634e27f6f458037ec59947f24ac7385623e5575fb817"
+content-hash = "3156d28f769918f0fc547653c11a84e33728d9abed9e7be1a885aa7ae512d6dd"
@@ -19,6 +19,7 @@ opentelemetry-sdk = "^1.40.0"
 opentelemetry-exporter-otlp = "^1.40.0"
 opentelemetry-instrumentation-fastapi = "^0.61b0"
 opentelemetry-instrumentation-httpx = "^0.61b0"
+opentelemetry-instrumentation-redis = "^0.61b0"
 pytest = "^9.0.2"
 redis = "^7.3.0"

@@ -1,7 +1,7 @@
 # Spec Tasks Index

 > ⚠️ This file is generated. Do not edit manually.
-> Generated at (UTC): `2026-03-09T13:13:56+00:00`
+> Generated at (UTC): `2026-03-13T14:18:34+00:00`

 ## Tasks

@@ -21,9 +21,10 @@
 | 011 | DONE | 2026-03-08 | Migrate Redis repository client to aioredis | `spec/tasks/011_migrate_redis_repository_to_aioredis.md` |
 | 012 | DONE | 2026-03-08 | Remove observability and SigNoz stack for phase 1 | `spec/tasks/012_remove_observability_and_signoz_for_phase1.md` |
 | 013 | DONE | 2026-03-09 | Add configurable provider price multiplier in domain logic | `spec/tasks/013_add_configurable_provider_price_multiplier.md` |
+| 014 | DONE | 2026-03-12 | Add minimal structlog JSON logging | `spec/tasks/014_add_minimal_structlog_json_logging.md` |

 ## Summary

- Total: **14**
+- Total: **15**
 - TODO: **0**
- DONE: **14**
+- DONE: **15**
@@ -0,0 +1,44 @@
+---
+id: 014
+title: Add minimal structlog JSON logging
+status: DONE
+created: 2026-03-12
+---
+
+## Context
+После удаления observability stack приложение осталось без централизованной конфигурации логирования. При этом в runtime-коде есть локальная настройка `logging.basicConfig(...)`, а новое требование состоит в том, чтобы все runtime-логи приложения выводились в JSON без возврата tracing, metrics и alerting.
+
+## Goal
+Подключить минимальную централизованную настройку `structlog`, чтобы runtime-логи приложения и Uvicorn выводились как JSON-объекты, а прикладные модули использовали общий logging setup вместо локальной конфигурации.
+
+## Constraints
+- Соблюдать layered architecture из `AGENTS.md`.
+- Scope задачи: только logging wiring, JSON formatting и интеграция существующих logger calls.
+- `structlog` использовать только для JSON logging; не добавлять `request_id`, `trace_id`, OpenTelemetry, metrics, SigNoz, Telegram и иные observability features.
+- Конфигурация логирования должна быть централизована на уровне app startup или отдельного runtime-модуля; в Controller, Service, Repository, Adapter и Business Logic запрещено вызывать `logging.basicConfig(...)`.
+- Не изменять API contract, business rules, provider protocol, cache behavior и логику обработки ошибок.
+- используй context7, чтобы узнать контракт текущей версии пакета structlog
+
+## Acceptance criteria
+- При старте приложения выполняется единая инициализация logging на базе `structlog`.
+- Логи приложения и `uvicorn.error`/`uvicorn.access` сериализуются в JSON, одна запись на строку.
+- Каждая лог-запись содержит как минимум поля `event`, `level`, `timestamp` и `logger`.
+- В прикладных модулях отсутствуют локальные вызовы `logging.basicConfig(...)` и текстовые formatter-конфигурации для runtime logging.
+- Добавлен тест, который валидирует emitted log line как корректный JSON и проверяет обязательные поля.
+
+## Definition of Done
+- [ ] Добавлена централизованная конфигурация JSON logging на базе `structlog`.
+- [ ] Удалены локальные настройки logging из прикладных модулей.
+- [ ] `uvicorn.error` и `uvicorn.access` подключены к тому же JSON logging setup.
+- [ ] Добавлены или обновлены тесты для logging bootstrap и JSON serialization.
+- [ ] Пройдены все команды из раздела Commands.
+
+## Tests
+- Добавить `tests/logging/test_json_logging.py` для проверки JSON serialization и обязательных полей лог-записи.
+- Обновить `tests/smoke/test_app_import.py` для проверки вызова централизованного logging bootstrap при создании app.
+- При изменении конфигурации Uvicorn loggers добавить тест на `uvicorn.error` и `uvicorn.access` без запуска реального сервера.
+
+## Commands
+- `poetry run pytest tests/logging/test_json_logging.py -q`
+- `poetry run pytest tests/smoke/test_app_import.py -q`
+- `poetry run pytest tests/adapters/delivery_providers/cdek/test_client.py -q`
@@ -0,0 +1,56 @@
+import json
+import logging
+from io import StringIO
+
+import structlog
+
+from app.runtime.logging import configure_logging
+
+
+def test_application_log_is_serialized_as_json() -> None:
+    stream = StringIO()
+
+    configure_logging(stream=stream)
+
+    logging.getLogger("app.test").info("application_event")
+
+    payload = json.loads(stream.getvalue().splitlines()[0])
+
+    assert payload["event"] == "application_event"
+    assert payload["level"] == "info"
+    assert payload["logger"] == "app.test"
+    assert isinstance(payload["timestamp"], str)
+
+    _reset_logging()
+
+
+def test_uvicorn_loggers_use_shared_json_logging_setup() -> None:
+    stream = StringIO()
+
+    configure_logging(stream=stream)
+
+    logging.getLogger("uvicorn.error").error("uvicorn_error_event")
+    logging.getLogger("uvicorn.access").info("uvicorn_access_event")
+
+    records = [json.loads(line) for line in stream.getvalue().splitlines()]
+
+    assert [record["event"] for record in records] == [
+        "uvicorn_error_event",
+        "uvicorn_access_event",
+    ]
+    assert [record["logger"] for record in records] == [
+        "uvicorn.error",
+        "uvicorn.access",
+    ]
+    assert all(record["level"] in {"error", "info"} for record in records)
+    assert all(isinstance(record["timestamp"], str) for record in records)
+
+    _reset_logging()
+
+
+def _reset_logging() -> None:
+    structlog.reset_defaults()
+    root_logger = logging.getLogger()
+    root_logger.handlers = []
+    for logger_name in ("uvicorn", "uvicorn.error", "uvicorn.access"):
+        logging.getLogger(logger_name).handlers = []
@@ -6,9 +6,11 @@ from fastapi import FastAPI

 from app import config as config_module
 from app.config import Settings, get_settings
+from app.runtime import logging as logging_module

 TEST_CONFIG_FILE = Path(__file__).resolve().parents[2] / "config.test.yaml"

+
 def _import_main_module(monkeypatch):
    get_settings.cache_clear()
    monkeypatch.setattr(config_module, "TEST_CONFIG_FILE", str(TEST_CONFIG_FILE))
@@ -17,14 +19,27 @@ def _import_main_module(monkeypatch):


 def test_app_import_smoke(monkeypatch) -> None:
+    bootstrap_calls: list[None] = []
+
+    def fake_configure_logging() -> None:
+        bootstrap_calls.append(None)
+
+    monkeypatch.setattr(logging_module, "configure_logging", fake_configure_logging)
    main_module = _import_main_module(monkeypatch)

    assert isinstance(main_module.app, FastAPI)
    assert isinstance(main_module.app.state.settings, Settings)
+    assert bootstrap_calls == [None]
    get_settings.cache_clear()


 def test_app_created_with_provided_settings(monkeypatch) -> None:
+    bootstrap_calls: list[None] = []
+
+    def fake_configure_logging() -> None:
+        bootstrap_calls.append(None)
+
+    monkeypatch.setattr(logging_module, "configure_logging", fake_configure_logging)
    main_module = _import_main_module(monkeypatch)
    monkeypatch.setattr(config_module, "TEST_CONFIG_FILE", str(TEST_CONFIG_FILE))

@@ -32,4 +47,5 @@ def test_app_created_with_provided_settings(monkeypatch) -> None:
    instance = main_module.create_app(settings=settings)

    assert instance.state.settings is settings
+    assert bootstrap_calls == [None, None]
    get_settings.cache_clear()