Проблема выбора

Для логирования сообщений Перл предлагает несколько готовых решений. Все они, как водится, размещены на CPAN'е. По запросу «log» можно найти кучу модулей на все случаи жизни.

Однако, среди всех этих модулей есть один особенный, называется он Log::Any.

Особенность этого модуля для логирования заключается в том, что он не занимается, собственно, логированием. Модуль Log::Any предоставляет программе (и программисту) универсальное API для обращений к другим модулям, которые занимаются непосредственно логированием.

Если вас мучает проблема выбора способа логирования в Перле — эта статья для вас.

Проблема


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

print "$time Начинаю загрузку файла\n";
# тут выполняется загрузка
print "$time Закончена загрузка файла\n";
print "$time Загружено $size байт\n";

Обратите внимание — для того, чтобы вычислить время $time, потребуются еще какие-то дополнительные действия, но я даже не буду заострять на этом внимание, потому что это не главная проблема.

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

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

И тогда вы захотите перенаправить вывод лога с консоли куда-нибудь ещё. В файл, в базу, в другую программу, в какой-нибудь веб-сервис по API, к чёрту на рога etc. Тут-то и возникнет проблема — куда же именно и как логировать сообщения?

  • Писать в файл? А вдруг ваш модуль будет использоваться в окружении, где нельзя писать файлы?
  • Писать в базу? А вдруг модуль для работы с базой будет не установлен?
  • Перенаправлять в другую программу? А вдруг пользователь вашего скрипта предпочитает совсем не ту программу, которую выбрали вы?

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

Решение


Использовать модуль Log::Any.

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

Идея этого модуля заключается в том, чтобы разделить процедуру логирования на две отдельные части, которые могут работать независимо друг от друга. При этом, та часть, которая генерирует сообщения, не имеет понятия о том, как и куда эти сообщения будут далее записываться. А часть, которая сообщения куда-то записывает, не имеет понятия о том, откуда эти сообщения взялись и как они были сформированы.

Вот как это работает


Диаграмма работы Log::Any

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

Отправка сообщений


Для отправки сообщения ваш код (в модуле или в скрипте, не важно) вызывает стандартную функцию, предоставляемую модулем Log::Any:

# Это загрузка модуля Log::Any с одновременным импортом объекта $log, к которому далее нужно будет обращаться для логирования
use Log::Any qw($log);

# А это - уже логирование (кроме метода error есть и другие методы)
$log->error("Что-то случилось при выполнении какой-то задачи");

Указанные выше две строчки — это всё, что нужно, для того, чтобы начать логирование. Но отправленное сообщение пока что не будет никуда записано, так-как мы еще не выбрали, куда конкретно писать лог.

Запись сообщений


Теперь нам нужно решить, куда мы писать лог. Для этого в скрипте нужно воспользоваться одним из адаптеров:

# Этот встроенный адаптер будет просто выводить все сообщения на экран
use Log::Any::Adapter ('Stdout');

# Этот встроенный адаптер будет записывать все сообщения в файл
use Log::Any::Adapter ('File', '/path/to/file.log');

# А этот внешний адаптер будет отправлять все сообщения в отдельный навороченный модуль для логирования Log::Dispatch
use Log::Dispatch;
my $log = Log::Dispatch->new(outputs => [[ ... ]]);
Log::Any::Adapter->set( { category => 'Foo::Baz' }, 'Dispatch', dispatcher => $log );

В комплекте с Log::Any поставляется несколько простых встроенных адаптеров — File, Stdout и Stderr. Как можно догадаться по названию, первый из них записывает сообщения в файл, а два других отправляют сообщения на стандартные выводы.

Помимо встроенных адаптеров на CPAN'е можно найти внешние, такие как Log4perl или Syslog. Внешние адаптеры позволяют писать логи куда угодно — хоть в Твиттер.

