Введение в логирование — Python Logging: от основ

Введение в логирование в Python

Логирование — это не просто «запись в файл». Это инструмент observability, который позволяет понять, что происходит в приложении без изменения кода. Хорошее логирование экономит часы расследования инцидентов.

#1. Зачем нужно логирование

#1.1. Проблема: что происходит в production?

Сценарий: Production-система упала в 3 часа ночи. PagerDuty будит дежурного инженера.

Вопросы, на которые нужно ответить за 15 минут:

Какой запрос вызвал падение?
Какой пользователь столкнулся с проблемой?
Какая ошибка произошла?
Какие данные были на входе?

Без логирования:

❌ Нет информации о запросе
❌ Непонятно, какой код выполнялся
❌ Невозможно воспроизвести проблему
❌ Расследование занимает часы/дни

С логированием:

✅ request_id=abc-123 → найдены все логи запроса
✅ user_id=42, order_id=100500 → понятен контекст
✅ ERROR: DatabaseTimeout → понятна причина
✅ Воспроизведение: повторить запрос с теми же параметрами

#1.2. print() vs logging

Проблема: Начинающие разработчики используют print() для отладки.

# ❌ Плохо: print()
print("Error occurred")
print(f"User {user_id} logged in")
print("Processing data...")

# Проблемы print():
# 1. Нет уровней — всё выводится всегда
# 2. Нет timestamp — непонятно когда произошло
# 3. Нет имени модуля — непонятно откуда лог
# 4. Нельзя отключить без изменения кода
# 5. Нет контекста (user_id, request_id)
# 6. Невозможно фильтровать и искать
# 7. Пишет только в stdout

# ✅ Хорошо: logging
import logging

logger = logging.getLogger(__name__)

logger.debug("Processing user data", extra={"user_id": user_id})
logger.info("User logged in", extra={"user_id": user_id, "ip": request.ip})
logger.warning("Rate limit approaching", extra={"user_id": user_id, "remaining": 5})
logger.error("Database connection failed", exc_info=True)
logger.critical("Service unavailable", extra={"service": "payments"})

# Преимущества logging:
# 1. Уровни: DEBUG, INFO, WARNING, ERROR, CRITICAL
# 2. Timestamp автоматически добавляется
# 3. Имя модуля в __name__
# 4. Можно настроить через конфигурацию
# 5. Контекст через extra={}
# 6. Фильтрация по полям в ELK/Kibana
# 7. Гибкие handlers: файл, консоль, email, Sentry, CloudWatch

#1.3. Сценарии использования

Сценарий	Уровень	Пример	В production
Детали работы алгоритма	`DEBUG`	`logger.debug(f"Cache hit for key: {key}")`	❌ Отключён
Бизнес-события	`INFO`	`logger.info("Order created", extra={"order_id": order.id})`	✅ Включён
Необычная ситуация	`WARNING`	`logger.warning("Rate limit at 90%")`	✅ Включён
Ошибка операции	`ERROR`	`logger.error("Payment failed", exc_info=True)`	✅ Включён
Критический сбой	`CRITICAL`	`logger.critical("Database unreachable")`	✅ Включён

#2. Уровни логирования

#2.1. Стандартные уровни

import logging

# Уровни по возрастанию важности:
logging.DEBUG     # 10 — Детальная отладочная информация
logging.INFO      # 20 — Обычные события работы приложения
logging.WARNING   # 30 — Предупреждения, необычные ситуации
logging.ERROR     # 40 — Ошибки, операция не выполнена
logging.CRITICAL  # 50 — Критические сбои, приложение не может продолжать

#2.2. Когда использовать каждый уровень

#DEBUG (10) — Детальная отладка

Использование: Development, staging, расследование проблем.

# ✅ Хорошо: детали для отладки
logger.debug(f"SQL query: {query}")
logger.debug(f"Cache hit for key: {cache_key}")
logger.debug(f"Processing batch {batch_num}/{total_batches}")

