igor_nadein
025f82147c
Добавлена полнофункциональная система логирования: Структура логов (backend/logs/): - all.log - все сообщения (DEBUG+) - error.log - ошибки и критические события (ERROR+) - debug.log - отладочная информация (DEBUG+) - security.log - события безопасности (аутентификация, авторизация) - requests.log - HTTP запросы с деталями производительности Возможности: - Ротация файлов (10MB макс. размер, 5 бэкапов) - 3 форматтера (verbose, simple, json_style) - Фильтр RequireDebugFalse для production - Раздельное логирование Django, DRF, Channels, Celery Документация: - LOGGING_GUIDE.md - полное руководство (400+ строк) - logging_examples.py - примеры использования для всех компонентов
447 lines
17 KiB
Python
447 lines
17 KiB
Python
"""
|
||
Примеры использования модернизированной системы логирования EUSRR.
|
||
|
||
Этот модуль демонстрирует best practices для логирования
|
||
в различных сценариях приложения.
|
||
"""
|
||
|
||
import logging
|
||
from functools import wraps
|
||
from time import time
|
||
|
||
# Инициализация логгеров для разных компонентов
|
||
logger = logging.getLogger(__name__)
|
||
ldap_logger = logging.getLogger('employees.ldap')
|
||
security_logger = logging.getLogger('django.security')
|
||
|
||
|
||
# ============================================================================
|
||
# Базовое логирование
|
||
# ============================================================================
|
||
|
||
def basic_logging_example():
|
||
"""Примеры базового логирования на разных уровнях."""
|
||
|
||
# DEBUG: детальная информация для диагностики
|
||
logger.debug("Начало обработки запроса")
|
||
logger.debug("Параметры: limit=%d, offset=%d", 10, 0)
|
||
|
||
# INFO: стандартные события жизненного цикла
|
||
logger.info("Пользователь успешно авторизован: %s", "admin@example.com")
|
||
logger.info("Создан новый документ ID=%d", 123)
|
||
|
||
# WARNING: неожиданные ситуации, но не критичные
|
||
logger.warning("Использован устаревший API endpoint: /api/v1/old")
|
||
logger.warning("Попытка доступа к несуществующему ресурсу ID=%d", 999)
|
||
|
||
# ERROR: ошибки, которые не останавливают приложение
|
||
logger.error("Не удалось отправить email: %s", "smtp_error")
|
||
|
||
# CRITICAL: критические ошибки
|
||
logger.critical("Потеряно подключение к базе данных")
|
||
|
||
|
||
# ============================================================================
|
||
# Логирование с контекстом
|
||
# ============================================================================
|
||
|
||
def contextual_logging_example(user, document):
|
||
"""Логирование с дополнительным контекстом."""
|
||
|
||
# Передача структурированных данных через extra
|
||
logger.info(
|
||
"Документ %s обработан пользователем %s",
|
||
document.title,
|
||
user.email,
|
||
extra={
|
||
'user_id': user.id,
|
||
'user_email': user.email,
|
||
'document_id': document.id,
|
||
'document_type': document.doc_type,
|
||
'action': 'process',
|
||
}
|
||
)
|
||
|
||
# Лог будет содержать все переданные данные,
|
||
# что упростит фильтрацию и анализ
|
||
|
||
|
||
# ============================================================================
|
||
# Логирование исключений
|
||
# ============================================================================
|
||
|
||
def exception_logging_example():
|
||
"""Правильное логирование исключений с трассировкой."""
|
||
|
||
try:
|
||
# Опасная операция
|
||
result = 10 / 0
|
||
except ZeroDivisionError:
|
||
# exc_info=True добавляет полную трассировку стека
|
||
logger.error("Ошибка при выполнении операции", exc_info=True)
|
||
|
||
try:
|
||
# Другая операция
|
||
employee = Employee.objects.get(pk=99999)
|
||
except Employee.DoesNotExist:
|
||
# exception() - сокращение для error(..., exc_info=True)
|
||
logger.exception("Сотрудник не найден: pk=99999")
|
||
|
||
|
||
# ============================================================================
|
||
# LDAP и безопасность
|
||
# ============================================================================
|
||
|
||
def security_logging_example(request, username):
|
||
"""Логирование событий безопасности."""
|
||
|
||
# Успешная аутентификация
|
||
ldap_logger.info(
|
||
"LDAP аутентификация успешна: %s",
|
||
username,
|
||
extra={
|
||
'username': username,
|
||
'ip_address': request.META.get('REMOTE_ADDR'),
|
||
'user_agent': request.META.get('HTTP_USER_AGENT'),
|
||
'event': 'login_success',
|
||
}
|
||
)
|
||
|
||
# Неудачная попытка входа
|
||
security_logger.warning(
|
||
"Неудачная попытка входа: %s",
|
||
username,
|
||
extra={
|
||
'username': username,
|
||
'ip_address': request.META.get('REMOTE_ADDR'),
|
||
'reason': 'invalid_password',
|
||
'event': 'login_failed',
|
||
}
|
||
)
|
||
|
||
# Подозрительная активность
|
||
security_logger.error(
|
||
"Множественные неудачные попытки входа",
|
||
extra={
|
||
'username': username,
|
||
'ip_address': request.META.get('REMOTE_ADDR'),
|
||
'attempts': 5,
|
||
'event': 'brute_force_attempt',
|
||
}
|
||
)
|
||
|
||
|
||
# ============================================================================
|
||
# Декоратор для логирования производительности
|
||
# ============================================================================
|
||
|
||
def log_performance(logger_name=None):
|
||
"""
|
||
Декоратор для логирования времени выполнения функции.
|
||
|
||
Usage:
|
||
@log_performance('employees')
|
||
def slow_operation():
|
||
time.sleep(2)
|
||
"""
|
||
def decorator(func):
|
||
func_logger = logging.getLogger(logger_name or func.__module__)
|
||
|
||
@wraps(func)
|
||
def wrapper(*args, **kwargs):
|
||
start_time = time()
|
||
func_name = func.__qualname__
|
||
|
||
func_logger.debug("Начало выполнения: %s", func_name)
|
||
|
||
try:
|
||
result = func(*args, **kwargs)
|
||
elapsed = time() - start_time
|
||
|
||
func_logger.info(
|
||
"Функция %s завершена за %.3f сек",
|
||
func_name,
|
||
elapsed,
|
||
extra={
|
||
'function': func_name,
|
||
'elapsed_time': elapsed,
|
||
'success': True,
|
||
}
|
||
)
|
||
|
||
return result
|
||
|
||
except Exception as e:
|
||
elapsed = time() - start_time
|
||
|
||
func_logger.error(
|
||
"Ошибка в функции %s после %.3f сек: %s",
|
||
func_name,
|
||
elapsed,
|
||
str(e),
|
||
exc_info=True,
|
||
extra={
|
||
'function': func_name,
|
||
'elapsed_time': elapsed,
|
||
'success': False,
|
||
'error_type': type(e).__name__,
|
||
}
|
||
)
|
||
|
||
raise
|
||
|
||
return wrapper
|
||
return decorator
|
||
|
||
|
||
# ============================================================================
|
||
# Логирование в views
|
||
# ============================================================================
|
||
|
||
def view_logging_example(request):
|
||
"""Пример логирования в Django view."""
|
||
|
||
# Логирование начала запроса
|
||
logger.info(
|
||
"Обработка запроса %s %s",
|
||
request.method,
|
||
request.path,
|
||
extra={
|
||
'method': request.method,
|
||
'path': request.path,
|
||
'user_id': request.user.id if request.user.is_authenticated else None,
|
||
'ip': request.META.get('REMOTE_ADDR'),
|
||
}
|
||
)
|
||
|
||
try:
|
||
# Бизнес-логика
|
||
data = process_request(request)
|
||
|
||
logger.info("Запрос успешно обработан")
|
||
return JsonResponse(data)
|
||
|
||
except ValidationError as e:
|
||
# Пользовательские ошибки - WARNING уровень
|
||
logger.warning(
|
||
"Ошибка валидации: %s",
|
||
str(e),
|
||
extra={'errors': e.message_dict}
|
||
)
|
||
return JsonResponse({'errors': e.message_dict}, status=400)
|
||
|
||
except Exception as e:
|
||
# Неожиданные ошибки - ERROR уровень
|
||
logger.exception("Необработанная ошибка в view")
|
||
return JsonResponse({'error': 'Internal server error'}, status=500)
|
||
|
||
|
||
# ============================================================================
|
||
# Логирование фоновых задач Celery
|
||
# ============================================================================
|
||
|
||
@log_performance('celery')
|
||
def celery_task_logging_example():
|
||
"""Пример логирования в Celery задаче."""
|
||
|
||
task_logger = logging.getLogger('celery.tasks')
|
||
|
||
task_logger.info("Начало выполнения задачи sync_ldap")
|
||
|
||
try:
|
||
# Выполнение задачи
|
||
synced_count = 0
|
||
error_count = 0
|
||
|
||
for employee in Employee.objects.filter(is_active=True):
|
||
try:
|
||
employee.sync_to_ldap()
|
||
synced_count += 1
|
||
|
||
task_logger.debug("Синхронизирован Employee ID=%d", employee.id)
|
||
|
||
except Exception as e:
|
||
error_count += 1
|
||
|
||
task_logger.error(
|
||
"Ошибка синхронизации Employee ID=%d: %s",
|
||
employee.id,
|
||
str(e),
|
||
extra={'employee_id': employee.id}
|
||
)
|
||
|
||
# Итоговый отчет
|
||
task_logger.info(
|
||
"Задача sync_ldap завершена: успешно=%d, ошибок=%d",
|
||
synced_count,
|
||
error_count,
|
||
extra={
|
||
'synced_count': synced_count,
|
||
'error_count': error_count,
|
||
'total': synced_count + error_count,
|
||
}
|
||
)
|
||
|
||
except Exception as e:
|
||
task_logger.exception("Критическая ошибка в задаче sync_ldap")
|
||
raise
|
||
|
||
|
||
# ============================================================================
|
||
# Условное логирование
|
||
# ============================================================================
|
||
|
||
def conditional_logging_example(data):
|
||
"""Логирование в зависимости от условий."""
|
||
|
||
# Логируем только если включен DEBUG уровень
|
||
if logger.isEnabledFor(logging.DEBUG):
|
||
# Дорогостоящая операция форматирования
|
||
detailed_info = format_complex_data(data)
|
||
logger.debug("Детальная информация: %s", detailed_info)
|
||
|
||
# Всегда логируем важные события
|
||
logger.info("Обработка завершена")
|
||
|
||
|
||
# ============================================================================
|
||
# Логирование Django Signals
|
||
# ============================================================================
|
||
|
||
def signal_logging_example(sender, instance, created, **kwargs):
|
||
"""Пример логирования в Django signal handler."""
|
||
|
||
if created:
|
||
logger.info(
|
||
"Создан новый объект %s (ID=%d)",
|
||
sender.__name__,
|
||
instance.pk,
|
||
extra={
|
||
'model': sender.__name__,
|
||
'object_id': instance.pk,
|
||
'action': 'created',
|
||
}
|
||
)
|
||
else:
|
||
logger.debug(
|
||
"Обновлен объект %s (ID=%d)",
|
||
sender.__name__,
|
||
instance.pk,
|
||
extra={
|
||
'model': sender.__name__,
|
||
'object_id': instance.pk,
|
||
'action': 'updated',
|
||
}
|
||
)
|
||
|
||
|
||
# ============================================================================
|
||
# Антипаттерны (чего НЕ делать)
|
||
# ============================================================================
|
||
|
||
def antipatterns_example():
|
||
"""Примеры неправильного использования логирования."""
|
||
|
||
# ❌ НЕ ДЕЛАЙТЕ ТАК:
|
||
|
||
# 1. Логирование чувствительных данных
|
||
# logger.info("User password: %s", password) # НИКОГДА!
|
||
# logger.debug("API key: %s", api_key) # НИКОГДА!
|
||
|
||
# 2. Избыточное логирование в циклах
|
||
# for i in range(10000):
|
||
# logger.debug("Processing item %d", i) # Замедляет выполнение
|
||
|
||
# 3. Использование print() вместо logger
|
||
# print("Something happened") # Используйте logger!
|
||
|
||
# 4. Конкатенация строк в логах
|
||
# logger.info("User " + user.email + " logged in") # Неэффективно
|
||
|
||
# 5. Логирование без контекста
|
||
# logger.error("Error") # Бесполезно без деталей
|
||
|
||
# ✅ ПРАВИЛЬНО:
|
||
|
||
# 1. Не логируем пароли, только факт действия
|
||
logger.info("User authentication successful", extra={'username': username})
|
||
|
||
# 2. Логируем суммарные результаты после цикла
|
||
logger.info("Processed %d items", 10000)
|
||
|
||
# 3. Всегда используем logger
|
||
logger.info("Something happened")
|
||
|
||
# 4. Используем форматирование
|
||
logger.info("User %s logged in", user.email)
|
||
|
||
# 5. Добавляем контекст
|
||
logger.error("Database connection failed", extra={'host': db_host, 'port': db_port})
|
||
|
||
|
||
# ============================================================================
|
||
# Контекстный менеджер для логирования блоков кода
|
||
# ============================================================================
|
||
|
||
class LogContext:
|
||
"""
|
||
Контекстный менеджер для логирования блоков кода.
|
||
|
||
Usage:
|
||
with LogContext('employees', 'Синхронизация с LDAP'):
|
||
sync_employees()
|
||
"""
|
||
|
||
def __init__(self, logger_name, operation_name):
|
||
self.logger = logging.getLogger(logger_name)
|
||
self.operation_name = operation_name
|
||
self.start_time = None
|
||
|
||
def __enter__(self):
|
||
self.start_time = time()
|
||
self.logger.info("Начало: %s", self.operation_name)
|
||
return self
|
||
|
||
def __exit__(self, exc_type, exc_val, exc_tb):
|
||
elapsed = time() - self.start_time
|
||
|
||
if exc_type is None:
|
||
self.logger.info(
|
||
"Завершено: %s (%.3f сек)",
|
||
self.operation_name,
|
||
elapsed,
|
||
extra={'operation': self.operation_name, 'elapsed': elapsed}
|
||
)
|
||
else:
|
||
self.logger.error(
|
||
"Ошибка в: %s (%.3f сек): %s",
|
||
self.operation_name,
|
||
elapsed,
|
||
str(exc_val),
|
||
exc_info=True,
|
||
extra={
|
||
'operation': self.operation_name,
|
||
'elapsed': elapsed,
|
||
'error_type': exc_type.__name__,
|
||
}
|
||
)
|
||
|
||
return False # Не подавляем исключение
|
||
|
||
|
||
# Пример использования контекстного менеджера
|
||
def context_manager_example():
|
||
"""Использование LogContext для логирования блоков кода."""
|
||
|
||
with LogContext('employees', 'Импорт сотрудников из Excel'):
|
||
# Код операции
|
||
employees = import_from_excel('employees.xlsx')
|
||
# Автоматически залогируется время выполнения
|
||
|
||
# При ошибке автоматически залогируется с трассировкой
|
||
try:
|
||
with LogContext('employees.ldap', 'Синхронизация с AD'):
|
||
sync_with_active_directory()
|
||
except Exception:
|
||
pass # Уже залогировано в контекстном менеджере
|