По следам происшествия: как логировать эффективно

Людям свойственно ошибаться. Это относится не только к разработчикам, но и к пользователям. В ходе разработки мы контролируем процесс и можем разобраться в неправильном поведении программы простой отладкой. А вот расследовать случай, который произошёл в production-окружении, не всегда просто. В таких ситуациях на помощь приходят журналы. И чтобы от них действительно была польза, их нужно вести правильно.

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

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

Стандарт PSR-3. Уровни логирования

PSR — это свод рекомендаций для PHP-разработчиков. Он содержит советы по оформлению кода, некоторые интерфейсы и другие рекомендации. Один из его документов (PSR-3) посвящён реализации логера.

Знакомство с этими рекомендациями предлагаю начать с уровней логирования, которые в них предлагаются.

<?php
 
namespace Psr\Log;
 
class LogLevel
{
   const EMERGENCY = 'emergency';
   const ALERT     = 'alert';
   const CRITICAL  = 'critical';
   const ERROR     = 'error';
   const WARNING   = 'warning';
   const NOTICE    = 'notice';
   const INFO      = 'info';
   const DEBUG     = 'debug';
}

PSR-3 определяет 8 уровней сообщений. Если их использовать правильно, искать ошибки станет проще и получится оперативнее реагировать на инциденты. Давайте разберёмся, как выбрать уровень:

• DEBUG — отладочная информация, подробно раскрывающая детали события;
• INFO — любые интересные события. Например, когда пользователь авторизовался;
• NOTICE — важные события в рамках ожидаемого поведения;
• WARNING — исключительные ситуации, не являющиеся ошибками. Например, использование устаревшего метода, неправильный запрос в API;
• ERROR — ошибки, которые следует отслеживать, но они не требуют срочного исправления;
• CRITICAL — критическое состояние или событие. Например, недоступность компонента, неожиданное исключение (Exception);
• ALERT — ошибка или событие, требующие срочных действий. Например, когда база данных недоступна;
• EMERGENCY — ситуация, когда программа или система полностью выведены из строя.

Чтобы использовать эти уровни, достаточно добавлять их название к строке каждой записи журнала. Например:

[2021-01-01 12:10:35] website.INFO: User has changed his password

На уровни ALERT и EMERGENCY часто ставят дополнительное информирование, например по SMS. По INFO можно легко восстановить последовательность действий пользователя, по DEBUG — узнать точные значения переменных, результат работы функции в определённом месте и прочее.

PSR-3. Интерфейс для класса-логера

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

LoggerInterface требует реализации методов ведения журнала — и чтобы она учитывала уровни, которые мы разобрали выше. Создадим собственный класс-логер, который будет соответствовать этому интерфейсу и делать записи в файл.

Для начала загрузим код стандарта PSR-3 с помощью Composer.

composer req psr/log

В загруженном пакете содержится несколько классов, трейтов и интерфейсов. Среди них — LogLevel, который мы разобрали выше, и интересующий нас в данный момент LoggerInterface. Давайте создадим новый класс, реализующий этот интерфейс. Важно: убедитесь, что у вас подключён класс-автозагрузчик (vendor/autoload.php).

<?php
// index.php
 
// Автозагрузчик Composer
require_once 'vendor/autoload.php';
// Наш новый класс-логер
require_once 'src/FileLogger.php';

<?php
// src/FileLogger.php
 
// Если `use` не добавился автоматически
// - обязательно добавьте его самостоятельно
use Psr\Log\LoggerInterface;
 
// Наследуем интерфейс логера от PSR-3
class FileLogger implements LoggerInterface
{
   // ...
}

Класс мы создали. Но чтобы он удовлетворял требованиям стандарта, нужно написать все методы, описанные в интерфейсе. Самый важный из них — log. В нём будет указана основная логика записи в файл.

class FileLogger implements LoggerInterface
{
   // ...
   public function log($level, $message, array $context = []): void
   {
       // Текущая дата в формате 1970-12-01 23:59:59
       $dateFormatted = (new \DateTime())->format('Y-m-d H:i:s');
 
       // Собираем сообщение, подставив дату, уровень и текст из аргумента
       $message = sprintf(
           '[%s] %s: %s%s',
           $dateFormatted,
           $level,
           $message,
           PHP_EOL // Перенос строки
       );
 
       // Пишем в файл gb.log
       file_put_contents('gb.log', $message, FILE_APPEND);
       // FILE_APPEND - позволяет добавлять записи к существующим,
       // не затирая старые логи
   }
   // ...
}