# ❌ Плохо: слишком много деталей в production
for item in items:
    logger.debug(f"Processing item {item.id}")  # 100K логов!

Правило: В production DEBUG отключён. Включайте временно для расследования.

#INFO (20) — Бизнес-события

Использование: Production, важные события работы приложения.

# ✅ Хорошо: бизнес-события
logger.info("Application started", extra={"version": "1.2.3", "env": "production"})
logger.info("User logged in", extra={"user_id": user.id, "ip": request.ip})
logger.info("Order created", extra={"order_id": order.id, "amount": order.total})
logger.info("Scheduled job completed", extra={"job": "cleanup", "duration_ms": duration})

# ❌ Плохо: тривиальные операции
logger.info("Function called")  # Бесполезно
logger.info("Variable x = 5")   # Не бизнес-событие

Правило: INFO — это история того, что произошло важного в приложении.

#WARNING (30) — Предупреждения

Использование: Необычные ситуации, которые не являются ошибками.

# ✅ Хорошо: предупреждения
logger.warning("Cache miss rate exceeded 50%")
logger.warning("Deprecated API endpoint called", extra={"endpoint": "/api/v1/users"})
logger.warning("Rate limit approaching", extra={"user_id": user.id, "remaining": 10})
logger.warning("Retry attempt 3/5 for external API")

# ❌ Плохо: это не предупреждение
logger.warning("User logged in")  # Это INFO
logger.warning("Database error")   # Это ERROR

Правило: WARNING — что-то необычное, но приложение работает корректно.

#ERROR (40) — Ошибки

Использование: Операция не выполнена, но приложение продолжает работать.

# ✅ Хорошо: ошибки с контекстом
try:
    process_payment(order)
except PaymentError as e:
    logger.error(
        "Payment processing failed",
        extra={
            "order_id": order.id,
            "user_id": user.id,
            "amount": order.total,
            "error_type": type(e).__name__,
        },
        exc_info=True
    )

# ❌ Плохо: ошибка без контекста
except Exception as e:
    logger.error(f"Error: {e}")  # Какой заказ? Какой пользователь?

Правило: ERROR требует расследования. Всегда добавляйте контекст.

#CRITICAL (50) — Критические сбои

Использование: Приложение не может продолжать работу.

# ✅ Хорошо: критические сбои
if not database_connection:
    logger.critical(
        "Database unreachable, shutting down",
        extra={
            "host": db_host,
            "port": db_port,
            "error": str(exc),
        }
    )
    sys.exit(1)

if not config_required_value:
    logger.critical("Required configuration missing: DB_HOST")
    sys.exit(1)

Правило: CRITICAL требует немедленного реагирования. Используйте редко.

#2.3. Настройка уровня логирования

import logging

# Установка уровня для logger
logger = logging.getLogger(__name__)
logger.setLevel(logging.DEBUG)  # Принимает все сообщения от DEBUG и выше

# Установка уровня для root logger
logging.basicConfig(level=logging.INFO)  # INFO и выше

# Установка уровня для handler
handler = logging.FileHandler('app.log')
handler.setLevel(logging.WARNING)  # Только WARNING и выше

Иерархия уровней:

logger.setLevel(DEBUG) + handler.setLevel(WARNING)
    → выводятся WARNING и выше (пересечение)

logger.setLevel(INFO) + handler.setLevel(DEBUG)
    → выводятся INFO и выше (logger ограничивает)

Сообщение должно пройти уровень И logger, И handler.

#3. Архитектура logging

#3.1. Компоненты

┌─────────────────────────────────────────────────────────────┐
│                  Архитектура Python Logging                 │
└─────────────────────────────────────────────────────────────┘

Приложение
    │ logger.info("Message", extra={...})
    ▼
┌──────────────────┐
│     Logger       │  ← Принимает сообщения от приложения
│  getLogger(__name__)  ← Фильтрует по уровню
└────────┬─────────┘
         │ LogRecord (создаётся автоматически)
         ▼
┌──────────────────┐
│    Filter(s)     │  ← Кастомная фильтрация (опционально)
└────────┬─────────┘
         │
         ▼
