Логирование для разработчиков 1С-Битрикс

Два года назад писали про внутренней инструмент для логирования. С помощью модуля Intensa Logger мы выполняем отладку на проектах на 1С-Битрикс.

Ниже расскажем про релиз-версию, в которой:

повысили уровень качества, стабильности и безопасности кода,
упростили установку,
улучшили производительность и отказоустойчивость,
добавили в проект тесты,
добавили трекер SQL-запросов,
добавили новые возможности для кастомизации в рамках проекта.

Результат выложили в 1С-Битрикс: Маркетплейс, пользуйтесь.

Сегодня поделимся обновленной документацией, расскажем о фичах в новой версии и на примерах разберем, как использовать Intensa Logger в проектах.

Учимся логировать с модулем

Intensa Logger — простой функциональный модуль CMS Bitrix, который логирует данные проекта в файлы. Подойдет для отслеживания «‎узких"‎ мест в проекте и дебага при разработке.

В модуле реализованы:

оповещения о критических проблемах в проекте,
очищение устаревших лог-файлов,
таймеры выполнения,
SQL-трекер на основе diag.

Как добавить модуль в проект

Самый простой способ — установить его через маркетплейс.

Но можно и вручную. Для этого:

Клонируем репозиторий в директорию с модулями /bitrix/modules/ или /local/modules/.
Переходим в директорию intensa.logger/lib (команда cd intensa.logger/lib).
Устанавливаем зависимости composer install --no-dev.
Добавляем модуль через админскую часть сайта /bitrix/admin/partner_modules.php.

При установке модуль создает:

защищённую директорию /logs/ в корне проекта для хранения лог-файлов,
почтовое события для оповещений фатальных уровней логирования,
агента для удаления устаревших лог-файлов.

Как работать с хранилищем логов

По умолчанию лог-файлы хранятся в директории /logs/ в корне проекта. Изменить место хранения можно в настройках модуля. Защита логов от просмотра в браузере реализована через .htaccess.

В проектах, которые используют nginx в качестве веб-сервера, нужно самостоятельно обезопасить хранилище. Для этого закрываем директорию от просмотра в браузере в конфигах nginx или меняем пути хранилища логов — выносим хранилище из document_root.

Чтобы файлы логов было легко найти, модуль содержит функционал хранения по дням.

Например, все логи за 19 августа 2021 года можно найти в директории /logs/19.08.2021/. Название лог-файла совпадает с кодом логгера, который передается в конструктор класса ILog.

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

Уровень лога — это классификация проблемы. В модуле они подразделяются так:

DEBUG,
INFO,
NOTICE,
WARNING,
ERROR,
CRITICAL,
ALERT,
EMERGENCY.

Для каждого уровня лога действует одноименный метод, но с особенностями.

log () — является алиасом для info ().
fatal () — является алиасом для alert ().

Это наследие, с которым приходится жить 🙂

Уровни CRITICAL, ALERT, EMERGENCY, помимо записи данных в лог-файл, отправляют сообщение администратору сайта. Адрес электронной почты можно указать в настройках модуля.

Какой уровень лога использовать в том или ином месте проекта, решает сам разработчик. Ниже приводим примеры использования логгера.

Из чего состоят логи

Разбираем пример по частям.

Как использовать возможности модуля — на примерах

1. Пример инициализации логгера и демонстрация базовых методов.

// Подключение модуля \Bitrix\Main\Loader:includeModule ('intensa.logger'); // Инициализация объекта логгера // В конструктор передаем код логгера, которому будет соответствовать имя лог-файла $logger = new \Intensa\Logger\ILog ('logger_code'); // Пример записи логов уровня INFO // Вторым параметром можно передать данные любого типа $context = ['яблоко', 'мандарин', 'банан']; $logger->info ('сообщение', $context); // Пример записи логов уровня ERROR $logger->error ('что-то пошло не так', $context); // Пример записи логов уровня ALERT // В данном случае будет отправлено письмо с информацией из лога $logger->alert ('алярм! мы все сломали', $context);

Содержимое лог-файла:

[2021−11−24 01:24:30][:info][pid:2696] сообщение Array ( [0] => яблоко [1] => мандарин [2] => банан ) [2021−11−24 01:24:30][:error][pid:2696] что-то пошло не так Array ( [0] => яблоко [1] => мандарин [2] => банан ) [2021−11−24 01:24:30][:alert][pid:2696] алярм! мы все сломали Array ( [0] => яблоко [1] => мандарин [2] => банан )

2. Пример вызова таймера.

// Подключение модуля \Bitrix\Main\Loader:includeModule ('intensa.logger'); // Инициализация объекта логгера // В конструктор передаем код логгера, ему будет соответствовать имя лог-файла $logger = new \Intensa\Logger\ILog ('logger_timer'); $context = ['яблоко', 'мандарин', 'банан']; $logger->info ('Логируем какие-то данные', $context); // Запуск таймера. Необходимо передать код таймера $logger->startTimer ('timer₁'); sleep (1); // Остановка таймера. Необходимо передать код таймера. $logger->stopTimer ('timer₁'); $logger->startTimer ('timer₂'); // Можно запускать один таймер внутри другого $logger->startTimer ('timer_internal'); sleep (2); $logger->stopTimer ('timer_internal'); sleep (3); $logger->stopTimer ('timer₂'); // Если у таймера не указана точка остановки, то время остановки определяется в дeструкторе класса $logger->startTimer ('dont_stop');