А если надо в Фейсбук? Тоже не проблема. Вы можете без особых усилий написать свой собственный адаптер к чему угодно. Создание своего адаптера описано в документации модуля, или вот тут на русском языке.

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

Логирование уже имеющихся действий


Коннекторы


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

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

Ремарка — термин «коннектор» я выдумал сам, возможно, имеется какое-то другое общепринятое название.

Модули-коннекторы обычно размещаются в пространстве имен Log::Any::For. Есть несколько готовых коннекторов, например, Log::Any::For::DBI или Log::Any::For::LWP.

Написание своих собственных коннекторов не формализовано, так-как сильно зависит от того, к чему, собственно, пишется коннектор. В общем и целом, коннектор работает так:

  • Перехватывается событие, которое нужно логировать. Для этого могут быть использованы разные средства, типа моков или tie.
  • Сообщение о событии отправляется в лог с помощью стандартного вызова $log->method('сообщение').

Использование коннектора происходит так (на примере коннектора LWP):

# Подключаем LWP
use LWP::Simple

# Подключаем коннектор к LWP
use Log::Any::For::LWP;

# И загружаем страничку из сети с помощью функции из LWP
get "http://www.google.com/";

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

Логирование предупреждений и исключений


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

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

Правильное решение — записать такое сообщение в лог. Но как? Ведь в лог пишутся сообщения, которые были явно отправлены туда программистом через объект $log, а варнинги и исключения выбрасывает интерпретатор, который ничего про наше замечательное логирование не знает и валит все свои сообщения просто на STDERR.

Значит, нужно всё, что идет на STDERR, принудительно перенаправить в лог.

Для решения этой задачи я не нашел подходящего коннектора на CPAN'е, поэтому написал свой — Log::Any::For::Std. Этот коннектор отправляет в лог все возможные сообщения интепретатора, на любом этапе исполнения программы.

Для перехвата STDERR иcпользуется функция tie:

tie *STDERR, __PACKAGE__;

Эта конструкция заворачивает абсолютно всё, что отправляется на STDERR, в нужный нам пакет, а в нем уже не составляет труда перенаправить сообщения в лог с помощью Log::Any.

При желании вы можете реализовать любой другой коннектор для перехвата предупреждений и исключений (или вообще можете их не перехватывать).

Фильтрация сообщений


Обстоятельства могут сложиться так, что имеющийся код уже выводит какие-то сообщения. Например, у меня есть большой проект с легаси-кодом, в котором всё логирование сделано так:

print STDERR "$time --- $login --- $pid --- некое сообщение\n";

Как можно видеть, здесь все сообщения отправляются на STDERR, а в тексте сообщений имеются всякие переменные, разделители, да плюс ещё перевод строки. Вдобавок, хоть это и не видно на глаз, все сообщения написаны без использования utf8.

Перенаправление сообщений с STDERR в лог легко решается с помощью коннектора Log::Any::For::Std, а вот лишний мусор из текста сообщения придется убирать отдельно. Для этого при подключении модуля Log::Any нужно включить фильтрацию.

Делается это примерно так:

use Log::Any '$log', filter => sub { my $msg = $_[2]; utf8::decode($msg); return $msg };

Каждое сообщение, отправляемое в лог с помощью $log->method(), будет пропускаться через функцию, указанную в аргументе filter. Переменная $_[2] в этой функции содержит отправляемое сообщение. Если вы хотите что-то сделать с сообщением, то вы должны взять его из этой переменной, модифицировать и возвратить. Возвращенное значение будет записано в лог.

К примеру, в приведенном выше коде текст сообщения приводится к utf8.

Пример скрипта


Давайте соберем всё это вместе в скрипте test.pl:

#!/usr/bin/perl

use strict;
use warnings;

use Log::Any '$log', filter => sub { my $msg = $_[2]; $msg =~ s/привет/прЕвеД/; return $msg };
use Log::Any::Adapter ('Stdout');
use Log::Any::For::Std;