┌──────────────────┐
│   Handler(s)     │  ← Определяет куда: файл, консоль, email
│  FileHandler     │  ← Фильтрует по уровню
│  StreamHandler   │
└────────┬─────────┘
         │
         ▼
┌──────────────────┐
│   Formatter      │  ← Форматирует сообщение
└────────┬─────────┘
         │
         ▼
    Вывод лога

#3.2. Logger — точка входа

Проблема: Нужно создать объект для логирования в модуле.

Решение: getLogger(__name__) создаёт logger с именем модуля.

# В файле app/api/users.py
import logging

logger = logging.getLogger(__name__)
# Имя logger: 'app.api.users'

# Иерархия:
# app.api.users → app.api → app → root

Преимущества именованных logger'ов:

Можно настроить разный уровень для разных модулей
Легко фильтровать логи по имени
Понятно, откуда пришло сообщение

Пример конфигурации по модулям:

# Разные уровни для разных модулей
logging.getLogger('app').setLevel(logging.INFO)
logging.getLogger('app.db').setLevel(logging.WARNING)  # Меньше шума от DB
logging.getLogger('app.api').setLevel(logging.DEBUG)  # Детально для API

#3.3. Handler — куда отправлять

Проблема: Нужно отправить логи в определённое место.

Решение: Handler определяет destination.

import logging

# Консоль
console_handler = logging.StreamHandler()

# Файл
file_handler = logging.FileHandler('app.log')

# Файл с ротацией по размеру
from logging.handlers import RotatingFileHandler
rotating_handler = RotatingFileHandler(
    'app.log',
    maxBytes=10*1024*1024,  # 10 MB
    backupCount=5
)

# Email при ошибках
from logging.handlers import SMTPHandler
smtp_handler = SMTPHandler(
    mailhost=('smtp.example.com', 587),
    fromaddr='app@example.com',
    toaddrs=['oncall@example.com'],
    subject='Application Error'
)
smtp_handler.setLevel(logging.ERROR)  # Только ERROR+

# Добавление handlers к logger
logger.addHandler(console_handler)
logger.addHandler(file_handler)

#3.4. Formatter — форматирование

Проблема: Нужно форматировать сообщения логов.

Решение: Formatter определяет формат вывода.

import logging

# Простой формат
formatter = logging.Formatter('%(levelname)s: %(message)s')
# Вывод: INFO: User logged in

# Подробный формат
formatter = logging.Formatter(
    '%(asctime)s - %(name)s - %(levelname)s - %(message)s'
)
# Вывод: 2026-03-21 10:00:00,123 - app.api.users - INFO - User logged in

# С контекстом
formatter = logging.Formatter(
    '%(asctime)s - %(levelname)s - %(message)s - user_id=%(user_id)s'
)

handler.setFormatter(formatter)

Популярные формат-переменные:

Переменная	Значение	Пример
`%(asctime)s`	Timestamp	`2026-03-21 10:00:00,123`
`%(name)s`	Имя logger	`app.api.users`
`%(levelname)s`	Уровень	`INFO`, `ERROR`
`%(message)s`	Сообщение	`User logged in`
`%(filename)s`	Имя файла	`users.py`
`%(lineno)d`	Номер строки	`42`
`%(funcName)s`	Имя функции	`create_user`
`%(process)d`	PID процесса	`12345`
`%(thread)d`	ID потока	`98765`

#3.5. Filter — кастомная фильтрация

Проблема: Нужно фильтровать сообщения по кастомным условиям.

Решение: Filter решает, пропустить ли LogRecord.

import logging

# Встроенная фильтрация по уровню
handler.setLevel(logging.WARNING)

# Кастомный фильтр
class SensitiveDataFilter(logging.Filter):
    """Маскирует чувствительные данные в логах."""
    def filter(self, record):
        message = record.getMessage()
        if 'password' in message.lower():
            return False  # Не логировать
        return True

logger.addFilter(SensitiveDataFilter())

