Логирование в Chat Backend

Основная информация

Логирование — это процесс формирования логов, а именно: фиксация и структурирование информации о работе системы в отдельные лог-файлы с возможностью быстрого доступа к ним в случае необходимости.

Для настройки системы логирования в Chat Backend используется конфигурационный файл logging.json. Он позволяет детально определить, как будут обрабатываться и форматироваться сообщения журнала, а также куда они будут отправляться. Также с его помощью можно настроить раздельное логирование - способ, который предполагает разделение логов по уровням, модулям и форматам. Это может облегчить анализ логов.

logging.json имеет структуру конфигурационного файла стандартного python-модуля logging. Это означает, что его формат и содержимое соответствуют принятым в этом модуле стандартам.

Файл logging.json позволяет:

Изменять уровни логирования: контролировать, какие сообщения будут записываться (например, только ошибки или все сообщения, включая отладочные)
Настраивать выходные форматы: можно изменить формат сообщений для более удобного чтения
Добавлять или удалять обработчики: Например, настроить запись логов в разные файлы для разных модулей или отправку сообщений на консоль для быстрого просмотра

Конфигурация логирования

В Chat Backend предусмотрено два способа получения файла конфигурации logging.json:

1. `Параметр запуска`: можно передать конфигурацию через параметр запуска `--logging_config`, указав путь к файлу:

  ```
  --logging_config=src/configs/logging.json
  ```

1. `По умолчанию`: если параметр запуска не указан, система автоматически использует файл конфигурации, который находится по пути `/opt/webim/envs/<имя окружения>/configs/`.

N.B

Файл logging.json уже входит в состав дистрибутива Chat Backend и будет автоматически найден и использован системой при запуске, если параметр запуска не указан.

Использование Tornado

В Chat Backend используется фреймворк Tornado, который также поддерживает собственное логирование. Tornado логирует запросы и ошибки, что позволяет лучше отслеживать и диагностировать работу сервера. Для интеграции логирования Tornado с общей системой логирования в logging.json добавляются соответствующие настройки логгеров.

Пример настройки логирования Tornado:

{
    "loggers": {
        "tornado.access": {
            "level": "INFO"
        },
        "tornado.application": {
            "level": "ERROR"
        },
        "tornado.general": {
            "level": "ERROR"
        }
    }
}

Базовые настройки

Файл logging.json содержит следующие базовые настройки:

Логирование на стандартный поток ошибок (stderr)
Уровень логирования для корневого логгера установлен на WARNING
Специфичные логгеры также могут иметь свои уровни логирования

Пример базовой конфигурации:

{
  "version": 1,
  "formatters": {
      "default_text": {
          "style": "{",
          "format": "[{levelname[0]} {asctime} {module}:{lineno}] {message}",
          "datefmt": "%y%m%d %H:%M:%S %z"
      }
  },
  "handlers": {
      "stderr": {
          "class": "logging.StreamHandler",
          "formatter": "default_text",
          "stream": "ext://sys.stderr"
      }
  },
  "root": {
      "handlers": ["stderr"],
      "level": "WARNING"
  },
  "loggers": {
      "webim": {
          "level": "INFO"
      },
      "clickhouse_driver.connection": {
          "level": "ERROR"
      }
  }
}

Параметры логирования при запуске Chat Backend

При запуске Chat Backend можно указать параметры логирования через командную строку. Один из таких параметров — --logging_config, который позволяет указать путь к файлу конфигурации logging.json.

Пример:

python main.py --logging_config=src/configs/logging.json

Направление логов в файл, stderr, systemd и другие места

Для направления логов в разные места (файл, stderr, systemd и т.д.) используются различные обработчики (handlers) в конфигурации logging.json.

Для логирования в файл используется FileHandler:

{
    "handlers": {
        "file_handler": {
            "class": "logging.FileHandler",
            "formatter": "default_text",
            "filename": "/var/log/chat_backend.log"
        }
    },
    "root": {
        "handlers": ["file_handler"],
        "level": "WARNING"
    }
}

Для логирования в стандартный поток ошибок (stderr) используется StreamHandler с параметром stream:

{
    "handlers": {
        "stderr": {
            "class": "logging.StreamHandler",
            "formatter": "default_text",
            "stream": "ext://sys.stderr"
        }
    },
    "root": {
        "handlers": ["stderr"],
        "level": "WARNING"
    }
}

