Perlのスタックトレースを見やすく扱う方法

この記事は、Perl Advent Calendar 2019 23日目 の記事です。

概要

　Perlは、次のように通常の状態では例外が投げられてもスタックトレースを表示しません。

die.pl

sub do_something {
    die 'Something wrong happened!';
}

do_something();

Something wrong happened! at die.pl line 2.

　スタックトレースを見たい場合は次のように、 __DIE__ シグナルハンドラに die が実行された時スタックトレースを伴った例外を投げる Carp::confess を呼び出すようなフック処理を書いたり、そのような処理をやってくれる Carp::Always モジュールをuseしたりします。

sig_die.pl

use Carp qw( confess );

sub do_something {
    local $SIG{__DIE__} = \&confess;
    die 'Something wrong happened!';
}

do_something();

Something wrong happened! at sig_die.pl line 5.
 at sig_die.pl line 5.
        main::do_something() called at sig_die.pl line 8

　しかし、このような状態でコードを書き続けていくと、次のように例外を補足して再度例外を投げ直す...というような処理をした時に、実際にエラーが起きた時に見る必要のないスタックトレースまで表示されてしまい、例外が発生した箇所が突き止めづらく開発体験が悪くなってしまいます。

die_many_times.pl

use v5.30;
use warnings;
use utf8;
use Carp qw( confess );

sub one {
  die 'Something wrong happened!';
}

sub two {
  eval { one(); };
  if ($@) {
    die $@;
  }
}

sub three {
  local $SIG{__DIE__} = \&confess;
  eval {
    two();
  };
  if ($@) {
    die $@;
  }
}

three();

Something wrong happened! at die_many_times.pl line 7.
 at die_many_times.pl line 7.
        main::one() called at die_many_times.pl line 11
        eval {...} called at die_many_times.pl line 11
        main::two() called at die_many_times.pl line 20
        eval {...} called at die_many_times.pl line 19
        main::three() called at die_many_times.pl line 27
 at die_many_times.pl line 13.
        main::two() called at die_many_times.pl line 20
        eval {...} called at die_many_times.pl line 19
        main::three() called at die_many_times.pl line 27
 at die_many_times.pl line 23.
        main::three() called at die_many_times.pl line 27

　見たいスタックトレースは、1回目のスタックトレースの表示だけのはずで、rethrowしている箇所のスタックトレースは別に見なくてもいいはずです。

　本来ならフレームワークなどがスタックトレースが見やすくなるようによしなに扱ってくれるのですが、今利用している社内フレームワークではスタックトレースが見やすくなるような対応がされておらず、例外が発生した時のエラーログが見づらくて開発体験が悪い状況であるため、他のWAFの実装を調査しどのようにすればスタックトレースを見やすく扱えるのかを調べてみました。

　この記事ではMojoliciousの実装を参考に、スタックトレースを見やすく扱うための方法を記します。

1. スタックトレースを格納する例外クラスを作る

　まず、例外発生時のメッセージとスタックフレームのリストをインスタンス変数として持つ例外クラスを作り、例外を投げるときに利用します。

lib/MyException.pm

package MyException;
use v5.30;
use warnings;
use utf8;

# (4) エラーログとして出力されるときは文字列化するようにする
use overload (
  q{""}     => sub { shift->to_string },
  fallback => 1,
);

use Class::Accessor::Lite (
  new => 0,
  ro  => [qw( message frames )],
);

sub throw {
  my ($class, $message) = @_;
  # (1) die には文字列以外の値も渡せる
  die $class->new($message, $class->trace());
}

