воскресенье, 25 апреля 2010 г.

Введение в Log4php, часть 2. Использование

Итак, в первой части мы подключили к проекту log4php, сконфигурировали его. А что дальше?

Базовое использование

У логгера log4php есть все те же уровни, что у логгера log4net. И, в соответствии с ними, функции (в порядке возрастания уровня):
  • trace
  • debug
  • info
  • warn
  • error
  • fatal
Все эти функции имеют одну и ту же сигнатуру: <functionName>(mixed $message, [mixed $caller = null]). $message — это, как нетрудно догадаться, то, что мы выводим в лог. А вот $caller вообще нигде не используется.
А теперь попробуем сотворить с логами что-нибудь интересное.

Категории

В параметрах conversionPattern был у нас такой ключ %c. Рассмотрим подробнее, что он значит.
Помимо RootLogger-а в конфиге log4php можно определять и другие логгеры:
<log4php:configuration xmlns:log4php="http://logging.apache.org/log4php/" threshold="all" debug="true">
    <appender name="default" class="LoggerAppenderDailyFile">
        <param name="file" value="logs/%s.log" />
        <param name="datePattern" value="Ymd" />
        <layout class="LoggerLayoutPattern">
            <param name="ConversionPattern" value="%d{H:i:s} %p    [%c]: %m (at %F:%L) %x%n" />
        </layout>
    </appender>

    <logger name="test">
        <appender_ref ref="default" />
    </logger>

    <logger name="modules">
        <appender_ref ref="default" />
    </logger>

    <root>
        <level value="DEBUG" />
        <appender_ref ref="default" />
    </root>
</log4php:configuration>
До этих дополнительных логгеров можно достучаться по имени:
$logger = Logger::getLogger("test");
Так вот, имя логгера — это и есть та самая категория, которую впоследствии выведет ключ %c.
Категории могут быть полезны в случае большого приложения из многих частей. Использование разных логгеров позволяет отлаживать каждую часть, не засоряя при этом лог сообщениями из других частей. Ведь логгер можно в любой момент запросто отключить:
<logger name="test">
    <appender_ref ref="default" />
    <level value="OFF" />
</logger>

Вывод объектов

Как уже говорилось, объекты выводятся с помощью функции var_export. Поэтому нужно уделять особое внимание объектам с циклическими ссылками — при попытке их вывести в лог обязательно вылезет ошибка. Выходом может быть написание собственных рендереров. А можно пойти в класс LoggerRendererDefault и в его единственном методе render заменить var_export на serialize или json_encode. Во случае serialize, правда, вывод будет совсем некрасивый. А json_encode не умеет ходить в приватные поля.

NDC

Nested diagnostic context (NDC) был описан в статье Patterns for Logging Diagnostic Messages. Попробую описать основную его идею.
Итак, у нас есть сайт, к которому идут всякие разные запросы. И для всего этого сплошной кашей валится лог, в котором черт ногу сломит, потому что непонятно, какое сообщение к какому запросу относится. И возникает желание кроме сообщений лога выводить параметры окружения, т.е. контекст, в котором выполняется запрос. Причем мы очень ленивые, и потому хотим, чтобы это происходило как-то само собой, так что вариант вручную добавлять что-либо к сообщению отпадает. Тут нам и приходит на помощь NDC.
Для работы с NDC в log4php есть специальный класс LoggerNDC с кучей статических функций со вполне очевидными названиями — push, pop, clear, и так далее. С помощью всех этих функций можно управлять стеком сообщений NDC, которые будут выводится абсолютно во все логи.
Рассмотрим синтетический пример. Пусть есть класс:
class User
{
    public $isAdmin;
    
    public function accessProfile()
    {
        $logger = Logger::getRootLogger();
        $logger->trace("Accessing profile");
        
        if ($this->isAdmin)
            $logger->trace("Accessing admin privileges");
    }
}
И пусть есть следующий код:
$user = new User();

if (!empty($user))
{
    LoggerNDC::push("user");
    
    if ($user->isAdmin)
        LoggerNDC::push('admin');
    
    $logger->trace("Try to access profile");
    $user->accessProfile();    

    if ($user->isAdmin)
        LoggerNDC::pop();        
}
$logger->trace("User proceed");

if (!empty($user))
    LoggerNDC::pop();
В конфиге же пропишем ConversionPattern = %p [%x] %m%n.
После исполнения такого кода в логе выведется:
TRACE [user] Try to access profile
TRACE [user] Accessing profile
TRACE [user] User proceed
Если мы добавим $user->isAdmin = true;, то лог будет следующий:
TRACE [user admin] Try to access profile
TRACE [user admin] Accessing profile
TRACE [user admin] Accessing admin privileges
TRACE [user] User proceed
Если же зададим $user = null;, то получим:
TRACE [] User proceed
Итак, все, что находится в NDC, выводится во все логи, откуда бы они ни были вызваны.

MDC

MDC расшифровывается, как Mapped Diagnostic Context. По сути это то же самое, что NDC, с тем отличием, что данные хранятся не в стеке, а в хеше. И можно обращаться к ним по ключу.
Для работы с MDC в log4php существует класс LoggerMDC, содержащий, опять же, статические функции. Причем, в отличие от LoggerNDC, их совсем немного — put, get и remove. Использование данного класса вполне очевидно:
LoggerMDC::put("user", "darja");
$logger->info("Hello, World");
Однако, для полного счастья этого недостаточно. Нужно сконфигурить логгер так, чтобы он выводил нужную нам информацию. В conversionPattern мы рассматривали ключ %X. Сам по себе он ничего не выводит. Нужно писать %X{key}, где key — ключ хеша. Итак, если мы зададим ConversionPattern = %p [%X{user}] %m%n, то наш код выведет в лог:
INFO [darja] Hello, World

Заключение

Мы рассмотрели некоторые интересные аспекты использования log4php. Видно, насколько мощные возможности предоставляет log4php для отладки приложений. Слава ему.
Надо сказать, что все сказанное относятся и к другим логгерам этого семейства.

Ссылки

6 комментариев:

bear комментирует...

Очень понятно. Я искал способы фильтрации логов для разных аппендеров и, как оказалось, механизм категорий, но NDC и MDC были приятным и неожиданным дополнением, о котором вроде не упоминается в родной документации log4php.
Дарья, большое спасибо! :)

bear комментирует...

Дарья, скажите, пожалуйста, а в самом верхнем примере кода, вот здесь:
[b]
param name="file" value="logs/%s.log" [/b]

%s - для чего? Это позволяет как-то использовать appender с параметром, или случайно вышло?

darja комментирует...

Тут используется LoggerAppenderDailyFile, он создает новые файлы логов каждый день. Тут file - это не само имя файла, а формат, в который с помощью функции sprintf будет подставляться текущая дата. Соответственно, %s - это место для даты.

Анонимный комментирует...

Полезная штука (%s.log). А я всё думал как же LoggerAppenderDailyFile, а файл логов все один и тот же.
Спасибо!

Влад.

Анонимный комментирует...

Больное спасибо Вам за статью.

Пользуюсь log4j в Java. А тут потребовался логгер для PHP. Ваша статья мне очень помогла.

Валерий.

Aquary комментирует...

За статью спасибо.

Вопрос - а насколько громоздка эта штука в плане ресурсов и времени интерпретации?

Скачал, распаковал... вышло, что исходники тянут на 270 Кб. У меня некоторые проекты целиком столько весят! Конечно, инклюдится сразу едва ли половина, однако - есть подозрение, что громоздкая штука получается. Или я ошибаюсь?