diff --git a/app/adapters/delivery_providers/cdek/client.py b/app/adapters/delivery_providers/cdek/client.py index b14abc3..c08e86e 100644 --- a/app/adapters/delivery_providers/cdek/client.py +++ b/app/adapters/delivery_providers/cdek/client.py @@ -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): diff --git a/app/main.py b/app/main.py index 3e70814..f1b2f22 100644 --- a/app/main.py +++ b/app/main.py @@ -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") diff --git a/app/runtime/__init__.py b/app/runtime/__init__.py new file mode 100644 index 0000000..7a3a3d8 --- /dev/null +++ b/app/runtime/__init__.py @@ -0,0 +1 @@ +"""Runtime support modules.""" diff --git a/app/runtime/logging.py b/app/runtime/logging.py new file mode 100644 index 0000000..99b0147 --- /dev/null +++ b/app/runtime/logging.py @@ -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() diff --git a/poetry.lock b/poetry.lock index da55cf8..02f5db9 100644 --- a/poetry.lock +++ b/poetry.lock @@ -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" diff --git a/pyproject.toml b/pyproject.toml index 00b2f41..df537b0 100644 --- a/pyproject.toml +++ b/pyproject.toml @@ -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" diff --git a/spec/index.md b/spec/index.md index 484526f..194cb44 100644 --- a/spec/index.md +++ b/spec/index.md @@ -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** diff --git a/spec/tasks/014_add_minimal_structlog_json_logging.md b/spec/tasks/014_add_minimal_structlog_json_logging.md new file mode 100644 index 0000000..58cbdfb --- /dev/null +++ b/spec/tasks/014_add_minimal_structlog_json_logging.md @@ -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` diff --git a/tests/logging/test_json_logging.py b/tests/logging/test_json_logging.py new file mode 100644 index 0000000..abbbfdf --- /dev/null +++ b/tests/logging/test_json_logging.py @@ -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 = [] diff --git a/tests/smoke/test_app_import.py b/tests/smoke/test_app_import.py index 393a61b..af7920a 100644 --- a/tests/smoke/test_app_import.py +++ b/tests/smoke/test_app_import.py @@ -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()