# (2) caller で例外が投げられた時に表示させたいスタックフレームのリストを取得するメソッド
sub trace {
  my ($class, $start) = (shift, shift // 1);
  my @frames;
  while (my @trace = caller($start++)) { push @frames, \@trace }
  \@frames;
}

sub new {
  # (3) スタックフレームのリストを外部から受け取る
  my ($class, $message, $frames) = @_;
  bless +{
    message => $message,
    frames  => $frames,
  }, $class;
}

sub to_string {
  my $self = shift;
 
  my $str = $self->message;
  my $frames = $self->frames;

  if ($str !~ /\n$/) {
    $str .= @$frames ? " at $frames->[0][1] line $frames->[0][2].\n" : "\n";
  }

  # (5) スタックトレースが文字列化された場合の表示され方
  for my $frame (@$frames) {
    $str .= qq{\t$frame->[3] called at $frame->[1] line $frame->[2]\n};
  }
 
  $str;
}

1;

　アプリケーションで例外を投げるときは基本的にこの例外クラスを継承したクラスで例外を投げるようにします。

package SomeException;
use parent 'MyException';

SomeException->throw('Something wrong happened!');

　ではこの例外クラスのコードについて解説していきます。

　まず (1) についてですが、throw メソッドの中では die にこの例外クラスのインスタンスを生成して渡すという処理をしています。このように die には文字列以外の値を渡せるので、例外を投げるときにインスタンスを作ってエラーメッセージ以外の情報を受け渡すこともできます。

　(2) の trace メソッドの中で、例外が投げられた時に表示させたいスタックフレームのリストを caller で取得しています。どのような情報が取得できるのかについては callerのドキュメント に譲ります。

　(3) では表示させたいスタックフレームのリストを外部から受け取っています。今回は直感的に表示させるスタックフレームの位置を外部から制御できるようにするため、このような実装にしました。例えば、 throw メソッドで例外クラスのインスタンスを作ってから例外を投げようとした場合、スタックトレース先頭には trace メソッドが呼ばれたことを記録しているスタックフレームが積まれています。これは、エラー発生時に見たくない情報なので、その次からのスタックフレームの情報を取得しています。

　(4) では文字列変換演算子をoverloadしています。これにより、実際にエラーが出力されるときに例外クラスのインスタンスは to_string により文字列化され、スタックフレームの内容が画面に出力されるになります。

　(5) でスタックフレームをフォーマットしています。これもどのような処理をやっているかの詳細は　callerのドキュメント に譲ります。

2. __DIE__ シグナルハンドラで文字列を例外クラスでラップする

　次にアプリケーションが起動されるあたりの処理で、(1) のように __DIE__ シグナルハンドラを利用し、die が実行された場合、 die に渡された引数が先ほど作った例外クラスのインスタンスならそのまま例外を投げ直し、そうでないなら die に渡された値(文字列であることを想定)をエラーメッセージとする例外クラスのインスタンスを生成し、その値でdieするフック処理を書きます。
　例外クラスで例外が投げられた時は例外を投げた時のスタックフレームを保持しつづけ、そうでない場合は一度だけスタックトレースを伴なった例外を投げるようになっているのがミソです。

die_many_times.pl

use v5.30;
use warnings;
use utf8;
use Carp qw( confess );
use MyException;

sub one {
  die 'Something wrong happened!';
}

sub two {
  eval {
    one();
  };
  if ($@) {
    die $@;
  }
}

sub three {
  # (1)
  local $SIG{__DIE__} = sub {
    my $e = $_[0];
    die ref $e ? $e : MyException->new($e);
  };
  eval {
    two();
  };
  if ($@) {
    die $@;
  }
}

three();

上記の対応をした状態で die_many_time.pl を実行

　上記の対応をした状態で概要の die_many_time.pl を実行すると、以下のようなエラーメッセージが出力されます。不必要な情報が消えて、わかりやすくなりました。

Something wrong happened! at die_many_times.pl line 8.
        main::one called at die_many_times.pl line 13
        (eval) called at die_many_times.pl line 12
        main::two called at die_many_times.pl line 26
        (eval) called at die_many_times.pl line 25
        main::three called at die_many_times.pl line 33

まとめ

　このように、基本的にスタックフレームの情報を持った例外クラスで例外を投げるようにした上で、それ以外の例外はアプリケーションを起動させるあたりの処理でスタックフレームの情報を持った例外クラスとして例外を投げ直させるようにすることで、スタックトレースを見やすく扱えることができます。
　このコードでは対応できていないケースもありますが、基本的にはこのような雰囲気で対応できることかと思います。

　明日(後1分後)の記事は、papixさんで Syntax::Keyword::TryとPerlのキーワードプラグイン (その2) です。

参考

• Mojolicious Line 200 ~ 206 のあたり
• Mojo::Exception