Логирование и конфиг: дерево логгеров по dot-именам, JSON-вывод и настройки, падающие на старте

Одно дерево, настроенное один раз

logging.getLogger("app.api.orders") не создаёт изолированный логгер — он создаёт (или возвращает: это реестр синглтонов) узел в дереве, ключованном dot-именем: app.api.orders — потомок app.api, тот — потомок app, и всё висит на корне. Запись, испущенная в узле, сначала проходит уровень этого узла, затем поднимается по дереву и предлагается обработчикам каждого предка — уровни предков повторно не проверяются, срабатывают только их обработчики. Эта асимметрия и есть весь контракт конфигурации: обработчики живут на корне, настраиваются один раз, в точке входа процесса; всё остальное просто пишет.

# main.py — ЕДИНСТВЕННОЕ место в процессе, настраивающее логирование
import logging.config

logging.config.dictConfig({
    "version": 1,
    "disable_existing_loggers": False,   # не глушить логгеры библиотек
    "formatters": {
        "json": {"()": "pythonjsonlogger.json.JsonFormatter",
                 "format": "%(asctime)s %(levelname)s %(name)s %(message)s"},
    },
    "handlers": {"stdout": {"class": "logging.StreamHandler", "formatter": "json"}},
    "root": {"level": "INFO", "handlers": ["stdout"]},
})

# любой другой модуль — и приложение, и библиотеки
import logging
logger = logging.getLogger(__name__)     # узел дерева; НИЧЕГО к нему не прикреплять

Библиотеки зовут getLogger(__name__) и не добавляют ничего — максимум NullHandler, чтобы погасить предупреждение «no handlers found». Классическое нарушение: автор библиотеки «услужливо» прикрепляет StreamHandler при импорте. Теперь каждая запись испускается этим обработчиком и, после подъёма по дереву, обработчиком корня — каждая строка в выводе дважды, и опсы неделю грепают дубликаты, пока кто-то не прочитает исходник библиотеки. Помодульная болтливость при этом остаётся дешёвой: пропишите loggers: {"app.api": {"level": "DEBUG"}} в том же dictConfig — и шумит только это поддерево.

Структурный JSON и correlation id

Прозаические логи можно только грепать; JSON-логи можно запрашивать — фильтровать по level, группировать по logger, считать перцентили duration_ms, джойнить по request_id. Именно это последнее поле превращает пятьдесят перемешанных потоков запросов в одну читаемую историю, и в асинхронных сервисах оно обязано приходить из contextvars (механизм контекстных переменных Python, изолированных на задачу), а не из threading.local — сотни задач чередуются в одном потоке, а ContextVar копируется на задачу, так что каждый запрос видит своё значение (тот же шов middleware, что вы строили в жизненном цикле запроса python/06):

import logging
from contextvars import ContextVar

request_id: ContextVar[str] = ContextVar("request_id", default="-")

class RequestIdFilter(logging.Filter):
    def filter(self, record: logging.LogRecord) -> bool:
        record.request_id = request_id.get()   # штампуется на КАЖДУЮ запись
        return True

# ASGI middleware выставляет его раз на запрос
async def correlation(request, call_next):
    request_id.set(request.headers.get("x-request-id") or new_id())
    return await call_next(request)

Два честных пути к JSON: python-json-logger — это подмена форматтера, пять строк dictConfig, семантика stdlib не тронута. structlog — второе мировоззрение логирования: связанные логгеры несут контекст (log = log.bind(user_id=...)) сквозь цепочки вызовов без фильтров, и это действительно лучшая эргономика, но половинчатое внедрение оставляет два формата в одном потоке и команду, не знающую, какой импорт правильный. Выберите одну позицию и мигрируйте сервисами целиком, а не файлами.

Дисциплина уровней и правило ленивого форматирования

logger.info("user %s rebalanced %d", uid, n) — это не стиль, а контракт отсрочки. Вызов логирования сначала проверяет isEnabledFor(INFO) (порядка сотни наносекунд); аргументы подставляются в шаблон, только если запись действительно будет испущена. logger.debug(f"user {user!r}") переворачивает это: f-строка вычисляется до вызова, каждый раз, даже при выключенном DEBUG — а repr жирного ORM-объекта стоит от микросекунд до миллисекунд. На нескольких миллионах вызовов в час на горячем пути это настоящий CPU, и именно он был тихим трёхнедельным налогом из Хука. У формы %s есть и второй выигрыш: шаблон сообщения постоянен, и пайплайн логов может группировать по шаблону и рисовать «эта строка стала срабатывать в 100 раз чаще» — f-строки дают уникальное сообщение на каждый вызов и убивают такую агрегацию.

Уровни — контракт пейджинга, а не ощущение серьёзности: ERROR значит, что человек должен действовать — если будить никого не нужно, это WARNING (деградация, самовосстановление, посмотреть утром) или INFO (смены состояния: старт, конфиг загружен, пул соединений). Команды, логирующие обработанные ретраи на ERROR, приучают дежурных игнорировать ERROR — и единственный настоящий пейдж тонет. DEBUG в проде по умолчанию выключен; когда нужен — включайте его для одного поддерева dot-имён через dictConfig и никогда на корне.

Настройки, падающие на старте

У конфигурационной половины дисциплины одно правило: неправильно сконфигурированный сервис обязан отказаться стартовать. pydantic-settings даёт механизм — типизированный класс, чьи поля читаются из окружения и валидируются при конструировании:

from pydantic import PostgresDsn, SecretStr
from pydantic_settings import BaseSettings

class Settings(BaseSettings):
    model_config = {"env_prefix": "APP_"}
    database_url: PostgresDsn        # ОБЯЗАТЕЛЬНО — без дефолта, иначе старт падает
    api_key: SecretStr               # repr и логи показывают '**********'
    log_level: str = "INFO"          # дефолт уместен, когда дефолт — БЕЗОПАСНЫЙ

settings = Settings()                # ValidationError НА СТАРТЕ, а не в 3 часа ночи

Отказ из-за дрейфа конфига, который это убивает: «разумный дефолт» вроде database_url = "postgres://staging-db/app" означает, что прод-деплой, забывший env-переменную, стартует зелёным и тихо гонит продакшен-трафик в staging — без падения, без пейджа, просто неправильные данные, пока аудит не заметит. Обязательные поля должны быть обязательными; падение в момент деплоя — это фича. SecretStr закрывает вторую утечку: секреты не появляются в repr, трейсбеках и дампе настроек, который вы логируете на старте (логируйте его — это самый дешёвый инструмент инцидентов из всех, что вы выпустите, — но с замаскированными секретами). Один образ, окружение на деплоймент: staging и прод различаются только env-переменными и никогда — путями в коде.