logging: уровни, handlers, formatters, root pitfalls

В первых уроках мы использовали print() для отладки (и pdb, когда print не хватало). В реальных приложениях это плохо: невозможно отключить, нет уровней, отсутствует контекст. Модуль logging решает это - стандартный, гибкий механизм журналирования. В этом уроке - устройство модуля, уровни, handlers, форматтеры и типичные ловушки.

Базовое использование

import logging

logging.basicConfig(level=logging.INFO)

logging.debug("debug message")     # не выведется - ниже уровня INFO
logging.info("started")             # выведется
logging.warning("disk almost full") # выведется
logging.error("connection failed")  # выведется
logging.critical("system crash")    # выведется

basicConfig настраивает root logger с дефолтным форматтером и handler в stderr. Сообщения с уровнем ниже level= игнорируются.

Уровни

DEBUG    (10) - подробная информация для отладки
INFO     (20) - подтверждение что всё идёт по плану
WARNING  (30) - что-то неожиданное, но работает
ERROR    (40) - функция не смогла выполниться
CRITICAL (50) - серьёзная проблема, может упасть программа

Уровни числовые - можно использовать константы logging.DEBUG, logging.INFO или числа 10, 20. Идиоматично - константы.

NOTSET (0) специальный - означает «без фильтра, используй уровень родителя».

Loggers - именованные журналы

Лучше использовать именованные loggers вместо root:

import logging

logger = logging.getLogger(__name__)   # имя = имя модуля

def process():
    logger.info("processing started")
    try:
        do_work()
    except Exception:
        logger.exception("failed")   # автоматически добавит traceback

__name__ это имя текущего модуля - например myapp.services.user. Это даёт hierarchy loggers, можно настраивать по subtree:

# Включаем DEBUG только для myapp.services
logging.getLogger("myapp.services").setLevel(logging.DEBUG)

Handlers - куда писать

import logging

logger = logging.getLogger("myapp")
logger.setLevel(logging.DEBUG)

# Handler 1 - всё в файл
file_handler = logging.FileHandler("app.log")
file_handler.setLevel(logging.DEBUG)
logger.addHandler(file_handler)

# Handler 2 - WARNING+ в stderr
console_handler = logging.StreamHandler()
console_handler.setLevel(logging.WARNING)
logger.addHandler(console_handler)

Один logger может иметь несколько handlers. Каждый со своим уровнем и форматом. Типичная схема: подробный лог в файл, предупреждения в console.

Полезные handlers:

  • StreamHandler - stdout/stderr
  • FileHandler - файл
  • RotatingFileHandler - файл с rotation по размеру
  • TimedRotatingFileHandler - rotation по времени
  • SysLogHandler - syslog
  • SMTPHandler - email при критических ошибках
  • HTTPHandler - POST на URL
  • NullHandler - ничего не делает

Formatters - как форматировать

formatter = logging.Formatter(
    "%(asctime)s - %(name)s - %(levelname)s - %(message)s"
)
file_handler.setFormatter(formatter)

Поля формата:

  • %(asctime)s - время
  • %(name)s - имя logger
  • %(levelname)s - INFO/ERROR/etc
  • %(message)s - само сообщение
  • %(filename)s, %(funcName)s, %(lineno)d - где залогирован
  • %(process)d, %(thread)d - process/thread id

Кастомный date format:

formatter = logging.Formatter(
    "%(asctime)s [%(levelname)s] %(message)s",
    datefmt="%Y-%m-%d %H:%M:%S",
)

Структурированное логирование

Для production лучше JSON-логи (модуль json разбирали в прошлом уроке) - удобнее парсить инструментами:

import logging
import json
from datetime import datetime, timezone

class JsonFormatter(logging.Formatter):
    def format(self, record):
        return json.dumps({
            "ts": datetime.now(timezone.utc).isoformat(),
            "level": record.levelname,
            "logger": record.name,
            "message": record.getMessage(),
            "module": record.module,
            "line": record.lineno,
        })

handler = logging.StreamHandler()
handler.setFormatter(JsonFormatter())

Это упрощённый пример. В production обычно используют python-json-logger или structlog - они мощнее.

logging.exception - с traceback

try:
    do_work()
except Exception:
    logger.exception("failed")   # автоматически добавит traceback

