Magento 2. Monolog или как писать логи

Изучая различные модули для Magento 2 можно заметить, что логирование используется значительно реже по сравнению с Magento 1. В большей степени это связано с тем, что запись логов стала сложнее. Здесь я бы хотел сконцентрироваться на технической стороне вопроса, а именно как логировать данные, как писать логи в свой собственный файл и что же такое Monolog.

Оглавление

Monolog
Особенности применения в Magento 2
Реализация
Запись лога при помощи стандартного логгера
Запись лога при помощи стандартного логгера с кастомным каналом
Запись в кастомный файл при помощи собственного хендлера
Запись в кастомный файл при помощи virtualType
Быстрое логирование данных
Заключение

Monolog

Начнем с самого главного вопроса — Что такое Monolog и причем он здесь.

Monolog — Это библиотека, которая реализует PSR-3 стандарт для логирования данных. Именно Monolog используется в Magento 2 для записи логов.

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

PSR-3 основные моменты

1. Логгер (объект) обязан реализовывать \Psr\Log\LoggerInterface интерфейс.
2. Имеем следующие уровни ошибок (указаны в порядке приоритета от большего к меньшему):
EMERGENCY — System is unusable.
ALERT — Action must be taken immediately. Example: Entire website down, database unavailable, etc.
CRITICAL — Critical conditions. Example: Application component unavailable, unexpected exception.
ERROR — Runtime errors that do not require immediate action but should typically monitored.
WARNING — Exceptional occurrences that are not errors.Example: Use of deprecated APIs.
NOTICE — Normal but significant events.
INFO — Interesting events. Example: User logs in, SQL logs.
DEBUG — Detailed debug information.

3. Каждый уровень имеет свой метод (debug, info, notice, warning, error, critical, alert, emerg/emergency) и так же должен быть метод log, который 1ым параметром принимает уровень ошибки.
4. Методы принимают строку или что угодно реализующее __toString() (т.е. надо использовать вручную print_r($message,true) для массивов или передавать их в следующем параметре).
5. Все методы принимают $context массив, дополняющий лог.
6. Может, но не обязательно, быть реализована подстановка данных из $context массива в сообщение. В таком случае рекомендуется формат {name}, где name -> ключ массива в $context.

Monolog довольно прост в использовании. Давайте рассмотрим следующий пример.

use Monolog\Logger;
use Monolog\Handler\StreamHandler;
use Monolog\Formatter\HtmlFormatter;

// Создаем логгер с именем "name"
$log = new Logger('name');

// Добавляем хендлер, который будет писать логи в "path/to/your1.log" и слушать все ошибки с уровнем "WARNING" и выше (notice, info и debug не будут записаны).
$log->pushHandler(new StreamHandler('path/to/your1.log', Logger::WARNING));

// Добавляем хендлер, который будет писать логи в "path/to/your2.log" и реагировать на ошибки с уровнем "ALERT" и выше (т.е. будет писать ошибки только если их уровень alert или emergency). Будет блокировать остальные хендлеры, если этот был применен. Текст добавленный в лог файл будет отформатирован в html при помощи HtmlFormatter.
$log->pushHandler(new StreamHandler('path/to/your2.log', Logger::ALERT,false)
->setFormatter(new HtmlFormatter));

// Добавляем процессор, который добавляет ко всем записям дополнительную информацию.
$log->pushProcessor(function ($record) {
    $record['extra']['dummy'] = 'Hello world!';

    return $record;
});

// Добавляем записи
$log->warning('Foo');
$log->error('Bar',['test']);
$log->info('Test'); // не будет записан, так как ни 1 из хендлеров не слушает INFO

//your1.log
// [2019-08-12 02:57:52] name.WARNING: Foo [] ['extra'=>['dummy'=>'Hello world!']]
// [2019-08-12 02:57:53] name.ERROR: BAR ['test'] ['extra'=>['dummy'=>'Hello world!']]

//your2.log
// пустой, т.к не было ошибок ALERT и EMERGENCY

Основные моменты работы Monolog, которые надо иметь в виду:

• Logger — это объект, который мы используем для записи логов. Сам логгер не занимается записью, но управляет хендлерами. Может быть создано любое количество.
• Handler — объект, который непосредственно обрабатывает данные. Вы можете добавить сколько угодно хендлеров в логгер. Все они будут вызываться по очереди, независимо от того смог данный хендлер обработать ошибку или нет. Метод isHandling определяет сможет ли этот хендлер обработать поступившую ошибку.
  
  

  public function isHandling(array $record)
  {
          return $record['level'] >= $this->level;
  }
  

  
  Самое близкое сходство с хендлером, с моей точки зрения, это Event Observer.
  