print "Это просто сообщение\n";

$log->info("А это сообщение в лог");

$log->info("Тут на слове привет сработает фильтрация");

Module::func();

warn "Предупреждение тоже окажется в логе";

die "И даже исключение можно завернуть в лог";

# Модуль
package Module;

use Log::Any '$log';

sub func {
    $log->info("Сообщение из модуля окажется в логе");
}

Запускаем и видим следующее:

$ ./test.pl 
Это просто сообщение
А это сообщение в лог
Тут на слове прЕвеД сработает фильтрация
Сообщение из модуля окажется в логе
Предупреждение тоже окажется в логе at ./test.pl line 18.
И даже исключение можно завернуть в лог at ./test.pl line 20.

Все сообщения будут выведены на консоль, но не верьте глазам своим — только первая строчка является обычным выводом, всё остальное — это лог. Просто этот лог выведен на консоль.

А что, если теперь нам вдруг захочется отправить лог не на консоль, а в файл? С модулем Log::Any нет ничего проще:

# Достаточно сменить адаптер с этого
# use Log::Any::Adapter ('Stdout');

# На этот
use Log::Any::Adapter ('File', 'file.log');

Запускаем и видим:

$ ./test.pl 
Это просто сообщение

Как и ожидалось, на консоль будет выведен только print.

А вот куда делось всё остальное:

$ cat file.log 
[Fri Jun 19 17:25:44 2015] А это сообщение в лог
[Fri Jun 19 17:25:44 2015] Тут на слове прЕвеД сработает фильтрация
[Fri Jun 19 17:25:44 2015] Сообщение из модуля окажется в логе
[Fri Jun 19 17:25:44 2015] Предупреждение тоже окажется в логе at ./test.pl line 18.
[Fri Jun 19 17:25:44 2015] И даже исключение можно завернуть в лог at ./test.pl line 20.

Резюме


  • Модуль Log::Any позволяет добавить в ваши программы и модули гибкое логирование, которое потом не потребуется переделывать при смене способа сохранения лога
  • Адаптеры Log::Any::Adapter позволяют адаптировать вашу программу к любому способу сохранения лога
  • Коннекторы Log::Any::For позволяют подключить логирование к любому источнику сообщений