Для логирования в systemd можно использовать SysLogHandler:

{
    "handlers": {
        "syslog": {
            "class": "logging.handlers.SysLogHandler",
            "formatter": "default_text",
            "address": "/dev/log"
        }
    },
    "root": {
        "handlers": ["syslog"],
        "level": "WARNING"
    }
}

Правила ротации логов

Для ротации логов используются RotatingFileHandler или TimedRotatingFileHandler.

Ротация по размеру файла

Использование RotatingFileHandler позволяет задавать максимальный размер файла и количество сохраняемых старых логов:

{
    "handlers": {
        "rotating_file_handler": {
            "class": "logging.handlers.RotatingFileHandler",
            "formatter": "default_text",
            "filename": "/var/log/chat_backend.log",
            "maxBytes": 10485760,
            "backupCount": 5
        }
    },
    "root": {
        "handlers": ["rotating_file_handler"],
        "level": "WARNING"
    }
}

Ротация по времени

Использование TimedRotatingFileHandler позволяет задавать интервал времени для ротации логов:

{
    "handlers": {
        "timed_rotating_file_handler": {
            "class": "logging.handlers.TimedRotatingFileHandler",
            "formatter": "default_text",
            "filename": "/var/log/chat_backend.log",
            "when": "midnight",
            "interval": 1,
            "backupCount": 7
        }
    },
    "root": {
        "handlers": ["timed_rotating_file_handler"],
        "level": "WARNING"
    }
}

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

Уровень	Значение	Описание
Status	777	Предоставляет информацию о статусе сервера и загрузке параметров лоогирования
Debug	10	Этот уровень предоставляет подробную информацию, полезную только при диагностике проблем
Info	20	Выводит в логах информационные сообщения о работе сервиса, например, об отправке сообщения или запросе к внутреннему API
Warning	30	Указывает на то, что произошло что-то неожиданное или проблема может возникнуть в ближайшем будущем
Error	40	Произошла ошибка, приложение не смогло выполнить некоторую функцию
Fatal	50	Произошла серьёзная ошибка. Приложение может завершить работу или перестать функционировать корректно

N.B.

При логировании высокого уровня будут также выводиться логи всех низлежащих уровней. Например, для уровня WARNING это будут ERROR и FATAL, для INFO - WARNING, ERROR и FATAL, и так далее.

Полезные настройки логгеров

* `INFO` для `sqlalchemy.engine` позволит вывести в лог все SQL-запросы к базе данных

* `INFO` для `tornado.access` может использоваться для вывода в лог информации о входящих HTTP-запросах.

API для управления уровнем логирования

Для управления уровнем логирования в режиме реального времени предусмотрен REST API.

Запрос для установки уровня логирования:

GET /l/a/monitor/set-log-level

Параметры запроса:

name: Название логгера.
level: Минимальный уровень логирования.
current_node_only: Применить только к текущему узлу (true/false).

Пример запроса:

GET /l/a/monitor/set-log-level?name=sqlalchemy.engine&current_node_only=false&level=info

Формат конфигурационного файла `logging.json`

{
    "version": 1,
    "formatters":
    {
        "default_text":
        {
            "style": "{",
            "format": "[{levelname[0]} {asctime} {module}:{lineno}] {message}",
            "datefmt": "%y%m%d %H:%M:%S %z"
        }
    },
    "handlers":
    {
        "stderr":
        {
            "class": "logging.StreamHandler",
            "formatter": "default_text",
            "stream": "ext://sys.stderr"
        }
    },
    "root":
    {
        "handlers": ["stderr"],
        "level": "WARNING"
    },
    "loggers":
    {
        "webim":
        {
            "level": "INFO"
        },
        "clickhouse_driver.connection":
        {
            "level": "ERROR"
        }
    }
}

Описание параметров