• Processor — любая вызываемая сущность (callable). Может быть несколько. Могут быть назначены как глобально, так и установлены для хендлера. Сначала запускаются глобальные процессоры. Основная задача процессора добавить дополнительные данные в лог (например IP, с которого был коннект, значение глобальных переменных, информация на какой git ветке сейчас находится код и так далее).
• Formatter — преобразует вывод сообщения перед записью. Может быть только 1 на хендлер. Нужен для изменения форматирования тела сообщения, например для преобразования текста в html или json.
• Channel — имя логгера. Оно будет написано при записи лога. Так как 1 хендлер может быть применен в 2ух разных логгерах (будет писать логи в 1 и тот же файл) это позволит определить откуда пришла ошибка.
• Level — уровень ошибки. Данный параметр у хендлера означает минимальный уровень ошибки, который будет им обрабатываться.
• Bubble — всплытие сообщения. После того, как хендлер обработал сообщение, то логгер передает сообщение следующему хендлеру. Этот процесс можно остановить с помощью свойства bubble. Если у хендлера значение этого свойства false (по умолчанию всегда true), то после того как этот хендлер выполнит свою работу (смог обработать данную ошибку), другие хендлеры уже не запустятся.
• Sort Order — порядок выполнения. Последний добавленный хендлер всегда запускается самым первым. Именно эта особенность позволяет внедрять механизм полного отключения логгера (через bubbling false). Хендлеры добавленные через конструктор идут в порядке указанном в конструкторе.

Так как PSR-3 не обязывает разработчиков реализовывать автозамену значений в тексте, то по умолчанию Monolog этого не делает. Если вы напишите ->emerg('test 1111 {placeholder}', ['placeholder'=> 'foo']) то получите следующее
[2019-08-12 02:57:52] main.EMERGENCY: test 1111 {placeholder} {«placeholder»:«foo»} []

Чтобы замена работала вам необходимо подключить дополнительный процессор — \Monolog\Processor\PsrLogMessageProcessor.

Стоит сказать, что Monolog обладает огромным числом Formatter, Processor, Handler из коробки. Вы можете как использовать их, так и написать свои собственные.

Особенности применения в Magento 2

На оффициальном сайте Magento вы можете найти общий пример как использовать логгер. К несчастью представленный пример не раскрывает всех деталей и увы не отвечает на вопрос «как писать логи в свой собственный файл». Поэтому давайте разберемся во всем по подробнее.

Во времена Magento 1, наверное, все рано или поздно использовали Mage::log метод, который был доступен везде в коде и запись самого простого лога выглядела как Mage::log('ALARM!', null, 'api.log'). В результате у нас была запись следующего вида в файле var/log/api.log

2019-08-12T01:00:27+00:00 DEBUG (7): ALARM!

Формат по умолчанию: %timestamp% %priorityName% (%priority%): %message%.

Давайте посмотрим как логировать данные в самом простом случае в Magento 2. Чаще всего вы будете использовать $this->_logger->info('ALARM!'); (если такое свойство имеется у объекта, например унаследовано).

В результате такого вызова мы получим следующую запись в файле var/log/system.log

[2019-08-12 02:56:43] main.INFO: ALARM! [] []

Формат по умолчанию: [%datetime%] %channel%.%level_name%: %message% %context% %extra%

Если такого свойства (_logger или logger) нет у объекта, тогда нам понадобится сначала добавить в ваш класс зависимость \Psr\Log\LoggerInterface и записать полученный объект в свойство $logger (согласно PSR-2 пункту 4.2 и примеру, представленному на сайте Magento).

В отличии от Magento 1, здесь куда больше нюансов.

1. Параметры для записи лога.

Рассмотрим общий вызов метода записи

$this->_logger->{level}($message, $context = []);
//$this->_logger->log('{level}', $message, $context = []);

1) Где {level} это, согласно PSR-3, 1 из методов, зарезервированных для логирования определенного уровня ошибки (debug, info, notice, warning, error, critical, alert, emerg/emergency).
2) $message — в отличии от Magento 1, это должна быть строка. Т.е. $object->getData() здесь не будет работать. Массив с данными надо передавать в следующий параметр. Объекты \Exception являются исключением, так как реализация \Magento\Framework\Logger\Monolog обрабатывает их отдельно и автоматически прокидывает ->getMessage() дальше в качестве $message, если объект \Exception был передан в качестве сообщения.
3) $context — это необязательный параметр, массив.

2. Свойство $this->_logger имеется не во всех классах.