# Фильтр по имени logger
class ModuleFilter(logging.Filter):
    def __init__(self, allowed_modules):
        super().__init__()
        self.allowed_modules = allowed_modules
    
    def filter(self, record):
        return any(
            record.name.startswith(mod)
            for mod in self.allowed_modules
        )

logger.addFilter(ModuleFilter(['app.api', 'app.db']))

#4. Propagation (Распространение логов)

#4.1. Как работает propagation

import logging

# Настройка root logger
logging.basicConfig(level=logging.INFO)
root_logger = logging.getLogger()
root_logger.info("Root message")  # Выводится

# Дочерний logger
child_logger = logging.getLogger('app.api')
child_logger.info("Child message")  # Выводится через root logger

# Propagation по умолчанию включён
# app.api → app → root

Схема:

child_logger.info("Message")
    ↓
app.api (свой handler? → вывод)
    ↓ propagate=True
app (свой handler? → вывод)
    ↓ propagate=True
root (handler от basicConfig → вывод)

#4.2. Когда отключать propagation

Проблема: Дублирование логов.

# ❌ Проблема: дублирование
logging.basicConfig(level=logging.INFO)  # Handler в root
logger = logging.getLogger('app')
logger.addHandler(logging.StreamHandler())  # Ещё handler
logger.info("Test")  # Выводится дважды!

Решение:

# ✅ Решение 1: отключить propagation
logger = logging.getLogger('app')
logger.addHandler(logging.StreamHandler())
logger.propagate = False  # Не передавать в root

# ✅ Решение 2: не добавлять handler в root
# (не использовать basicConfig, настроить через dictConfig)

#5. Базовая конфигурация

#5.1. basicConfig — для простых случаев

import logging

logging.basicConfig(
    level=logging.INFO,
    format='%(asctime)s - %(name)s - %(levelname)s - %(message)s',
    handlers=[
        logging.StreamHandler(),  # Консоль
        logging.FileHandler('app.log')  # Файл
    ]
)

logger = logging.getLogger(__name__)
logger.info("Application started")

Ограничения basicConfig:

Настраивает только root logger
Нельзя настроить несколько logger'ов с разными настройками
Нельзя настроить кастомные фильтры
Работает только один раз (повторные вызовы игнорируются)

Для production используйте dictConfig() (рассмотрено в теме "Конфигурация логирования").

#6. Логирование исключений

#6.1. exc_info и exception()

Проблема: Нужно залогировать ошибку с traceback.

import logging

try:
    risky_operation()
except Exception as e:
    # ❌ Плохо: нет traceback
    logger.error(f"Error: {e}")
    
    # ✅ Хорошо: с traceback
    logger.error("Operation failed", exc_info=True)
    
    # ✅ Или: logger.exception() (только внутри except)
    logger.exception("Operation failed")

Вывод:

ERROR:app:Operation failed
Traceback (most recent call last):
  File "app.py", line 10, in <module>
    risky_operation()
  File "app.py", line 5, in risky_operation
    raise ValueError("Invalid data")
ValueError: Invalid data

#6.2. Контекст при ошибках

try:
    process_payment(order)
except PaymentError as e:
    logger.error(
        "Payment processing failed",
        extra={
            "order_id": order.id,
            "user_id": user.id,
            "amount": order.total,
            "payment_method": order.payment_method,
            "error_type": type(e).__name__,
        },
        exc_info=True
    )

#7. Логирование с контекстом

#7.1. extra={} для контекста

Проблема: Нужно добавить контекст (user_id, request_id) в логи.

logger.info(
    "User action completed",
    extra={
        "user_id": user.id,
        "request_id": request.id,
        "action": "purchase",
        "duration_ms": duration,
    }
)

Для использования в formatter:

formatter = logging.Formatter(
    '%(asctime)s - %(levelname)s - %(message)s - user_id=%(user_id)s'
)

#7.2. LoggerAdapter для автоматического контекста

import logging

logger = logging.getLogger(__name__)