Параметр	Описание
`version`	Версия схемы конфигурации логирования
`formatters`	Определяет форматирование лог-сообщений
`formatters.default_text.style`	Вариант оформления логов
`formatters.default_text.format`	Формат строки лог-сообщения
`formatters.default_text.datefmt`	Формат даты и времени в логах
`handlers`	Определяет обработчики логов
`handlers.stderr.class`	Класс обработчика, который выводит логи в стандартный поток ошибок
`handlers.stderr.formatter`	Форматтер, используемый для этого обработчика
`handlers.stderr.stream`	Поток вывода
`root`	Настройки корневого логгера
`root.handlers`	Обработчики, используемые корневым логгером
`root.level`	Уровень логирования для корневого логгера
`loggers`	Настройки для отдельных логгеров
`loggers.webim.level`	Уровень логирования для логгера `webim`
`loggers.clickhouse_driver.connection.level`	Уровень логирования для логгера `clickhouse_driver.connection`, логирование содержит информацию о соединении с базой ClickHouse посредством драйвера

Описание параметров для `formatter`

Параметр	Описание	Пример
`levelname`	Уровень логирования	`DEBUG`, `INFO`, `WARNING`
`asctime`	Время создания записи лога	`2023-06-25 14:56:59,123`
`module`	Имя модуля (часть имени файла без расширения)	`example`
`lineno`	Номер строки в исходном коде, из которой были вызвано логи	`42`
`message`	Сообщение журнала	`Something happened`
`created`	Время создания записи лога (в секундах с начала эпохи - 1970-01-01 00:00:00)	`1624624619.123`
`filename`	Имя файла исходного кода, из которого было вызвано логирование	`example.py`
`funcName`	Имя функции, из которой было вызвано логирование	`my_function`
`levelno`	Числовое значение уровня логирования	`10`, `20`, `30`
`msecs`	Миллисекунды времени создания записи логирования	`123`
`name`	Имя логгера, который создал запись	`root`, `my_logger`
`pathname`	Полный путь к файлу исходного кода, из которого было вызвано логирование	`/path/to/example.py`
`process`	Идентификатор процесса (PID)	`12345`
`processName`	Имя процесса	`MainProcess`
`relativeCreated`	Время, прошедшее с момента запуска логирования (в миллисекундах)	`1234.567`
`thread`	Идентификатор потока	`140736987180032`
`threadName`	Имя потока	`MainThread`

Возможные спецификаторы параметра `datefmt`

Спецификатор	Описание	Пример
`%Y`	Полный год	`2024`
`%y`	Последние две цифры года	`24`
`%m`	Месяц (01-12)	`06`
`%d`	День месяца (01-31)	`25`
`%H`	Часы (00-23)	`14`
`%I`	Часы (01-12)	`02`
`%p`	AM или PM	`PM`
`%M`	Минуты (00-59)	`56`
`%S`	Секунды (00-59)	`59`
`%f`	Микросекунды (000000-999999)	`123456`
`%z`	Часовой пояс (смещение UTC)	`+0200`
`%Z`	Название часового пояса	`CEST`
`%j`	День года (001-366)	`176`
`%U`	Номер недели года (воскресенье как первый день недели)	`25`
`%W`	Номер недели года (понедельник как первый день недели)	`25`
`%c`	Полная дата и время	`Tue Jun 25 14:56:59 2024`
`%x`	Дата	`06/25/24`
`%X`	Время	`14:56:59`

Возможные параметры для `class`

Класс	Описание	Категория
`StreamHandler`	Логирование в поток (stdout, stderr)	Handlers
`FileHandler`	Логирование в файл	Handlers
`RotatingFileHandler`	Логирование в файл с ротацией по размеру	Handlers
`TimedRotatingFileHandler`	Логирование в файл с ротацией по времени	Handlers
`SocketHandler`	Логирование через сокет	Handlers
`DatagramHandler`	Логирование через UDP	Handlers
`SysLogHandler`	Логирование на syslog сервер	Handlers
`SMTPHandler`	Логирование через Email	Handlers
`NTEventLogHandler`	Логирование в журнал событий Windows	Handlers
`MemoryHandler`	Буферизация логи в памяти	Handlers
`HTTPHandler`	Логирование на HTTP сервер	Handlers
`QueueHandler`	Логирование в очередь	Handlers
`Formatter`	Форматирование записей логи	Formatters
`Filter`	Фильтрация записей логи	Filters

Описание параметров для `stream`

Поток	Описание
`ext://sys.stdout`	Стандартный поток вывода
`ext://sys.stderr	Стандартный поток ошибок