exception() это error() + traceback. Используется внутри except блока для логирования с полным stack trace. Один из самых полезных методов.

Параметризованные сообщения

# ПЛОХО - f-string evaluation даже если уровень ниже
logger.debug(f"processed {n} items in {elapsed}s")

# ХОРОШО - lazy формат
logger.debug("processed %s items in %s seconds", n, elapsed)

С %s placeholders форматирование происходит только если сообщение реально логируется. Для DEBUG, который часто отключен, это экономит CPU.

В современных проектах эту optimization часто игнорируют ради читаемости f-strings - performance impact обычно мизерный.

Иерархия loggers

parent = logging.getLogger("myapp")
child = logging.getLogger("myapp.module")

parent.setLevel(logging.WARNING)
# child наследует уровень

child.warning("test")   # выведется (через parent's handlers)

Сообщения propagate вверх по иерархии. Логирование в myapp.module сначала проверится локально, потом передастся в myapp, потом в root.

Отключить propagation:

child.propagate = False

Это полезно когда хочется свои handlers и не дублировать в parent.

Root logger - ловушка

# print() и logging.basicConfig могут не работать как ожидаешь
import logging
logging.basicConfig(level=logging.INFO)

# Где-то ещё в импортируемой библиотеке:
logging.basicConfig(level=logging.WARNING)   # уже настроен - игнорируется!

basicConfig() НЕ работает если root logger уже сконфигурирован. Если библиотека делает basicConfig до тебя - твоя конфигурация игнорируется. Решение - конфигурировать loggers через getLogger(), не root.

Также - library code не должен делать basicConfig. Это право приложения. Библиотеки используют getLogger(__name__) и оставляют конфигурацию пользователю.

NullHandler в библиотеках

# В __init__.py библиотеки
import logging
logging.getLogger("mylib").addHandler(logging.NullHandler())

NullHandler ничего не делает - но предотвращает warning «No handlers could be found for logger 'mylib'» если пользователь не настроил логирование.

Это стандартный паттерн для библиотек - дай пользователю контроль.

logging.dictConfig - полная конфигурация

Для сложных setups:

import logging.config

LOGGING = {
    "version": 1,
    "disable_existing_loggers": False,
    "formatters": {
        "default": {
            "format": "%(asctime)s [%(levelname)s] %(name)s: %(message)s",
        },
        "json": {
            "()": "myapp.JsonFormatter",
        },
    },
    "handlers": {
        "console": {
            "class": "logging.StreamHandler",
            "level": "INFO",
            "formatter": "default",
        },
        "file": {
            "class": "logging.handlers.RotatingFileHandler",
            "filename": "app.log",
            "maxBytes": 10485760,   # 10MB
            "backupCount": 5,
            "formatter": "json",
        },
    },
    "loggers": {
        "myapp": {
            "level": "DEBUG",
            "handlers": ["console", "file"],
        },
        "uvicorn": {
            "level": "INFO",
            "handlers": ["console"],
        },
    },
    "root": {
        "level": "WARNING",
        "handlers": ["console"],
    },
}

logging.config.dictConfig(LOGGING)

dictConfig это рекомендуемый способ настройки в production. Удобно загружать из YAML/JSON.

Когда какой уровень

  • DEBUG - переменные, control flow, всё подробно для отладки. В production обычно отключен.
  • INFO - старт/стоп компонентов, важные события (юзер зарегистрировался). Включён в production.
  • WARNING - что-то странное, но работает (deprecated API, retries). Stoit смотреть.
  • ERROR - функция упала, юзер увидит ошибку. Стоит реагировать.
  • CRITICAL - сервис не может работать. PagerDuty.

Хорошее правило: если ERROR/CRITICAL появляется - нужна реакция инженера. WARNING - инспекция и улучшение.

Контекст через extra

logger.info("user logged in", extra={"user_id": 123, "ip": "1.2.3.4"})

С formatter, который умеет работать с extra (или JSON formatter), получишь structured логи с контекстом. В Pydantic-based или structlog ещё проще.

ContextVar для request-scoped контекста

В async-приложениях для добавления request-id ко всем логам в запросе:

from contextvars import ContextVar

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

class ContextFilter(logging.Filter):
    def filter(self, record):
        record.request_id = request_id_var.get()
        return True

handler.addFilter(ContextFilter())
formatter = logging.Formatter(
    "%(asctime)s [%(request_id)s] %(message)s"
)