Присутствует в: Block, Helper, Model, Collection, etc.
Отсутствует в: ResourceModel, Controller, Comand, Setup, etc.

Подробнее про ResourceModel и Collection

В ResourceModel имеется свойство _logger, но оно не заполняется в конструкторе. Оно заполняется только при помощи приватного метода getLogger в \Magento\Framework\Model\ResourceModel\AbstractResource. Метод вызывается только в случае ошибки во время записи в бд (в блоке catch) внутри метода commit(). До тех пор, логгера у ресурс моделей не будет.

public function commit()
{
     $this->getConnection()->commit();
 
      if ($this->getConnection()->getTransactionLevel() === 0) {
          $callbacks = CallbackPool::get(spl_object_hash($this->getConnection()));
          try {
                foreach ($callbacks as $callback) {
                    call_user_func($callback);
                }
            } catch (\Exception $e) {
                $this->getLogger()->critical($e);
            }
        }
    return $this;
}

…
private function getLogger()
{
     if (null === $this->_logger) {
         $this->_logger = ObjectManager::getInstance()->get(\Psr\Log\LoggerInterface::class);
     }
     return $this->_logger;
}

У Collection логгер имеется с самого начала. Он присваивается в конструкторе \Magento\Framework\Data\Collection\AbstractDb и позже наследуется.

Нельзя не сказать, но в контроллерах есть способ получить логгер при помощи ObjectManager (через свойство $this->_objectManager). Но это не является, конечно же, самым правильным способом.

3. Дефолтный логгер и список хендлеров.

В глобальном di.xml (app/etc/di.xml) вы можете найти, что \Psr\Log\LoggerInterface имплементится \Magento\Framework\Logger\Monolog классом, который в свою очередь наследуется от \Monolog\Logger. Имя логгера main. Там же определены несколько хендлеров

…
<preference for="Psr\Log\LoggerInterface" type="Magento\Framework\Logger\Monolog" />
...
<type name="Magento\Framework\Logger\Monolog">
    <arguments>
        <argument name="name" xsi:type="string">main</argument>
        <argument name="handlers" xsi:type="array">
            <item name="system" xsi:type="object">Magento\Framework\Logger\Handler\System</item>
            <item name="debug" xsi:type="object">Magento\Framework\Logger\Handler\Debug</item>
            <item name="syslog" xsi:type="object">Magento\Framework\Logger\Handler\Syslog</item>
        </argument>
    </arguments>
</type>
...

Некоторые классы отличаются от перечисленных выше (так как переопределены в модуле Magento\Developer):

1) Magento\Framework\Logger\Handler\System (слушает INFO)
2) Magento\Developer\Model\Logger\Handler\Debug (слушает DEBUG)
3) Magento\Developer\Model\Logger\Handler\Syslog (слушает DEBUG)

В указанных классах (Debug и Syslog) добавлена возможность отключать запись логов (dev/debug/debug_logging и dev/syslog/syslog_logging соответственно).

Обратите внимание, что в списке хендлеров нет exception хендлера, который производит запись в exception.log. Он вызывается в System хендлере.

Magento\Framework\Logger\Handler\System

...
public function write(array $record)
    {
        if (isset($record['context']['exception'])) {
            $this->exceptionHandler->handle($record);

            return;
        }

        $record['formatted'] = $this->getFormatter()->format($record);

        parent::write($record);
    }
...

В Magento 2 до 2.2 была проблема связанная с тем, что логгер не мог перепрыгивать на другой хендлер после первого найденного. Данная проблема была вызвана тем, что Monolog рассчитывал что к нему все хендлеры приходят в массиве с цифровыми ключами, а приходили с буквенными (['system'=>,'debug'=>,...]). Разработчики Magento позже исправили ситуацию — они преобразуют хеш в обычный массив с цифровыми ключами прежде чем передать его в Monolog. Monolog сейчас так же изменил алгоритм перебора хендлеров и использует метод next().

4. Внедрение своего хендлера в список уже существующих.

Мы подходим к самому интересному, что немного портит впечатление от реализации в Magento 2. Вы не сможете добавить кастомный хендлер к списку уже существующих при помощи di.xml без …”дополнительных телодвижений”. Это связано с принципом мерджа конфигов.

Существует несколько Config Scope:

1) Initial (app/etc/di.xml)
2) Global ({moduleDir}/etc/di.xml)
3) Area-specific ({moduleDir}/etc/{area}/di.xml ie. frontend/adminhtml/crontab/webapi_soap/webapi_rest, etc.)