# Создание адаптера с контекстом
adapter = logging.LoggerAdapter(
    logger,
    extra={
        "request_id": "abc-123",
        "user_id": 42
    }
)

# Контекст добавляется автоматически
adapter.info("Request started")
adapter.info("Processing data", extra={"records": 100})

#8. Best Practices

#8.1. Что логировать

✅ Логировать:

Вход/выход из важных функций (INFO)
Ошибки с контекстом (ERROR + exc_info)
Изменения состояния (создание пользователя, заказ)
Внешние вызовы (API, БД) с duration
Необычные ситуации (WARNING)

❌ Не логировать:

Пароли, токены, секретные ключи
Персональные данные без необходимости (GDPR, PCI DSS)
Каждую итерацию цикла (используйте агрегацию)
Тривиальные операции ("function called")

#8.2. Именование logger'ов

# ✅ Хорошо: использовать __name__
logger = logging.getLogger(__name__)

# ✅ Хорошо: явное имя для специфичных случаев
logger = logging.getLogger('app.audit')

# ❌ Плохо: одинаковое имя во всех модулях
logger = logging.getLogger('my_logger')

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

# ❌ Плохо: строка формируется всегда
logger.debug(f"Processing {len(items)} items: {expensive_serialize(items)}")

# ✅ Хорошо: проверка перед форматированием
if logger.isEnabledFor(logging.DEBUG):
    logger.debug("Processing %d items: %s", len(items), items)

# ✅ Хорошо: % форматирование (ленивое)
logger.debug("Processing %d items", len(items))  # Форматируется только если DEBUG включён

#8.4. Форматирование строк

# ✅ Хорошо: % форматирование (рекомендуется для logging)
logger.info("User %s logged in from %s", user_id, ip)

# ✅ Допустимо: f-strings (для простых случаев)
logger.info(f"User {user_id} logged in")

# ❌ Плохо: + конкатенация
logger.info("User " + str(user_id) + " logged in")

#9. Типичные ошибки

#9.1. Логи не выводятся

Причины:

Уровень logger выше, чем сообщение
Нет handlers
Handler уровень выше, чем сообщение
basicConfig вызван после первого лога

Диагностика:

logger = logging.getLogger(__name__)
print(f"Level: {logger.level}")  # 0 = NOTSET (наследуется от родителя)
print(f"Handlers: {logger.handlers}")  # Пусто?
print(f"Effective level: {logger.getEffectiveLevel()}")  # Реальный уровень

#9.2. Дублирование логов

Причины:

Handler в logger + handler в root logger (propagation)
Handler добавлен дважды

Решение:

# Проверить handlers
print(f"Logger handlers: {logger.handlers}")
print(f"Root handlers: {logging.getLogger().handlers}")

# Отключить propagation
logger.propagate = False

# Или не добавлять handler в root

#9.3. basicConfig не работает

Причина: basicConfig работает только один раз, до первого лога.

# ❌ Плохо: второй вызов игнорируется
logging.basicConfig(level=logging.INFO)
logger.info("test")  # Первый лог
logging.basicConfig(level=logging.DEBUG)  # Игнорируется!

# ✅ Хорошо: один вызов в начале приложения
if __name__ == '__main__':
    logging.basicConfig(level=logging.INFO)
    # ... остальной код

#Резюме

#Ключевые концепции

Концепция	Описание
Logger	Точка входа для логирования, создаётся через `getLogger(__name__)`
Handler	Определяет куда: файл, консоль, email, сеть
Formatter	Определяет формат: timestamp, уровень, сообщение
Filter	Кастомная фильтрация по условиям
Propagation	Передача логов родительским logger'ам

#Уровни логирования

Уровень	Число	Когда использовать
`DEBUG`	10	Детали для отладки (development)
`INFO`	20	Бизнес-события (production)
`WARNING`	30	Необычные ситуации
`ERROR`	40	Ошибки операций
`CRITICAL`	50	Критические сбои

#Best Practices

