Log::Dispatch::Email は即座にメールが配信されない件

今面倒を見ているアプリケーションのログ管理として Log::Dispatch 系を採用しました。

SQL などのトレースログは Log::Dispatch::FileRotate を使ってファイルに書き出しています。エラーログは同じく Log::Dispatch::FileRotate を使ってファイルに書き出すとともに、Log::Dispatch::Email を使ってメール通知をする仕組みで実装しました。

すでにこのアプリケーションは稼働させてから半年ほど経つわけですが、どうにもエラーメールの配信が遅れたり遅れなかったりと不思議な挙動をしていました。幸いにも致命的なエラーは１つもなく今に至っているので、大事には至っていないのですが、長い間メールの遅延の原因がわからず悩んできました。

最初はメールサーバが遅延しているかと考えていたので、メールサーバ側を解析していたのですが、どうにも原因わからず。そうこうしているうちに別の仕事で忙しくなったりと、なかなか解析が進まなかったのですが、昨日やっと解析が終わりました。

ヽ(´ー｀)ノﾊﾞﾝｻﾞｰｲ

よくよくメールヘッダーを見てみると、そもそもリクエスト時間が遅れているっぽいことがわかりました。
とするとアプリケーション側で遅延していると考えるのが自然です。開発環境でメールサーバのログをトレースしつつ、意図的にエラー発生を発生させると、確かにメールサーバへのリクエストが遅延しています。

何気なく同時進行している仕事の都合上、開発環境の apache の設定で mod_perl を一時 off にさせてみたのですが、再び解析を進めていくと、急にメールの遅延がなくなりました。どうも mod_perl のように永続的に動作させているときに発生する不具合っぽいです。

とりあえず Log::Dispatch::Email のソースを見てみました。　ヽ(´Д｀ヽ)(/´Д｀)/イヤァ〜ン

package Log::Dispatch::Email;

use strict;
use warnings;

use Log::Dispatch::Output;

use base qw( Log::Dispatch::Output );

use Params::Validate qw(validate SCALAR ARRAYREF BOOLEAN);
Params::Validate::validation_options( allow_extra => 1 );

our $VERSION = '2.26';

# need to untaint this value
my ($program) = $0 =~ /(.+)/;

sub new
{
    my $proto = shift;
    my $class = ref $proto || $proto;

    my %p = validate( @_, { subject  => { type => SCALAR,
                                          default => "$program: log email" },
                            to       => { type => SCALAR | ARRAYREF },
                            from     => { type => SCALAR,
                                          optional => 1 },
                            buffered => { type => BOOLEAN,
                                          default => 1 },
                          } );

    my $self = bless {}, $class;

    $self->_basic_init(%p);

    $self->{subject} = $p{subject} || "$0: log email";
    $self->{to} = ref $p{to} ? $p{to} : [$p{to}];
    $self->{from} = $p{from};

    # Default to buffered for obvious reasons!
    $self->{buffered} = $p{buffered};

    $self->{buffer} = [] if $self->{buffered};

    return $self;
}

sub log_message
{
    my $self = shift;
    my %p = @_;

    if ($self->{buffered})
    {
        push @{ $self->{buffer} }, $p{message};
    }
    else
    {
        $self->send_email(@_);
    }
}

sub send_email
{
    my $self = shift;
    my $class = ref $self;

    die "The send_email method must be overridden in the $class subclass";
}

sub flush
{
    my $self = shift;

    if ($self->{buffered} && @{ $self->{buffer} })
    {
        my $message = join '', @{ $self->{buffer} };

        $self->send_email( message => $message );
        $self->{buffer} = [];
    }
}

sub DESTROY
{
    my $self = shift;

    $self->flush;
}

なぜこんな仕様で実装したか不明なのですが、メールのリクエストをは受け付けるだけ受け付けて、Log::Dispatch::Email が DESTORY されるときに一気に送信するロジックになっています。リクエスト毎に送信をしたければ、インスタンス生成時に buffered = 0 を指定しなければいけないようです。デフォルトでは bufferd = 1 になっています。

このアプリの実装として、mod_perl 配下で動作させているときは、ログインスタンスが永続化される作りになっています。ということは DESTROY が永久に call されないのでメールが配信されないことになります。

一方で、mod_perl 配下で動作させたときのメモリリーク等を懸念して、MaxRequestsPerChild の値を 500 に設定していました。これで個々の子サーバプロセスは 500 回リクエストを処理したら終了します。そのときになって初めて Log::Dispatch::Email の DESTROY が call されてメールが送信されていたため、メール遅延が発生していたわけです。

また一方で、CGI モードにしたときには、毎回 DESTROY されるので即座にメール配信されたわけです。

メール遅延は Log::Dispatch::Email の仕様だったわけです。よく見たらドキュメントにもちゃんと書いてありました。

というわけで、ログの設定はこんな感じに変更しました。赤字が追加部分。

dispatchers = errorfile email

errorfile.class       = Log::Dispatch::FileRotate
errorfile.min_level   = debug
errorfile.filename    = /tmp/log/app01/error.log
tracefile.size        = 200000000
errorfile.mode        = append
errorfile.TZ          = JST
errorfile.DatePattern = 'yyyy-MM-dd'
errorfile.format      = '[%d] [%p] %m at %F line %L%n'

email.class     = Log::Dispatch::Email::MailSender
email.min_level = error
email.name      = email
email.to        = メールアドレス
email.from      = メールアドレス
email.subject   = system error
email.smtp      = メールサーバIP
email.buffered  = 0

何度も書いている気がするけど、やっぱり採用するモジュールは一通りソースとドキュメントを読むべきですね！(* ^ーﾟ)ﾉ