Содержимое лог файла:

[2021−11−24 01:29:47][:info][pid:2704] Логируем какие-то данные Array ( [0] => яблоко [1] => мандарин [2] => банан ) [2021−11−24 01:29:48][:info][pid:2704] Timer timer₁ Array ( [CODE] => timer₁ [START_TIME] => 2021−11−24 01:29:47.000000 [STOP_TIME] => 2021−11−24 01:29:48.000000 [EXEC_TIME] => 1.000375032 ) [2021−11−24 01:29:50][:info][pid:2704] Timer timer_internal Array ( [CODE] => timer_internal [START_TIME] => 2021−11−24 01:29:48.000000 [STOP_TIME] => 2021−11−24 01:29:50.000000 [EXEC_TIME] => 2.000512838 ) [2021−11−24 01:29:53][:info][pid:2704] Timer timer₂ Array ( [CODE] => timer₂ [START_TIME] => 2021−11−24 01:29:48.000000 [STOP_TIME] => 2021−11−24 01:29:53.000000 [EXEC_TIME] => 5.000887871 ) [2021−11−24 01:29:53][:info][pid:2704] Timer dont_stop Array ( [CODE] => dont_stop [START_TIME] => 2021−11−24 01:29:53.000000 [STOP_TIME] => 2021−11−24 01:29:53.000000 [EXEC_TIME] => 0.010784864 [STOP_POINT] => __destruct )

Формат логов таймера:

CODE — код таймера, определяется разработчиком при вызове таймера.
START_TIME — время запуска.
STOP_TIME — время остановки.
EXEC_POINT — время исполнения, т. е. разница между временем остановки и временем запуска.
START_POINT — место определения точки запуска, вызов метода startTimer ().
STOP_POINT — место определения точки остановки, вызов метода через команду stopTimer ().
Значение «__destruct» означает, что для текущего счетчика не вызвали метод stopTimer () и остановка произошла в деструкторе класса.

3. Использование трекера SQL-запросов.

\Bitrix\Main\Loader:includeModule ('intensa.logger'); $logger = new \Intensa\Logger\ILog ('logger_sql'); // Запускаем трекер-sql запросов $logger->startSqlTracker ('get_users'); // Пример кода, который делает запрос к базе данных $users = []; $result = \Bitrix\Main\UserTable:getList ([ 'select' => ['ID','SHORT_NAME', 'order' => ['LAST_LOGIN'=>'DESC', 'limit' => 3 ]); // Остановка трекера $logger->stopSqlTracker ('get_users');

Содержимое лог-файла:

[2021−11−24 01:29:48][:info][pid:1138] SqlTracker get_users: Array ( [0] => Array ( [query] => SELECT main_user.ID AS ID, CONCAT (main_user.LAST_NAME, ' ', UPPER (SUBSTR (main_user.NAME, 1, 1)), '.') AS SHORT_NAME FROM b_user main_user ORDER BY main_user.LAST_LOGIN DESC LIMIT 0, 3 [time] => 0.0076520442962646 ) )

Методы логгера

Доступные методы класса ILog помогут кастомизировать поведение каждого отдельного объекта логгера.

\Bitrix\Main\Loader:includeModule ('intensa.logger'); $logger = new \Intensa\Logger\ILog ('logger_sql'); // Метод заставляет логгер перезаписывать файл при каждом новом вызове логирующего метода $logger->rewrite (); // Через этот метод можно установить дополнительный email для получения алерт-сообщений на почту $logger->setAlertEmail ('additional_admin@no-reply.com'); $logger->setAlertEmail ('additional_admin2@no-reply.com'); // Позволяет отключить отладку для конкретного логгера // Данная настройка уберет из лог-файла информацию о месте вызова логгера // Рекомендуется использовать данную настройку для логгеров, записывающих большое кол-во данных при одном вызове // Снижает количество оперативной памяти, выделяемой php $logger->notUseBacktrace (); // Включает отладку для конкретного логгера // Используется в случае, когда глобально в настройках модуля выключена настройка отладки $logger->useBacktrace ();

Что нового в модуле

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

Полностью отказались от хранения настроек в файле конфигурации и перенесли все настройки в админ-панель Битрикс.

Внедрили ряд новых настроек и информирований. Теперь можно:

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

Отказоустойчивость и улучшение производительности

В альфа-версии модуля PHP не хватало памяти. Это отразилось на проектах с малыми серверными ресурсами: когда нужно было записать большое количество данных в файл, скрипт падал с фатальной ошибкой.

Чтобы выяснить причину, мы подключили профилирование. По результатам стало ясно, какие именно узлы модуля нужно рефакторить.

Переписали функционал записи логов в файл и протестировали его на серверах с 1 Гб оперативной памяти. Тестовые скрипты для записи большого количества данных больше не падали. Производительность увеличилась примерно на 50%, если сравнивать с альфа-версией.

Удаление устаревших логов

Еще одна проблема, с которой столкнулись, — это громадный объем устаревших данных логирования. Ценности они не несли, а место на сервере занимали. Поэтому мы реализовали на агенте функционал, который очищает устаревшие файлы и директории. В настройках модуля можно указать, как часто нужно удалять устаревшие логи.

Ссылки на модуль

Маркетплейс 1С-Битрикс http://marketplace.1c-bitrix.ru/solutions/intensa.logger/
Репозиторий https://github.com/intensa/intensa.logger