Для полного удовлетворения интерфейса LoggerInterface нам осталось написать реализацию для методов emergency, alert, critical, error, warning, notice, info и debug, которые соответствуют уровням (их мы разобрали выше). Их реализация сводится к очень простому принципу: мы вызываем метод log, передав в него необходимый уровень.

class FileLogger implements LoggerInterface
{
   // ...
   public function emergency($message, array $context = []): void
   {
       // Передаем уровень из класса LogLevel
       $this->log(LogLevel::EMERGENCY, $message, $context);
   }
 
   public function alert($message, array $context = []): void
   {
       $this->log(LogLevel::ALERT, $message, $context);
   }
   // и так далее
   // ...
}

Использование логера

Теперь, когда наш класс реализует интерфейс, предложенный стандартом PSR-3, мы можем легко задействовать его в любом месте. Например, в файле index.php:

<?php
// index.php
 
// Автозагрузчик Composer
require_once 'vendor/autoload.php';
// Наш новый класс-логер
require_once 'src/FileLogger.php';
 
$logger = new FileLogger();
$logger->debug('Message from index.php');

Или в любом другом классе.

<?php
 
use Psr\Log\LoggerInterface;
 
class ExampleService
{
   /** @var LoggerInterface */
   private $logger;
 
   public function __construct(LoggerInterface $logger)
   {
       $this->logger = $logger;
   }
 
   public function doSomeAction(): void
   {
       // выполняем какие-либо действия
       $this->logger->debug('Message from ExampleService');
   }
}

Обратите внимание: в качестве типа аргумента конструктора мы указываем не конечную реализацию (FileLogger), а именно интерфейс стандарта PSR-3. Это удобно, потому что позволяет легко заменять применяемый логер на любой другой, поддерживающий этот интерфейс.

Контекст

Вы могли заметить, что все методы интерфейса LoggerInterface содержат аргумент $context. Зачем он нужен?

Контекст предназначен для передачи вспомогательной и зачастую динамичной информации. Например, если вы делаете отладочную запись (уровень debug), можно передать в контекст значение переменной.

Чтобы применять этот аргумент, нам нужно поддержать его в методе log. Давайте доработаем его, учитывая, что $context — массив.

<?php
 
class FileLogger implements LoggerInterface
{
   // ...
   public function log($level, $message, array $context = []): void
   {
       $dateFormatted = (new \DateTime())->format('Y-m-d H:i:s');
 
       // Преобразуем $context в формат json
       $contextString = json_encode($context);
       $message = sprintf(
           '[%s] %s: %s %s%s',
           $dateFormatted,
           $level,
           $message,
           $contextString, // Добавляем контекст к строке лога
           PHP_EOL
       );
 
       file_put_contents('gb.log', $message, FILE_APPEND);
   }
   // ...
}

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

<?php
// index.php
//...
 
$userName = 'GeekBrains';
$userEmail = 'user@gb.ru';
 
$logger = new FileLogger();
$logger->debug('Message from index.php', [
   'user_name' => $userName,
   'user_email' => $userEmail,
]);

В результате мы получим запись следующего вида:

[2021-09-02 13:00:24] debug: Message from index.php {"user_name":"GeekBrains","user_email":"user@gb.ru"}

Касательно контекста действует одно простое правило: любая динамическая информация должна передаваться в нём, но не в сообщении. То есть, если вы формируете сообщение в лог с помощью sprintf или конкатенацией строчных переменных, — скорее всего, эту информацию можно вынести в контекст. Соблюдая это правило, проще искать что-то в журнале, потому что не приходится предугадывать (или вычислять) значения переменных.

Библиотека Monolog

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

Здорово, что всё это уже реализовано в большинстве библиотек. Одна из самых распространённых – monolog.

Среди весомых преимуществ этого пакета:

• полная поддержка PSR-3;
• поддержка разных принципов обработки логов в зависимости от уровня;
• поддержка имён каналов (имена логеров);
• очень широкая поддержка фреймворков.

Чтобы начать использовать этот прекрасный инструмент, установим его с помощью Composer.

composer req monolog/monolog

Использование Monolog

Работа библиотеки monolog основывается на обработчиках. Они позволяют задавать конкретное поведение в ответ на события логирования. Например: запись в файл — это специальный обработчик, который называется StreamHandler. Давайте заменим использование нашего класса на загруженную библиотеку.