Внутри 1 уровня конфиги объединяются, но следующий уровень переопределяет их при мердже (если они там тоже объявлены). Это приводит к невозможности добавлять хендлеры в своих модулях к существующему списку, так как он объявлен в initial scope.

Возможно в будущем мы увидим реализацию, в которой добавление хендлеров будет вынесено из initial scope в какой-то другой модуль, тем самым перенесено в global scope.

Реализация

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

1. Запись лога при помощи стандартного логгера

Данный способ позволяет нам достаточно легко писать логи в 1 из стандартных логов (debug.log, system.log или exception.log).

class RandomClass
{
    private $logger;

    public function __construct(\Psr\Log\LoggerInterface $logger)
    {
         $this->logger = $logger;
    }

    public function foo()
    {
         $this->logger->info('Something went wrong');
         //[...some date...] main.INFO: Something went wrong [] []
    }
}

Все становится еще проще, если в нашем классе уже присутствует унаследованная зависимость логгера.

…
$this->_logger->info('Something went wrong'); // можно использовать метод ->debug, если вы хотите, чтобы сообщение писалось только в debug.log
...

2. Запись лога при помощи стандартного логгера с кастомным каналом

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

class RandomClass
{
    private $logger;

    public function __construct(\Psr\Log\LoggerInterface $logger)
    {
         $this->logger = $logger->withName('api'); //может быть любое имя
    }

    public function foo()
    {
         $this->logger->info('Something went wrong');
         //[...some date...] api.INFO: Something went wrong [] []
    }
}

Для поиска нужных логов теперь достаточно воспользоваться поиском по «api» (дефолтный логгер в Magento 2 называется main) в уже существующих файлах system.log, debug.log, exception.log. Можно использовать

grep -rn 'api' var/log/system.log

3. Запись в кастомный файл при помощи собственного хендлера

Создадим простой хендлер, который логирует все ошибки уровня Critical и выше в отдельный файл var/log/critical.log. Добавим также возможность, чтобы он блокировал все остальные хендлеры для данного уровня ошибки и выше. Это позволит уйти от дублирования данных в debug.log и system.log файлах.

<?php
namespace Oxis\Log\Logger\Handler;

use Magento\Framework\Filesystem\DriverInterface;
use Magento\Framework\Logger\Handler\Base;
use Monolog\Logger;

class Test extends Base
{
    protected $fileName = 'var/log/critical.log';

    protected $loggerType = Logger::CRITICAL;
    public function __construct(DriverInterface $filesystem)
    {
          parent::__construct($filesystem,null,null);
          $this->bubble = false; //так же можно и через метод setBubble()
    }
}

В Magento 2 2.2+ в конструкторе \Magento\Framework\Logger\Handler\Base изменился способ обработки пути до файла с логом

//было
BP . $this->fileName
//стало
BP. DIRECTORY_SEPARATOR . $this->fileName

Поэтому в старых хендлерах вы все еще можете найти / в начале $fileName.

К примеру выше стоит дать небольшое пояснение. Так как Base не позволяет установить bubble свойство через параметры конструктора, то нам бы пришлось либо повторять часть кода из конструктора Base, чтобы передать корректно входной параметр в родителя класса Base (который, к слову сказать, обладает входным параметром для установки этого свойства) либо воспользоваться таким подходом. Я выбрал 2ой вариант.

use Oxis\Log\Logger\Handler\Test;
use Psr\Log\LoggerInterface;

class RandomClass
{
    private $logger;

    public function __construct(
        LoggerInterface $logger,
        Test $handler
    ) {
         $logger->pushHandler($handler); //можно использовать setHandlers([$handler]), тогда все остальные хендлеры будут заменены нашим хендлером.
         $this->logger = $logger;
    }

    public function foo()
    {
         $this->logger->critical('Something went wrong'); // запись будет добавлена только в critical.log
         //[...some date...] main.CRITICAL: Something went wrong [] []
    }
}

Данный способ добавления хендлера, не идеальный, но позволяет уйти от Config Scope проблемы, которая потребует от нас дублировать все логгеры у себя в di.xml. Если же цель заменить все логгеры своим, то гораздо лучше использовать virtualType подход, который мы рассмотрим дальше.

4. Запись в кастомный файл при помощи virtualType

Данный подход позволяет нам заставить необходимый нам класс писать логи в указанный для этого лог файл при помощи di.xml. Похожий подход вы можете найти в Magento\Payment и Magento\Shipping модулях. Обращаю ваше внимание на то, что этот подход работает начиная с Magento 2 2.2 и выше.

