Битрикс логи ошибок

Просмотров: 7165
Дата последнего изменения: 21.04.2022

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

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

Поэтому логи не должны занять все свободное пространство на диске, т.е. в логи нужно помещать только нужную информацию, а не все подряд. Устаревшие логи должны удаляться. Для удаления устаревших логов лучше всего настроить задание на 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());

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

Два года назад писали про внутренней инструмент для логирования. С помощью модуля Intensa Logger мы выполняем отладку на проектах на 1С-Битрикс.

Ниже расскажем про релиз-версию, в которой:

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

Результат выложили в 1С-Битрикс: Маркетплейс, пользуйтесь.

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

Учимся логировать с модулем

Intensa Logger — простой функциональный модуль CMS Bitrix, который логирует данные проекта в файлы. Подойдет для отслеживания «‎узких»‎ мест в проекте и дебага при разработке.

В модуле реализованы:

• оповещения о критических проблемах в проекте,
• очищение устаревших лог-файлов,
• таймеры выполнения,
• SQL-трекер на основе diag.

Как добавить модуль в проект

Самый простой способ — установить его через маркетплейс.

Но можно и вручную. Для этого:

1. Клонируем репозиторий в директорию с модулями /bitrix/modules/ или /local/modules/.
2. Переходим в директорию intensa.logger/lib (команда cd intensa.logger/lib).
3. Устанавливаем зависимости composer install --no-dev.
4. Добавляем модуль через админскую часть сайта /bitrix/admin/partner_modules.php.

При установке модуль создает:

• защищённую директорию /logs/ в корне проекта для хранения лог-файлов,
• почтовое события для оповещений фатальных уровней логирования,
• агента для удаления устаревших лог-файлов.

Как работать с хранилищем логов

По умолчанию лог-файлы хранятся в директории /logs/ в корне проекта. Изменить место хранения можно в настройках модуля. Защита логов от просмотра в браузере реализована через .htaccess.

В проектах, которые используют nginx в качестве веб-сервера, нужно самостоятельно обезопасить хранилище. Для этого закрываем директорию от просмотра в браузере в конфигах nginx или меняем пути хранилища логов — выносим хранилище из document_root.

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

Например, все логи за 19 августа 2021 года можно найти в директории /logs/2021-08-19/. Название лог-файла совпадает с кодом логгера, который передается в конструктор класса ILog.

Уровни логирования

Уровень лога — это классификация проблемы. В модуле они подразделяются так:

• DEBUG,
• INFO,
• NOTICE,
• WARNING,
• ERROR,
• CRITICAL,
• ALERT,
• EMERGENCY.

Для каждого уровня лога действует одноименный метод, но с особенностями.

• log() — является алиасом для info().
• fatal() — является алиасом для alert().

Это наследие, с которым приходится жить 🙂

Уровни CRITICAL, ALERT, EMERGENCY, помимо записи данных в лог-файл, отправляют сообщение администратору сайта. Адрес электронной почты можно указать в настройках модуля.

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

Из чего состоят логи

Разбираем пример по частям.

Как использовать возможности модуля — на примерах

1. Пример инициализации логгера и демонстрация базовых методов.

// Подключение модуля
 BitrixMainLoader::includeModule('intensa.logger');

 // Инициализация объекта логгера
 // В конструктор передаем код логгера, которому будет соответствовать имя лог-файла
 $logger = new IntensaLoggerILog('logger_code');

 // Пример записи логов уровня INFO
 // Вторым параметром можно передать данные любого типа
 $context = ['яблоко', 'мандарин', 'банан'];

 $logger->info('сообщение', $context);

 // Пример записи логов уровня ERROR
 $logger->error('что-то пошло не так', $context);

 // Пример записи логов уровня ALERT
 // В данном случае будет отправлено письмо с информацией из лога
 $logger->alert('алярм! мы все сломали', $context);

Содержимое лог-файла:

[2021-11-24 01:24:30][:info][pid:2696] сообщение Array
 (
     [0] => яблоко
     [1] => мандарин
     [2] => банан
 )
 [2021-11-24 01:24:30][:error][pid:2696] что-то пошло не так Array
 (
     [0] => яблоко
     [1] => мандарин
     [2] => банан
 )
 [2021-11-24 01:24:30][:alert][pid:2696] алярм! мы все сломали Array
 (
     [0] => яблоко
     [1] => мандарин
     [2] => банан
 )

1. Пример вызова таймера.