<?php
 
// index.php
 
use Monolog\Logger;
use Monolog\Handler\StreamHandler;
 
// Автозагрузчик Composer
require_once 'vendor/autoload.php';
 
// В качестве аргумента передаем имя канала
$logger = new Logger('gb-demo');
// Подключаем обработчик. В качестве аргумента у StreamHandler - путь к файлу
$logger->pushHandler(new StreamHandler('gb.log'));
 
// Далее все оставляем, как было
$userName = 'GeekBrains';
$userEmail = 'user@gb.ru';
$logger->debug('Message from index.php', [
   'user_name' => $userName,
   'user_email' => $userEmail,
]);

Если мы запустим этот код, в файле gb.log появится запись следующего вида:

[2021-09-02T13:16:14.122686+00:00] gb-demo.DEBUG: Message from index.php {"user_name":"GeekBrains","user_email":"user@gb.ru"} []

Очень похоже на то, что было у нас ранее, кроме добавления имени канала (gb-demo).

Важная особенность обработчиков monolog: им можно задать уровень, на котором они работают. Например, чтобы писать все ошибки в отдельный файл.

<?php
 
// index.php
 
use Monolog\Handler\StreamHandler;
use Monolog\Logger;
use Psr\Log\LogLevel;
 
// ...
$logger = new Logger('gb-demo');
$logger->pushHandler(new StreamHandler('gb.log'));
$logger->pushHandler(new StreamHandler('errors.log', LogLevel::ERROR));
 
// ...
$logger->emergency('It is not even an error. It is EMERGENCY!!!');

Подключённый на уровень ERROR обработчик будет принимать на себя все записи уровня ERROR и выше. Поэтому вызов метода emergency попадает в оба файла: gb.log и errors.log

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

Все записи от одного запроса

Когда мы разрабатываем проект, журналы читаются очень просто, они последовательны и ясны. Но когда продуктом пользуются несколько человек, логи могут перемешиваться и больше запутывать, чем помогать. Для решения этой проблемы есть простой трюк. Вместо имени канала (логера) используйте уникальный идентификатор сессии. Получить его можно с помощью встроенной функции session_id(). При этом сессия должна быть обязательно запущена с помощью session_start()

Рассмотрим пример реализации такого приёма:

<?php
// index.php
 
// Запускаем сессию
session_start();
 
// ...
 
// Передаем id сессии в название канала
$logger = new Logger(session_id());
// ...

Что нам даёт такая простая доработка? Важную возможность — группировать все записи запросам пользователя.

// Это записи от первого запроса
[2021-09-02T13:35:54.155043+00:00] b30m8k1fvmf638au7ph0edb3o5.DEBUG: Message from index.php {"user_name":"GeekBrains","user_email":"user@gb.ru"} []
[2021-09-02T13:35:54.156800+00:00] b30m8k1fvmf638au7ph0edb3o5.EMERGENCY: It is not even an error. It is EMERGENCY!!! [] []
// А это записи от второго запроса. У них отличаются названия каналов
[2021-09-02T13:36:03.528474+00:00] u7fi04mn99h0timg148rles1um.DEBUG: Message from index.php {"user_name":"GeekBrains","user_email":"user@gb.ru"} []
[2021-09-02T13:36:03.529421+00:00] u7fi04mn99h0timg148rles1um.EMERGENCY: It is not even an error. It is EMERGENCY!!! [] []

Что дальше?

Monolog поддерживает множество полезных готовых обработчиков, на которые стоит обратить внимание:

• TelegramBotHandler — отправляет записи в Telegram от имени бота. Пригодится для высоких уровней логирования;
• SlackHandler — похож на предыдущий, но отправляет записи в Slack;
• SwiftMailerHandler — позволяет отправлять записи по email;
• ChromePHPHandler – даёт доступ к журналам прямо из браузера Chrome в режиме Live.

Заключение

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

Главное — помнить простые правила:

• Следование PSR-3 позволит легче заменять классы-логеры в вашем коде и использовать внешние библиотеки.
• Разные уровни логирования помогут сосредоточиться на важном.
• Отделение динамической информации в контекст упростит поиск по журналам.
• Библиотека Monolog реализует практически все возможные хотелки. Обязательно изучите её.
• С помощью идентификатора сессии можно разделить записи в журналах по каждому запросу.
• Лучше писать много лишних логов, чем не дописать один важный.