В Magento 2 2.2+ был добавлен новый параметр в конструктор \Magento\Framework\Logger\Handler\Base, что позволяет создавать виртуальный хендлер и указывать через di.xml относительный путь до файл для записи лога. Ранее требовалось либо указывать полный путь через $filePath, либо создавать новый хендлер и записывать относительный путь в протектед свойство $fileName.

В di.xml нашего модуля добавляем следующее

     <!--Создаем виртуальный хендлер и указываем ему файл, в который будем писать логи-->
     <virtualType name="ApiHandler" type="Magento\Framework\Logger\Handler\Base">
        <arguments>
            <argument name="fileName" xsi:type="string">var/log/api.log</argument>
        </arguments>
    </virtualType>
   
   <!--Создаем виртуальный логгер, в который добавляем наш хендлер-->
    <virtualType name="ApiLogger" type="Magento\Framework\Logger\Monolog">
        <arguments>
            <argument name="name" xsi:type="string">api</argument>
            <argument name="handlers" xsi:type="array">
                <item name="default" xsi:type="object">ApiHandler</item>
            </argument>
        </arguments>
    </virtualType>

   <!--Добавляем в наш класс только что созданный логгер-->
    <type name="Oxis\Log\Model\A">
        <arguments>
            <argument name="logger" xsi:type="object">ApiLogger</argument>
        </arguments>
    </type>

Добавляем в Oxis\Log\Model\A класс логгер.

namespace Oxis\Log\Model;

class A
{
    private $logger;

    public function __construct(\Psr\Log\LoggerInterface $logger)
    {
         $this->logger = $logger;
    }

    public function foo()
    {
         $this->logger->info('Something went wrong');
    }
}

Теперь абсолютно все логи, которые будут писаться в нашем классе будут обрабатываться нашей версией логгера, который будет писать логи при помощи нашего хендлера в файл var/log/api.log.

4.1. Если класс получает логгер через объект $context, а не через свой конструктор.
Сюда можно отнести \Magento\Catalog\Model\Product, в зависимостях которого нет \Psr\Log\LoggerInterface, но есть \Magento\Framework\Model\Context, через который происходит установка логгера в свойство класса. В таком случае, нам необходимо немного усложнить вариант выше и подменить логгер находящийся в $context объекте. А чтобы это не затронуло всю Magento, то подменим $context только для нашего класса при помощи virtualType.

<virtualType name="ApiHandler" type="Magento\Framework\Logger\Handler\Base">
        <arguments>
            <argument name="fileName" xsi:type="string">var/log/api.log</argument>
        </arguments>
</virtualType>
<virtualType name="ApiLogger" type="Magento\Framework\Logger\Monolog">
        <arguments>
            <argument name="name" xsi:type="string">api</argument>
            <argument name="handlers" xsi:type="array">
                <item name="default" xsi:type="object">ApiHandler</item>
            </argument>
        </arguments>
</virtualType>

<!--Создаем виртуальный контекст и подменяем в нем logger-->
 <virtualType name="ApiLogContainingContext" type="Magento\Framework\Model\Context">
        <arguments>
            <argument name="logger" xsi:type="object">ApiLogger</argument>
        </arguments>
</virtualType>

<!--Заменяем контекст в нашем классе-->
<type name="Oxis\Log\Model\A">
        <arguments>
            <argument name="context" xsi:type="object">ApiLogContainingContext</argument>
        </arguments>
</type>

5. Быстрое логирование данных

Бывают случаи, когда нам необходимо быстро добавить логирование. Чаще всего это может понадобиться либо на продакшен сервере либо для быстрого тестирования.

...
$log = new \Monolog\Logger('custom', [new \Monolog\Handler\StreamHandler(BP.'/var/log/custom.log')]);
$log->error('test');
...

Плюсы данного подхода: пишет дату, имеется контекст (массив), автоматически добавляет \n в конец

В примере выше специально применен \Monolog\Logger, а не \Magento\Framework\Logger\Monolog который его расширяет. Дело в том, что при таком использовании разницы никакой нет, а писать меньше (и запомнить проще).

\Monolog\Handler\StreamHandler в свою очередь применен вместо \Magento\Framework\Logger\Handler\Base так как Base использовать в качестве сниппета не очень удобно по причине дополнительных зависимостей от сторонних классов.

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

...
file_put_contents(BP.'/var/log/custom.log', 'test',FILE_APPEND);
...

Плюсы данного подхода: относительно быстро писать и не нужно запоминать классы.

В обоих случаях главную роль выполняет константа BP. Она всегда указывает на папку с маджентой (на 1 уровень выше pub), что удобно и всегда помогает нам писать логи в нужное место.

Заключение

Я надеюсь информация изложенная выше оказалась или окажется вам полезной.