Используйте logging.getLogger(__name__) для создания logger'ов
Уровень INFO для production, DEBUG только для отладки
Всегда добавляйте контекст через extra={}
Используйте exc_info=True для ошибок
Не логируйте чувствительные данные (пароли, токены)
Используйте isEnabledFor() для дорогих операций
Для production используйте dictConfig, не basicConfig
Отключайте propagate=False если добавляете handler к logger

#Следующие шаги

Базовое использование logging — детальное изучение компонентов
Конфигурация логирования — production конфигурации
Структурированное логирование — JSON логи для ELK

❌ Нет информации о запросе ❌ Непонятно, какой код выполнялся ❌ Невозможно воспроизвести проблему ❌ Расследование занимает часы/дни

✅ request_id=abc-123 → найдены все логи запроса ✅ user_id=42, order_id=100500 → понятен контекст ✅ ERROR: DatabaseTimeout → понятна причина ✅ Воспроизведение: повторить запрос с теми же параметрами

Сценарий

Уровень

Пример

В production

Детали работы алгоритма

DEBUG

logger.debug(f"Cache hit for key: {key}")

❌ Отключён

Бизнес-события

INFO

logger.info("Order created", extra={"order_id": order.id})

✅ Включён

Необычная ситуация

WARNING

logger.warning("Rate limit at 90%")

✅ Включён

Ошибка операции

ERROR

logger.error("Payment failed", exc_info=True)

✅ Включён

Критический сбой

CRITICAL

logger.critical("Database unreachable")

✅ Включён

logger.setLevel(DEBUG) + handler.setLevel(WARNING) → выводятся WARNING и выше (пересечение) logger.setLevel(INFO) + handler.setLevel(DEBUG) → выводятся INFO и выше (logger ограничивает)

┌─────────────────────────────────────────────────────────────┐ │ Архитектура Python Logging │ └─────────────────────────────────────────────────────────────┘ Приложение │ logger.info("Message", extra={...}) ▼ ┌──────────────────┐ │ Logger │ ← Принимает сообщения от приложения │ getLogger(__name__) ← Фильтрует по уровню └────────┬─────────┘ │ LogRecord (создаётся автоматически) ▼ ┌──────────────────┐ │ Filter(s) │ ← Кастомная фильтрация (опционально) └────────┬─────────┘ │ ▼ ┌──────────────────┐ │ Handler(s) │ ← Определяет куда: файл, консоль, email │ FileHandler │ ← Фильтрует по уровню │ StreamHandler │ └────────┬─────────┘ │ ▼ ┌──────────────────┐ │ Formatter │ ← Форматирует сообщение └────────┬─────────┘ │ ▼ Вывод лога

Переменная

Значение

Пример

%(asctime)s

Timestamp

2026-03-21 10:00:00,123

%(name)s

Имя logger

app.api.users

%(levelname)s

Уровень

INFO, ERROR

%(message)s

Сообщение

User logged in

%(filename)s

Имя файла

users.py

%(lineno)d

Номер строки

42

%(funcName)s

Имя функции

create_user

%(process)d

PID процесса

12345

%(thread)d

ID потока

98765

child_logger.info("Message") ↓ app.api (свой handler? → вывод) ↓ propagate=True app (свой handler? → вывод) ↓ propagate=True root (handler от basicConfig → вывод)

ERROR:app:Operation failed Traceback (most recent call last): File "app.py", line 10, in <module> risky_operation() File "app.py", line 5, in risky_operation raise ValueError("Invalid data") ValueError: Invalid data

Концепция

Описание

Logger

Точка входа для логирования, создаётся через getLogger(__name__)

Handler

Определяет куда: файл, консоль, email, сеть

Formatter

Определяет формат: timestamp, уровень, сообщение

Filter

Кастомная фильтрация по условиям

Propagation

Передача логов родительским logger'ам

Уровень

Число

Когда использовать

DEBUG

Детали для отладки (development)

INFO

Бизнес-события (production)

WARNING

Необычные ситуации

ERROR

Ошибки операций

CRITICAL

Критические сбои