Perl: Cooking warnings

Данная заметка касается некоторых тактических приемов обработки предупреждений и не претендует на полноценный обзор систем логирования будь-то Log::Dispatch или Log::Log4perl.

Обработка предупреждений

Обычно имея лишь предупреждение подобное этому: "Use of uninitialized value in hash element at ...", - практически не возможно установить, что привело к нему. Необходима дополнительная информация: минимум входящие данные. Поэтому обработку предупреждений можно разделить на два уровня.

Первый уровень обработки предупреждений простой: он отлавливает предупреждения и ошибки, которые возникают до того, как заработает второй уровень. Для этого можно использовать CGI::Carp, например:

 use CGI::Carp qw(carpout);
 open (LOG, ">>/var/log/.../foo.log");
 carpout(*LOG);

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

Простейшая реализация обработки предупреждений второго уровня показана ниже.

Подключение обработчика и вызов подпрограммы записи предупреждений:

 use Foo::Log;
 
 sub main {
     # ...
     local SIG{__WARN__} = warn_trap();
     # ...
     write_warn($id_source, $id_input_data);
 }

Непосредственно модуль обработки (без экспорта имен и полезных прагм):

 package Foo::Log;
 
 my @warnings = ();
 
 sub warn_trap() {
     @warnings = ();
     my $old_warn_trap = $SIG{__WARN__};
     return sub {
         my $warn = shift;
         push @warnings, $warn;
         if ($old_warn_trap) {
             # Конечно, если хотим передать сообщение
             # вышестоящему обработчику.
             local $SIG{__WARN__} = $old_warn_trap;
             eval { &$old_warn_trap($warn) };
         }
     };
 }
 
 sub write_warn(;$$) {
     my ($id_source, $id_input_data) = @_;
     if (@warnings) {
         # Открываем лог файл и 
         # сохраняем $id_source, $id_input_data и @warnings.
         # ...
     }
 }

Почему не устанавливаю ловушку для __DIE__?
Потому что предпочитаю ловить die в eval и вызывать warn $@, да и первый уровень на страже.

Отладка

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

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

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

Нет проблем: используем callar и @DB::args в __WARN__ обработчике.

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

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

Более красивым решением может быть тактика точечных обработчиков предупреждений.

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

Пример реализации точечного обработчика:

 use Data::Dumper;

 sub pointed_warn_trap(@) {
     my @data = @_;
     my $old_warn_trap = $SIG{__WARN__};
     return sub { 
         my $message = join "", shift, Dumper @data;
         $old_warn_trap ? eval { &$old_warn_trap($message) } :
              warn $message;
     };
 }

Пример использования точечного обработчика:

 local $SIG{__WARN__} = pointed_warn_trap($foo, $too);

В этом примере $foo может быть обрабатываемыми данными, а $too - информацией из базы.

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

Заключение

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

P.S.
Копия: http://kiev.pm.org/node/188.