// Подключение модуля
 BitrixMainLoader::includeModule('intensa.logger');

 // Инициализация объекта логгера
 // В конструктор передаем код логгера, ему будет соответствовать имя лог-файла
 $logger = new IntensaLoggerILog('logger_timer');

 $context = ['яблоко', 'мандарин', 'банан'];
 $logger->info('Логируем какие-то данные', $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');

Содержимое лог файла:

[2021-11-24 01:29:47][:info][pid:2704] Логируем какие-то данные Array
 (
     [0] => яблоко
     [1] => мандарин
     [2] => банан
 )
 [2021-11-24 01:29:48][:info][pid:2704] Timer timer_1 Array
 (
     [CODE] => timer_1
     [START_TIME] => 2021-11-24 01:29:47.000000
     [STOP_TIME] => 2021-11-24 01:29:48.000000
     [EXEC_TIME] => 1.000375032
 )
 [2021-11-24 01:29:50][:info][pid:2704] Timer timer_internal Array
 (
     [CODE] => timer_internal
     [START_TIME] => 2021-11-24 01:29:48.000000
     [STOP_TIME] => 2021-11-24 01:29:50.000000
     [EXEC_TIME] => 2.000512838
 )
 [2021-11-24 01:29:53][:info][pid:2704] Timer timer_2 Array
 (
     [CODE] => timer_2
     [START_TIME] => 2021-11-24 01:29:48.000000
     [STOP_TIME] => 2021-11-24 01:29:53.000000
     [EXEC_TIME] => 5.000887871
 )
 [2021-11-24 01:29:53][:info][pid:2704] Timer dont_stop Array
 (
     [CODE] => dont_stop
     [START_TIME] => 2021-11-24 01:29:53.000000
     [STOP_TIME] => 2021-11-24 01:29:53.000000
     [EXEC_TIME] => 0.010784864
     [STOP_POINT] => __destruct
 )

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

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

1. Использование трекера SQL-запросов.

BitrixMainLoader::includeModule('intensa.logger');

 $logger = new IntensaLoggerILog('logger_sql');
 // Запускаем трекер-sql запросов
 $logger->startSqlTracker('get_users');
 // Пример кода, который делает запрос к базе данных
 $users = [];
 $result = BitrixMainUserTable::getList([
     'select' => ['ID','SHORT_NAME'],
     'order' => ['LAST_LOGIN'=>'DESC'],
     'limit' => 3
 ]);
 // Остановка трекера
 $logger->stopSqlTracker('get_users');

Содержимое лог-файла:

[2021-11-24 01:29:48][:info][pid:1138] SqlTracker get_users: Array
 (
     [0] => Array
         (
             [query] => 
                             SELECT main_user.ID AS ID,
                             CONCAT(main_user.LAST_NAME, ' ', UPPER(SUBSTR(main_user.NAME, 1, 1)), '.') AS SHORT_NAME
                             FROM b_user main_user
                             ORDER BY main_user.LAST_LOGIN DESC
                             LIMIT 0, 3
             [time] => 0.0076520442962646
         )
 )

Методы логгера

Доступные методы класса ILog помогут кастомизировать поведение каждого отдельного объекта логгера.

BitrixMainLoader::includeModule('intensa.logger');

 $logger = new IntensaLoggerILog('logger_sql');

 // Метод заставляет логгер перезаписывать файл при каждом новом вызове логирующего метода
 $logger->rewrite();

 // Через этот метод можно установить дополнительный email для получения алерт-сообщений на почту
 $logger->setAlertEmail('additional_admin@no-reply.com');
 $logger->setAlertEmail('additional_admin2@no-reply.com');

 // Позволяет отключить отладку для конкретного логгера
 // Данная настройка уберет из лог-файла информацию о месте вызова логгера
 // Рекомендуется использовать данную настройку для логгеров, записывающих большое кол-во данных при одном вызове
 // Снижает количество оперативной памяти, выделяемой php
 $logger->notUseBacktrace();

 // Включает отладку для конкретного логгера
 // Используется в случае, когда глобально в настройках модуля выключена настройка отладки
 $logger->useBacktrace();

Что нового в модуле

Конфигурация модуля

Полностью отказались от хранения настроек в файле конфигурации и перенесли все настройки в админ-панель Битрикс.

Внедрили ряд новых настроек и информирований. Теперь можно:

• менять права доступа к файлам и директориям логов,
• записывать логи в формате json,
• управлять ротацией логов,
• получать информацию о безопасности логов (логи недоступны в браузере),
• получать информацию о существовании корневой директории и делать в ней записи.

Отказоустойчивость и улучшение производительности

В альфа-версии модуля PHP не хватало памяти. Это отразилось на проектах с малыми серверными ресурсами: когда нужно было записать большое количество данных в файл, скрипт падал с фатальной ошибкой.

Чтобы выяснить причину, мы подключили профилирование. По результатам стало ясно, какие именно узлы модуля нужно рефакторить.

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

Удаление устаревших логов

Еще одна проблема, с которой столкнулись, — это громадный объем устаревших данных логирования. Ценности они не несли, а место на сервере занимали. Поэтому мы реализовали на агенте функционал, который очищает устаревшие файлы и директории. В настройках модуля можно указать, как часто нужно удалять устаревшие логи.

Ссылки на модуль

1. Маркетплейс 1С-Битрикс http://marketplace.1c-bitrix.ru/solutions/intensa.logger/
2. Репозиторий https://github.com/intensa/intensa.logger

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

Как отправить логи десктоп-приложения Битрикс24 в Поддержку