Все логи в обработке одного запроса получат тот же request_id - можно их связать.

Производительность

# Дорогое вычисление в debug сообщении
logger.debug(f"data: {expensive_serialization(data)}")
# expensive_serialization вызывается ВСЕГДА даже если debug отключён!

# Решение - lazy через if
if logger.isEnabledFor(logging.DEBUG):
    logger.debug(f"data: {expensive_serialization(data)}")

Или через %s placeholders - но они меньше работают для сложных выражений.

Сторонние альтернативы

  • structlog - structured logging с цепочками процессоров
  • loguru - простой API в стиле logger.info("...") без настройки
  • python-json-logger - JSON formatter из коробки

loguru особенно популярен для быстрого старта - один import и logger готов с красивым выводом. Для production обычно структурированный JSON через structlog или dictConfig. В контейнере логи пишут в stdout, а сбором и ротацией занимается платформа - смотри урок про Docker и CI.

Распространённые ошибки

1. logging.basicConfig в библиотеке

# library/__init__.py
import logging
logging.basicConfig(level=logging.INFO)   # НЕ ДЕЛАЙ ТАК

Это перехватывает конфигурацию приложения пользователя. Библиотеки должны использовать getLogger(__name__) + NullHandler() и оставлять конфиг приложению.

2. print() вместо logging в production

print(f"User {user.id} logged in")   # bad
logger.info("User logged in", extra={"user_id": user.id})   # good

print() нельзя отключить, нет уровней, нет timestamps. logging - стандарт для production.

3. logger.error без exception

try:
    do_work()
except Exception as e:
    logger.error(f"failed: {e}")   # без traceback

В except используй logger.exception() - получишь traceback. Critical для отладки.

4. Same logger в разных потоках без synchronization

# logging thread-safe ВНУТРИ - не нужны явные locks
logger.info("from thread")   # OK

logging безопасен для multi-thread. Но handler может быть несовместим (зависит от типа).

5. Логи с PII (personal identifying info)

logger.info(f"User authenticated: {user.password_hash}")   # ПЛОХО

Не логируй пароли, токены, ключи. Даже хеши. Применяй data masking для логирования sensitive info.

Сравнение с Go

В Go стандартный пакет log минимален, использует:

import "log"

log.Printf("error: %v", err)
log.Fatalf("fatal: %v", err)   // exit(1)

Для production обычно используют structured loggers: log/slog (стандарт с Go 1.21), zap, zerolog.

Семантически Python logging и Go slog похожи. Go более явный с уровнями (Info, Warn, Error через методы), Python через число/константу.

Мини-задание

  1. Базовая настройка:
import logging

logging.basicConfig(
    level=logging.INFO,
    format="%(asctime)s - %(name)s - %(levelname)s - %(message)s",
)

logger = logging.getLogger(__name__)
logger.info("application started")
logger.warning("disk space low")
  1. Logger с handlers:
import logging
from logging.handlers import RotatingFileHandler

logger = logging.getLogger("myapp")
logger.setLevel(logging.DEBUG)

console = logging.StreamHandler()
console.setLevel(logging.INFO)
console.setFormatter(logging.Formatter(
    "%(asctime)s [%(levelname)s] %(message)s"
))
logger.addHandler(console)

file = RotatingFileHandler("app.log", maxBytes=1024*1024, backupCount=5)
file.setLevel(logging.DEBUG)
file.setFormatter(logging.Formatter(
    "%(asctime)s [%(levelname)s] %(name)s:%(lineno)d - %(message)s"
))
logger.addHandler(file)

logger.debug("only in file")
logger.info("in both")
  1. Logger в библиотеке (правильный паттерн):
# mylib/__init__.py
import logging
logging.getLogger("mylib").addHandler(logging.NullHandler())

# mylib/module.py
import logging
logger = logging.getLogger(__name__)   # будет 'mylib.module'

def func():
    logger.debug("doing work")

Что дальше

Модуль 8 завершён. Освоили imports, packaging, и работу со стандартной библиотекой. В следующем модуле перейдём к тестированию: pytest, fixtures, mocking, линтеры и type checkers - инструменты для качественного backend-кода.

Зарегистрируйтесь бесплатно, чтобы пройти квиз, решить задание с автопроверкой и вести прогресс.