Зачем нужно логирование, уровни логирования, базовая архитектура logging
Логирование — это не просто «запись в файл». Это инструмент observability, который позволяет понять, что происходит в приложении без изменения кода. Хорошее логирование экономит часы расследования инцидентов.
Сценарий: Production-система упала в 3 часа ночи. PagerDuty будит дежурного инженера.
Вопросы, на которые нужно ответить за 15 минут:
Без логирования:
❌ Нет информации о запросе
❌ Непонятно, какой код выполнялся
❌ Невозможно воспроизвести проблему
❌ Расследование занимает часы/дни
С логированием:
✅ request_id=abc-123 → найдены все логи запроса
✅ user_id=42, order_id=100500 → понятен контекст
✅ ERROR: DatabaseTimeout → понятна причина
✅ Воспроизведение: повторить запрос с теми же параметрами
Проблема: Начинающие разработчики используют 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| Сценарий | Уровень | Пример | В 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") | ✅ Включён |
import logging
# Уровни по возрастанию важности:
logging.DEBUG # 10 — Детальная отладочная информация
logging.INFO # 20 — Обычные события работы приложения
logging.WARNING # 30 — Предупреждения, необычные ситуации
logging.ERROR # 40 — Ошибки, операция не выполнена
logging.CRITICAL # 50 — Критические сбои, приложение не может продолжатьИспользование: 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 отключён. Включайте временно для расследования.
Использование: 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 — это история того, что произошло важного в приложении.
Использование: Необычные ситуации, которые не являются ошибками.
# ✅ Хорошо: предупреждения
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 — что-то необычное, но приложение работает корректно.
Использование: Операция не выполнена, но приложение продолжает работать.
# ✅ Хорошо: ошибки с контекстом
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 требует расследования. Всегда добавляйте контекст.
Использование: Приложение не может продолжать работу.
# ✅ Хорошо: критические сбои
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 требует немедленного реагирования. Используйте редко.
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.
┌─────────────────────────────────────────────────────────────┐
│ Архитектура Python Logging │
└─────────────────────────────────────────────────────────────┘
Приложение
│ logger.info("Message", extra={...})
▼
┌──────────────────┐
│ Logger │ ← Принимает сообщения от приложения
│ getLogger(__name__) ← Фильтрует по уровню
└────────┬─────────┘
│ LogRecord (создаётся автоматически)
▼
┌──────────────────┐
│ Filter(s) │ ← Кастомная фильтрация (опционально)
└────────┬─────────┘
│
▼
┌──────────────────┐
│ Handler(s) │ ← Определяет куда: файл, консоль, email
│ FileHandler │ ← Фильтрует по уровню
│ StreamHandler │
└────────┬─────────┘
│
▼
┌──────────────────┐
│ Formatter │ ← Форматирует сообщение
└────────┬─────────┘
│
▼
Вывод лога
Проблема: Нужно создать объект для логирования в модуле.
Решение: 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Проблема: Нужно отправить логи в определённое место.
Решение: 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)Проблема: Нужно форматировать сообщения логов.
Решение: 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 |
Проблема: Нужно фильтровать сообщения по кастомным условиям.
Решение: 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']))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 → вывод)
Проблема: Дублирование логов.
# ❌ Проблема: дублирование
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)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:
Для production используйте dictConfig() (рассмотрено в теме "Конфигурация логирования").
Проблема: Нужно залогировать ошибку с 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
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
)Проблема: Нужно добавить контекст (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'
)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})✅ Логировать:
❌ Не логировать:
# ✅ Хорошо: использовать __name__
logger = logging.getLogger(__name__)
# ✅ Хорошо: явное имя для специфичных случаев
logger = logging.getLogger('app.audit')
# ❌ Плохо: одинаковое имя во всех модулях
logger = logging.getLogger('my_logger')# ❌ Плохо: строка формируется всегда
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 включён# ✅ Хорошо: % форматирование (рекомендуется для 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")Причины:
Диагностика:
logger = logging.getLogger(__name__)
print(f"Level: {logger.level}") # 0 = NOTSET (наследуется от родителя)
print(f"Handlers: {logger.handlers}") # Пусто?
print(f"Effective level: {logger.getEffectiveLevel()}") # Реальный уровеньПричины:
Решение:
# Проверить handlers
print(f"Logger handlers: {logger.handlers}")
print(f"Root handlers: {logging.getLogger().handlers}")
# Отключить propagation
logger.propagate = False
# Или не добавлять handler в rootПричина: 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 | Критические сбои |
logging.getLogger(__name__) для создания logger'овextra={}exc_info=True для ошибокisEnabledFor() для дорогих операцийdictConfig, не basicConfigpropagate=False если добавляете handler к loggerВопросы ещё не добавлены
Вопросы для этой подтемы ещё не добавлены.