Все статьи

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

Разработка модуля 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 ('timer1');
sleep (1);
// остановка таймера. необходимо передать код таймера.
$logger->stopTimer ('timer1');
 
$logger->startTimer ('timer2');
 
// можно запускать один таймер внутри другого
$logger->startTimer ('timer_internal');
sleep (2);
$logger->stopTimer ('timer_internal');
 
sleep (3);
$logger->stopTimer ('timer2');
 
// если у таймера не указана точка остановки, то время остановки определяется в д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] => timer1
 [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] => timer2
 [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.

Расскажите о своей задаче — мы предложим решение

Ответим в течение дня. Предложение и оценку подготовим за 2 рабочих дня.

Навигация

Что почитать ещё

Кейсы
Решения
Материалы