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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

  • Все логи хранятся в основной директории (DIR_LOG определяется в файле конфига) /logs/
  • Для каждого дня создается своя директория /logs/2018-10-01/
  • Критические проблемы, зафиксированные уровнем error и fatal, попадают в отдельную директорию errors /logs/2018-10-01/errors/
  • Имя файла лога определяется символьным кодом (задается в конструкторе объекта логгера) и расширением файла (LOG_FILE_EXTENSION определяется в файле конфига) /logs/2018-10-01/catalog_info.log
  • Если не указать код логгера, то данные будут записаны в общий файл /logs/2018-10-01/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_1');
sleep(1);
// остановка таймера. необходимо передать код таймера.
$logger->stopTimer('timer_1');
 
$logger->startTimer('timer_2');
 
// можно запускать один таймер внутри другого
$logger->startTimer('timer_internal');
sleep(2);
$logger->stopTimer('timer_internal');
 
sleep(3);
$logger->stopTimer('timer_2');
 
// если у таймера не указана точка остановки, то время остановки определяется в д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_1
    [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_2
    [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.

Статью подготовили:

Программирую и люблю молоко.
Пишу тексты про digital.

Intensa — производственное агентство для e‑commerce.

Мы помогаем торговым сетям увеличивать выручку интернет-магазинов за счет быстрой и отлаженной аутсорс-разработки.

Какие задачи мы решаем
0
0
0
0
You May Also Like
ССтатьи

Как мы построили процесс разработки

  • 26.02.2021
Командная работа в среде разработчиков неизбежно влечет проблемы с прочтением чужого кода, его перетиранием, неподходящим по статусам таск-трекером. В статье рассказываем, как…
ССтатьи

Развертывание фронтенд проекта на Heroku

  • 30.06.2022
В этой статье учимся разворачивать фронтенд приложения на PaaS-платформе Heroku. Heroku — облачная платформа для размещения веб-приложений. Легко масштабируется, интегрируется с docker…