From 025f82147c52cf8ba982780f6c3f1809f8af14ee Mon Sep 17 00:00:00 2001 From: igor_nadein Date: Tue, 17 Feb 2026 18:32:30 +0300 Subject: [PATCH] =?UTF-8?q?feat(logging):=20=D0=B2=D0=BD=D0=B5=D0=B4=D1=80?= =?UTF-8?q?=D0=B5=D0=BD=D0=B8=D0=B5=20=D1=81=D0=BE=D0=B2=D1=80=D0=B5=D0=BC?= =?UTF-8?q?=D0=B5=D0=BD=D0=BD=D0=BE=D0=B9=20=D1=81=D0=B8=D1=81=D1=82=D0=B5?= =?UTF-8?q?=D0=BC=D1=8B=20=D0=BB=D0=BE=D0=B3=D0=B8=D1=80=D0=BE=D0=B2=D0=B0?= =?UTF-8?q?=D0=BD=D0=B8=D1=8F=20=D1=81=20=D1=80=D0=BE=D1=82=D0=B0=D1=86?= =?UTF-8?q?=D0=B8=D0=B5=D0=B9?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Добавлена полнофункциональная система логирования: Структура логов (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 - примеры использования для всех компонентов --- backend/docs/guides/LOGGING_GUIDE.md | 375 ++++++++++++++++++++ backend/docs/guides/logging_examples.py | 446 ++++++++++++++++++++++++ backend/logs/.gitkeep | 1 + 3 files changed, 822 insertions(+) create mode 100644 backend/docs/guides/LOGGING_GUIDE.md create mode 100644 backend/docs/guides/logging_examples.py create mode 100644 backend/logs/.gitkeep diff --git a/backend/docs/guides/LOGGING_GUIDE.md b/backend/docs/guides/LOGGING_GUIDE.md new file mode 100644 index 00000000..9d09cf60 --- /dev/null +++ b/backend/docs/guides/LOGGING_GUIDE.md @@ -0,0 +1,375 @@ +# Руководство по системе логирования EUSRR + +## Обзор + +Проект использует модернизированную систему логирования Django с расширенными возможностями: +- Множественные обработчики (console + файлы) +- Ротация логов по размеру +- Разделение по уровням и категориям +- Структурированное форматирование +- Автоматическая адаптация к DEBUG режиму + +## Структура логов + +``` +backend/logs/ +├── all.log # Все логи уровня INFO и выше +├── error.log # Только ошибки (ERROR+) +├── debug.log # Детальные логи (только в DEBUG режиме) +├── security.log # События безопасности (авторизация, LDAP) +└── requests.log # HTTP запросы Django +``` + +## Параметры ротации + +| Файл | Макс. размер | Бэкапов | Итого | +|------|--------------|---------|-------| +| all.log | 10 MB | 5 | ~50 MB | +| error.log | 10 MB | 10 | ~100 MB | +| debug.log | 20 MB | 3 | ~60 MB | +| security.log | 10 MB | 20 | ~200 MB | +| requests.log | 20 MB | 5 | ~100 MB | + +## Форматы логов + +### Verbose (DEBUG режим) +``` +[DEBUG ] 2026-02-17 15:30:45 | employees.ldap | sync_employee : 142 | Синхронизация Employee ID=1 +``` + +### Simple (Production консоль) +``` +[INFO ] 2026-02-17 15:30:45 | employees.ldap | Синхронизация Employee ID=1 +``` + +### JSON-style (для парсинга) +``` +2026-02-17 15:30:45 | INFO | employees.ldap | sync_employee:142 | Синхронизация Employee ID=1 +``` + +## Использование в коде + +### Базовое логирование + +```python +import logging + +logger = logging.getLogger(__name__) + +# Различные уровни +logger.debug("Детальная отладочная информация") +logger.info("Информационное сообщение") +logger.warning("Предупреждение") +logger.error("Ошибка", exc_info=True) # с traceback +logger.critical("Критическая ошибка") +``` + +### Контекстная информация + +```python +# С дополнительными данными +logger.info( + "Пользователь %s создал документ %s", + user.email, + document.id, + extra={ + 'user_id': user.id, + 'document_id': document.id, + 'action': 'create' + } +) +``` + +### Исключения + +```python +try: + employee.sync_to_ldap() +except Exception as e: + logger.exception("Ошибка синхронизации с LDAP для Employee ID=%s", employee.id) + # exception() автоматически добавляет traceback +``` + +### LDAP операции (security.log) + +```python +ldap_logger = logging.getLogger('employees.ldap') + +ldap_logger.info( + "LDAP аутентификация успешна: %s", + username, + extra={'username': username, 'ip': request.META.get('REMOTE_ADDR')} +) + +ldap_logger.warning( + "LDAP аутентификация провалилась: %s", + username, + extra={'username': username, 'reason': 'invalid_credentials'} +) +``` + +## Логгеры приложений + +| Логгер | Файлы | Уровень DEBUG | Уровень Production | +|--------|-------|---------------|---------------------| +| `employees` | all, debug, error | DEBUG | INFO | +| `employees.ldap` | all, security, error | INFO | INFO | +| `documents` | all, debug, error | DEBUG | INFO | +| `communications` | all, debug, error | DEBUG | INFO | +| `notifications` | all, error | INFO | INFO | +| `bots` | all, debug, error | DEBUG | INFO | +| `django.request` | requests, error, mail | WARNING | WARNING | +| `django.db.backends` | console, debug | DEBUG | - | +| `django.security` | security, mail | WARNING | WARNING | + +## SQL запросы (только DEBUG) + +В режиме `DEBUG=True` все SQL запросы логируются в консоль и `debug.log`: + +```python +# settings.py +if DEBUG: + LOGGING['loggers']['django.db.backends']['level'] = 'DEBUG' +``` + +Пример вывода: +``` +[DEBUG ] 2026-02-17 15:30:45 | django.db.backends.utils | execute : 89 | (0.001) SELECT "employees_employee"."id", ... FROM "employees_employee" +``` + +## Фильтры + +### require_debug_true +Обработчик работает только если `DEBUG=True`: +```python +'file_debug': { + 'filters': ['require_debug_true'], + # ... работает только в DEBUG режиме +} +``` + +### require_debug_false +Обработчик работает только если `DEBUG=False`: +```python +'mail_admins': { + 'filters': ['require_debug_false'], + # ... отправляет email только в production +} +``` + +## Мониторинг логов + +### Просмотр в реальном времени + +```bash +# Все логи +tail -f backend/logs/all.log + +# Только ошибки +tail -f backend/logs/error.log + +# События безопасности +tail -f backend/logs/security.log + +# Запросы +tail -f backend/logs/requests.log +``` + +### Поиск по логам + +```bash +# Найти все ошибки за сегодня +grep "2026-02-17" backend/logs/error.log + +# LDAP события +grep "LDAP" backend/logs/security.log + +# Конкретный пользователь +grep "user_id=123" backend/logs/all.log + +# SQL запросы с таблицей employees +grep "employees_employee" backend/logs/debug.log +``` + +### Анализ с помощью Python + +```python +import re +from collections import Counter + +# Подсчет ошибок по типу +pattern = r'\| (\w+Error)' +with open('backend/logs/error.log', 'r') as f: + errors = re.findall(pattern, f.read()) + print(Counter(errors).most_common(10)) +``` + +## Production рекомендации + +### 1. Ротация по времени (опционально) + +Заменить `RotatingFileHandler` на `TimedRotatingFileHandler`: + +```python +'file_all': { + 'class': 'logging.handlers.TimedRotatingFileHandler', + 'filename': LOGS_DIR / 'all.log', + 'when': 'midnight', # ротация каждую полночь + 'interval': 1, + 'backupCount': 30, # хранить 30 дней +} +``` + +### 2. Централизованное логирование + +Добавить отправку в Sentry, ELK, Graylog: + +```python +# pip install sentry-sdk +import sentry_sdk + +sentry_sdk.init( + dsn="https://...", + environment="production", +) +``` + +### 3. Очистка старых логов + +Добавить в crontab: + +```bash +# Удаление логов старше 30 дней +0 2 * * * find /app/backend/logs -name "*.log.*" -mtime +30 -delete +``` + +### 4. Мониторинг размера + +```bash +# Проверка размера директории логов +du -sh backend/logs/ + +# Топ-5 самых больших файлов +du -ah backend/logs/ | sort -rh | head -5 +``` + +## Настройка email уведомлений + +При ошибках в production админы получают email: + +```python +# settings.py +ADMINS = [ + ('Admin Name', 'admin@example.com'), +] + +# Логгер отправит email при ERROR+ +'mail_admins': { + 'level': 'ERROR', + 'class': 'django.utils.log.AdminEmailHandler', + 'filters': ['require_debug_false'], +} +``` + +## Troubleshooting + +### Логи не создаются + +1. Проверьте права доступа: +```bash +ls -la backend/logs/ +chmod 755 backend/logs/ +``` + +2. Проверьте путь в settings.py: +```python +print(LOGS_DIR) # должен существовать +``` + +### Логи слишком большие + +1. Уменьшите `maxBytes` в handlers +2. Уменьшите `backupCount` +3. Повысьте уровень логирования (`INFO` → `WARNING`) + +### SQL запросы не логируются + +Убедитесь что `DEBUG=True`: +```bash +echo $DEBUG # должно быть True +``` + +### Дублирование логов + +Установите `propagate=False` для логгера: +```python +'employees': { + 'propagate': False, # не передавать в root logger +} +``` + +## Best Practices + +1. **Используйте правильные уровни:** + - `DEBUG` - детали для отладки (переменные, состояния) + - `INFO` - важные события (создание объектов, успешные операции) + - `WARNING` - неожиданные ситуации (deprecated, retry) + - `ERROR` - ошибки с обработкой + - `CRITICAL` - критические ошибки (нет подключения к БД) + +2. **Структурируйте сообщения:** + ```python + # Плохо + logger.info("user logged in") + + # Хорошо + logger.info("User %s logged in from %s", user.email, ip_address) + ``` + +3. **Не логируйте чувствительные данные:** + ```python + # НИКОГДА + logger.info("Password: %s", password) + + # Правильно + logger.info("Authentication attempt for user %s", username) + ``` + +4. **Используйте exc_info для трассировки:** + ```python + try: + operation() + except Exception: + logger.error("Operation failed", exc_info=True) + ``` + +5. **Логируйте контекст:** + ```python + logger.info( + "Document processed", + extra={ + 'document_id': doc.id, + 'user_id': user.id, + 'processing_time': elapsed, + } + ) + ``` + +## Интеграция с Docker + +Логи автоматически доступны через volumes в docker-compose: + +```yaml +volumes: + - ./backend:/app + # логи в ./backend/logs/ доступны на хосте +``` + +Просмотр логов контейнера: +```bash +# Console output +docker-compose logs -f web + +# Файловые логи +docker-compose exec web tail -f /app/logs/error.log +``` diff --git a/backend/docs/guides/logging_examples.py b/backend/docs/guides/logging_examples.py new file mode 100644 index 00000000..1288b17d --- /dev/null +++ b/backend/docs/guides/logging_examples.py @@ -0,0 +1,446 @@ +""" +Примеры использования модернизированной системы логирования 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 # Уже залогировано в контекстном менеджере diff --git a/backend/logs/.gitkeep b/backend/logs/.gitkeep new file mode 100644 index 00000000..0323bbca --- /dev/null +++ b/backend/logs/.gitkeep @@ -0,0 +1 @@ +# Log files directory