Ежемесячно наши программисты завершают десятки задач по разработке и поддержке интернет-магазинов. С ростом команды и проектов мы разработали удобный инструмент для логирования в виде модуля для системы 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.
Статью подготовили:
Intensa — производственное агентство для e‑commerce.
Какие задачи мы решаем