Модуль логирования для 1С-Битрикс

Ежемесячно наши программисты завершают десятки задач по разработке и поддержке интернет-магазинов. С ростом команды и проектов мы разработали удобный инструмент для логирования в виде модуля для системы 1С-Битрикс, на которой разработано большинство наших проектов.

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

Что такое логирование?

Логирование — это запись данных о работе программы или сервера в какое-либо хранилище (файл, база данных и т. д.) с целью дальнейшего анализа и выявления потенциальных проблем.

Зачем логировать?

Допустим, у вас есть функционал, который работает с API другого сервиса. Код стабильно выполняет свою работу. Однако, если вам упадет тикет с сообщением об ошибке, вы вряд ли вспомните, что вы отправляли в API, какой запрос получили, и не поймете, когда именно произошла ошибка. В таких ситуациях логирование помогает получить всю необходимую информацию о природе бага и быстро отладить работу кода.

Что логировать?

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

Мы используем модуль логирования в dev- и production-окружении:

Для дебаггинга при разработке.
При выкладке нового функционала. Обязательно добавляем временные логи, чтобы проследить, все ли работает должным образом.
Постоянные логи в критичных местах проекта.
Для замера времени выполнения кода.

Наш модуль Intensa.Logger (версия alfa)

Корневая директория для логов задается разработчиком. Ввиду безопасности ее можно вынести из DOCUMENT_ROOT проекта.

Классы модуля:

IntensaLogger/ILog — класс, реализующий в себе основной функционал модуля.
IntensaLoggerI/LogAlert — класс, реализующий функционал для оповещения разработчиков посредством почтовых событий.
IntensaLogger/Settings — класс, который отвечает за настройки модуля.

Структура хранения логов:

Все логи хранятся в основной директории (DIR_LOG определяется в файле конфига) /logs/
Для каждого дня создается своя директория /logs/01.10.2018/
Критические проблемы, зафиксированные уровнем error и fatal, попадают в отдельную директорию errors /logs/01.10.2018/errors/
Имя файла лога определяется символьным кодом (задается в конструкторе объекта логгера) и расширением файла (LOG_FILE_EXTENSION определяется в файле конфига) /logs/01.10.2018/catalog_info.log
Если не указать код логгера, то данные будут записаны в общий файл /logs/01.10.2018/common.log

Уровни логирования, их особенности и способы применения

Функционал имеет 5 уровней логирования:

debug
info
warning
error
fatal

При вызове error и fatal данные будут записываться в отдельную папку {LOG_DIR}/errors/. Также на почту разработчика будет отправлено письмо с цепочкой логов. Использовать данный уровень следует только в критических местах проекта для выявления проблем, которые могут повлиять на работоспособность системы.

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

Пример использования

<? // подключение модуля if (CModule:IncludeModule ('intensa.logger')) { /* * Создание объекта логгера. * Конструктору передаем код логгера * Файл лога будет соответствовать коду логгера + расширение, заданное в файле конфига */ $logger = new \Intensa\Logger\ILog ('log_code'); } /* * Ниже представлены несколько методов для более гибкой работы с данными логов * Методы переопределяют значения, заданные в файле конфига в рамках вызова логгера * */ /* * При вызове данного метода вся цепочка логов будет отправляться на почту * Независимо от того, был ли вызван метод fatal () * */ $logger->sendAlert (); /* * При вызове данного метода в запись лога будет добавлена информация о файле, в котором был вызван метод * Данные будут записываться даже при установленном флаге USE_BACKTRACE = false в файле конфига * */ $logger->useBacktrace (); /* * При вызове данного метода вызовы лога будут отделены разделителями * Разделители будут устанавливаться даже при установленном флаге USE_DELIMITER = false в файле конфига * */ $logger->useLogDelimiter (); /* * Для каждого уровня логирования имеется свой метод * */ $logger->debug ('debug message', [0 => 'context']); $logger->info ('log message', [0 => 'context']); $logger->log ('log message', [0 => 'context']); // алиас для log () $logger->error ('error message', [0 => 'context']); /* * При вызове метода будет автоматически отправлено письмо c полной цепочкой логов в рамках вызова * */ $logger->fatal ('fatal message', [0 => 'context']); ?>

Использование логгера при создании заявки

<? $ticketData = ['name' => 'John', 'sname' => 'Smith', 'phone' => '8000']; if (CModule:IncludeModule ('intensa.logger')) { $logger = new \Intensa\Logger\ILog (__FILE__); } $logger->log ('ticket data', $ticketData); try { $ticket = new TestTicket ($ticketData); $newTicketID = $ticket->add (); $logger->log ('ticket create number ' . $newTicketID); } catch (Exception $e) { $logger->fatal ('ticket create problem', $e); } <? $ticketData = ['name' => 'John', 'sname' => 'Smith', 'phone' => '8000']; if (CModule:IncludeModule ('intensa.logger')) { $logger = new \Intensa\Logger\ILog (__FILE__); } $logger->log ('ticket data', $ticketData); try { $ticket = new TestTicket ($ticketData); $newTicketID = $ticket->add (); $logger->log ('ticket create number ' . $newTicketID); } catch (Exception $e) { $logger->fatal ('ticket create problem', $e); } ?> <? $ticketData = ['name' => 'John', 'sname' => 'Smith', 'phone' => '8000']; if (CModule:IncludeModule ('intensa.logger')) { $logger = new \Intensa\Logger\ILog (__FILE__); } $logger->log ('ticket data', $ticketData); try { $ticket = new TestTicket ($ticketData); $newTicketID = $ticket->add (); $logger->log ('ticket create number ' . $newTicketID); } catch (Exception $e) { $logger->fatal ('ticket create problem', $e); } ?>