Комментарии (16)


  1. knutov
    19.06.2015 19:26

    А что с нагрузкой в сравнении с альтернативами?

    Разруливается ли ситуация, когда в один файловый лог пишут несколько воркеров?


    1. ivanych Автор
      19.06.2015 19:46

      > А что с нагрузкой в сравнении с альтернативами?

      А что считать альтернативой? Log::Any не пишет логи, это не логгер. Log::Any — это прокси, непосредственно логи пишутся всё теми же логгерами, что и раньше. При прямом сравнении «чистого» логгера и этого же логгера через Log::Any производительность будет выше у «чистого» логгера.

      > Разруливается ли ситуация, когда в один файловый лог пишут несколько воркеров?

      Опять же — в файл пишет логгер. Если он не следит за параллельным доступом — будет ой.


      1. mayorovp
        21.06.2015 09:36

        К примеру, в .NET есть log4net и NLog, оба построены по указанному принципу. В Java лично я не знаю других библиотек кроме log4j — но на самом деле их так много, что была сделана отдельная абстракция над ними (Apache Commons Logging).

        Является ли Log::Any единственной библиотекой для ведения логов в Perl?


        1. ivanych Автор
          21.06.2015 11:59
          +1

          В Перле есть много библиотек для ведения логов.

          К примеру, есть Log4Perl — аналог явовской log4j. Есть AnuEvent::Log — специализированная библиотека для логирования асинхронных программ. Есть Log::Fast — библиотека для логирования бешеных кроликов, пишущая быстрее, чем syslog. И много других.

          Это — именно библиотеки для логирования, логгеры.

          А описанный в статье модуль Log::Any — это не логгер, он не пишет логи, даже банально на экран ничего не выводит. Log::Any — это прокси, API между программой и логерами.

          Аналогов именно вот такого, прокси-модуля — нет. А библиотек для логирования — во множестве.


          1. mayorovp
            21.06.2015 12:01

            А как же use Log::Any::Adapter ('File', 'file.log')? Оно не пишет ничего само в файл? Или не является частью Log::Any?


            1. ivanych Автор
              21.06.2015 12:07

              Ок, чутка соврал. В комплекте с Log::Any идут три встроенных адаптера, которые действительно пишут сами. Но это — тестовые, демонстрационные адаптеры, чтобы совсем уж разработчика в недоумение не вводить:)

              В продакшене эти адаптеры не используются, они учебные. Вместо них используются адаптеры к логерам.


              1. mayorovp
                21.06.2015 12:08

                Значит, Log::Any — это аналог Apache Commons Logging из мира Java?


                1. ivanych Автор
                  21.06.2015 12:10

                  Не могу ответить, не знаком с Apache Commons Logging.


    1. ivanych Автор
      19.06.2015 19:48

      Log::Any — это как DBI. Можно самому работать с базой через соответствующий DBD, но через DBI удобнее:)


  1. Pono
    19.06.2015 20:46

    Мне кажется, или тут переизобретён syslog?


    1. ivanych Автор
      19.06.2015 21:11

      Есть что-то общее. Но сислог — это другой уровень, он находится, условно, между программой и операционкой.

      А Log::Any — он находится между компонентами программы, чтобы все компоненты в итоге писали в одно место.

      Представьте — я пишу программу, используя два модуля от разных авторов. Один пишет в файл, а другой в базу. А мне надо — на экран. Для решения этой беды и нужен Log::Any.


      1. cubuanic
        24.06.2015 01:30

        Совсем не сислог.

        Pono — еще лучше, представьте себе, я пишу не программу, а модуль.
        Но кем и как он будет использован — я не знаю.
        Возможно его будете использовать вы, или ivanych, или еще миллион тел которые найдут его на CPAN и решат что он полезный.
        И мне надо чтоб он писал что-то в лог.
        Чтобы в случае граблей вы могли мне отрепортить что-то вразумительное и полезное вместо «не работает».
        В какие логи он будет писать и какие либы для этого будет использовать — я без понятия.
        Это будет решать тот кто пишет аппликейшен.
        Но логать мне как-то надо.
        Вот для таких случаев Log::Any и был придуман в первую очередь.

        Это своего рода фреймверк для логанья в перле, который поддерживается всё бОльшим и бОльшим кол-вом модулей, и который (с помощью того же адаптера в Log4Perl) позволит настроить логанье от каждого компонента независимо, при этом не то что не меняя код этих модулей/компонентов, а даже и не просматривая его.


  1. crackpot
    19.06.2015 23:04

    А не пробовали пытаться забирать конфигурацию адаптера/логгера из внешнего конфига или вообще из $ENV?


    1. ivanych Автор
      19.06.2015 23:08

      Не понял. Куда забирать и для чего?


      1. powerman
        20.06.2015 00:49

        crackpot вероятно имел в виду, что было бы неплохо делать что-то вроде:

        PERL_LOGANY_ADAPTER=File:/tmp/my.log ./myscript
        
        и чтобы при наличии такой переменной окружения она имела приоритет над адаптером подгруженным в ./myscript (если он вообще хоть один адаптер сам загружает).

        У меня смутные воспоминания что такое возможно, но в доке сходу не нашёл. Сложность реализации такого подхода скорее всего связана с тем, что многие адаптеры не такие простые как Screen/File, и их нужно настраивать перл-кодом, который в переменную окружения в общем случае засунуть затруднительно.


  1. Hellsy22
    20.06.2015 11:50

    Похоже, что основной плюс в приличном количестве готовых адаптеров.