Bitrixvm логи ошибок

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

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

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

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

Все логи нужно держать в одной папке, чтобы было удобней их изучать (/logs/, /_logs/, /local/logs/ и т.п. ). В целях защиты следует закрыть доступ к папке с логами по http — настраивается в .htacces, 

deny from all

и/или добавить к названию файла уникальный для проекта постфикс.

Папку для логов надо предварительно создать и убедиться, что битрикс (веб-сервер) имеет права на запись в нее.

В системе 1С-Битрикс существует 2 вида логов

AddMessage2Log(…)

Это функция из старого ядра.
Многие модули пишут через нее отладочную информацию.

Пример настройки места хранения логов, выводимых данной функцией, выглядит так (не забывайте, что папка logs/bx должна быть создана):

define("LOG_FILENAME", $_SERVER["DOCUMENT_ROOT"] . "/logs/bx/" . date("Y-m-d") . ".log");

Прописать данную настройку можно, например, в dbconn.php.

Секция exception_handling в файле .settings.php

Это уже функционал нового ядра.

Ядро через данный функционал пишет информацию обо всех ошибках и исключениях. Что именно пишется — зависит от настроек.

Пример настройки логов с разделением по дате:

'exception_handling' => array (
  'value' => array (
      'debug' => false, // disables error output to screen
       // ошибки для вывода в лог
      'handled_errors_types' => E_ALL & ~E_NOTICE & ~E_STRICT & ~E_WARNING,
      'exception_errors_types' => E_ALL & ~E_NOTICE & ~E_WARNING & ~E_STRICT & ~E_COMPILE_WARNING,
      'ignore_silence' => true,
      'assertion_throws_exception' => true,
      'assertion_error_type' => 256,
      'log' => array (
          'settings' => array (
              'file' => "logs/bx_error/" . date("Y-m-d") . ".log",
			  'log_size' => 1000000, // ~ 1Mb per file
          ),
      ),
  ),
  'readonly' => true,
),

Функции отладки в ядре D7

На замену функции AddMessage2Log в ядре D7 пришли новые функции:

use BitrixMainDiagDebug;
Debug::dumpToFile($_SERVER); // для случаев, когда нужен var_dump
Debug::writeToFile($_SERVER); // когда нужен print_r

Также в ядре D7 появились методы, для измерения времени. В старом ядре аналогов не было.

use BitrixMainDiagDebug;
Debug::startTimeLabel("foo");
foo();
Debug::endTimeLabel("foo");

Debug::startTimeLabel("bar");
bar();
Debug::endTimeLabel("bar");

print_r(Debug::getTimeLabels());

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

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

Логи не должны занимать всё свободное пространство на диске, т.е. в логи нужно помещать только нужную информацию, а не всё подряд. Устаревшие логи должны удаляться. Для удаления устаревших логов лучше всего настроить задание на cron.

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

Все логи нужно держать в одной папке, чтобы было удобней их изучать (/logs/, /_logs/, /local/logs/ и т.п. ). В целях защиты следует закрыть доступ к папке с логами по http — настраивается в .htacces,

deny from all

и/или добавить к названию файла уникальный идентификатор.

Папку для логов надо предварительно создать и убедиться, что битрикс (веб-сервер) имеет права на запись в нее.

В системе 1С-Битрикс существует 2 вида логов:

ADDMESSAGE2LOG(…)

Это функция из старого ядра. Многие модули пишут через нее отладочную информацию.

Пример настройки места хранения логов, выводимых данной функцией, выглядит так (папка logs/bx должна быть создана):

define("LOG_FILENAME", $_SERVER["DOCUMENT_ROOT"] . "/logs/bx/" . date("Y-m-d") . ".log");

Прописать данную настройку можно, например, в dbconn.php.

СЕКЦИЯ EXCEPTION_HANDLING В ФАЙЛЕ .SETTINGS.PHP

Это уже функционал нового ядра D7.

Битрикс через данный функционал пишет информацию обо всех ошибках и исключениях. Что именно пишется — зависит от настроек.

Пример настройки логов с разделением по дате:

'exception_handling' => array (
  'value' => array (
      'debug' => false, // disables error output to screen
       // ошибки для вывода в лог
      'handled_errors_types' => E_ALL & ~E_NOTICE & ~E_STRICT & ~E_WARNING,
      'exception_errors_types' => E_ALL & ~E_NOTICE & ~E_WARNING & ~E_STRICT & ~E_COMPILE_WARNING,
      'ignore_silence' => true,
      'assertion_throws_exception' => true,
      'assertion_error_type' => 256,
      'log' => array (
          'settings' => array (
              'file' => "logs/bx_error/" . date("Y-m-d") . ".log",
			  'log_size' => 1000000, // ~ 1Mb per file
          ),
      ),
  ),
  'readonly' => true,
),

ФУНКЦИИ ОТЛАДКИ В ЯДРЕ D7

На замену функции AddMessage2Log в ядре D7 пришли новые функции:

use BitrixMainDiagDebug;
Debug::dumpToFile($_SERVER); // для случаев, когда нужен var_dump
Debug::writeToFile($_SERVER); // когда нужен print_r

Также в ядре D7 появились методы, для измерения времени. В старом ядре аналогов не было.

use BitrixMainDiagDebug;
Debug::startTimeLabel("foo");
foo();
Debug::endTimeLabel("foo");

Debug::startTimeLabel("bar");
bar();
Debug::endTimeLabel("bar");

print_r(Debug::getTimeLabels());

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

Ежемесячно наши программисты завершают десятки задач по разработке и поддержке интернет-магазинов. С ростом команды и проектов мы разработали удобный инструмент для логирования в виде модуля для системы 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 IntensaLoggerILog('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 IntensaLoggerILog(__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 IntensaLoggerILog(__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 IntensaLoggerILog(__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 IntensaLoggerILog('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 IntensaLoggerILog('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.

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