Использование логгера при добавлении товара

<? if (CModule:IncludeModule ('intensa.logger')) { $logger = new \Intensa\Logger\ILog ('import_script'); } $logger->useLogDelimiter (); $logger->log ('start import'); if (file_exists ('import.xml')) { $logger->log ('file exist'); // . // code // . $uid = $arImportFile['GUID']; $logger->log ('start add product'); if (in_array ($uid, $arProducts)) { $logger->error ('product exist. not add product', $uid); } else { // add product $logger->log ('success.product add', $uid); } } else { $logger->error ('file not exist'); } ?>

Использование таймера вызова

Допустим, нужно иметь в логе информацию о времени выполнения какого-то определенного участка кода:

<? $context = [1, 2, 3]; if (CModule:IncludeModule ('intensa.logger')) { $logger = new \Intensa\Logger\ILog ('my_logger_code'); } $logger->log ('Логируем какие-то данные', $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'); ?>

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

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

Еще одна небольшая особенность: ключи STARTPOINT и STOPPOINT будут добавлены в файл при включенной опции USE_BACKTRACE в конфиге или если вызван метод useBacktrace ().

Содержимое файла лога будет выглядеть следующим образом:

==============================[START: 9538]============================== [2018−10−08 16:15:47] [:info] [/var/www/html/test/ish.php:11] Логируем какие-то данные Array ( [0] => 1 [1] => 2 [2] => 3 ) [2018−10−08 16:15:48] [:timer] [/var/www/html/test/ish.php:17] Lead time: Array ( [CODE] => timer₁ [START_TIME] => 2018−10−08 16:15:47.000000 [STOP_TIME] => 2018−10−08 16:15:48.000000 [EXEC_TIME] => 1.000124931 [START_POINT] => /var/www/html/test/ish.php:14 [STOP_POINT] => /var/www/html/test/ish.php:17 ) [2018−10−08 16:15:50] [:timer] [/var/www/html/test/ish.php:24] Lead time: Array ( [CODE] => timer_internal [START_TIME] => 2018−10−08 16:15:48.000000 [STOP_TIME] => 2018−10−08 16:15:50.000000 [EXEC_TIME] => 2.000115871 [START_POINT] => /var/www/html/test/ish.php:22 [STOP_POINT] => /var/www/html/test/ish.php:24 ) [2018−10−08 16:15:53] [:timer] [/var/www/html/test/ish.php:27] Lead time: Array ( [CODE] => timer₂ [START_TIME] => 2018−10−08 16:15:48.000000 [STOP_TIME] => 2018−10−08 16:15:53.000000 [EXEC_TIME] => 5.000380039 [START_POINT] => /var/www/html/test/ish.php:19 [STOP_POINT] => /var/www/html/test/ish.php:27 ) [2018−10−08 16:15:53] [:timer] [/var/www/dev/intensa.logger/classes/general/ILog.php:516] Lead time: Array ( [CODE] => dont_stop [START_TIME] => 2018−10−08 16:15:53.000000 [STOP_TIME] => 2018−10−08 16:15:53.000000 [EXEC_TIME] => 0.009480000 [START_POINT] => /var/www/html/test/ish.php:30 [STOP_POINT] => __destruct ) ==============================[END: 9538]==============================

На скрине ниже описан шаблон записи лога.

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

Новые фичи или как будет выглядеть beta-версия

Модуль Logger работает 2 года и значительно облегчает нашу работу. За это время было найдено несколько узких мест и продуманы полезные фичи. Уже этой весной планируем реализовать несколько новых возможностей и выложить модуль в Bitrix Marketplace.

Ниже список наиболее интересных исправлений и фич для следующего обновления:

Ускоренная запись в файлы.
Максимальная отказоустойчивость.
Просмотр логов через админку «Битрикса».
Хранение настроек модуля в базе и редактирование через админ-панель Bitrix (интерфейс просмотра и настройки).
Построение отчета вызова логгера в формате отчет-таблицы о вызовах во всем проекте (поможет избавиться от ненужных логов, например, отладочных).
Автоматическая очистка старых логгеров — можно будет настроить очистку логов по времени, например старше 2 недель (настраиваемый параметр).
Оповещение о фатальных проблемах посредством telegram-бота.

Использование модуля ежемесячно экономит отделу разработки десятки часов. При выкладке нового функционала мы получаем тикет об ошибке, определяем точное место сбоя и устраняем его.

Модуль размещен на GitHub.