Yii2でわかるユニットテストはログ出力を切ったほうがいい理由

タイトルのまんまですが、Yii2 にかぎらず、自動テストを一括実行したさい大量にアプリケーションログが出るのは無駄だしいろいろヤバいので、ログを出力しないようにしましょう、という話です。

ログを出力するべきとき

Yii2 だとデバッガで見るとわかりますが、高度な Web アプリケーションフレームワークは、ひとつのリクエストが非常に多くのログを出力します。多くは単なるトレースログですが、きちんと完成している場合でも、警告やエラーは含まれます。

というのも、通常のナビゲーションでは起こらないような不正アクセスが起きた場合や、UIで想定していないようなクエリパラメータの間違いがあった場合は、それらをログに残すべきでだからです。

たとえば、ユーザーのログイン失敗が連続して起こっているとき、それは以下のようなコードでログを出力して検知できます。

class LoginForm extends Model
{
    // ...

    public function login()
    {
        if ($this->validate()) {
            return Yii::$app->user->login($this->getUser(), $this->rememberMe ? 3600*24*30 : 0);
        } else {
            // ここ
            Yii::warning('ログインに失敗しています: ' . $this->username);
            return false;
        }
    }
}

こんなフォームに対して、ログイン失敗を自動テストする場合を考えましょう。

ロギングは思ったより高度

一般的に、ロギングの仕組みはその使いやすさに比べてずいぶん高度です。

Yii::$app->log には、 yii\log\Dispatcher というログ配信マネージャーのようなコンポーネントが差し込まれています。この yii\log\Dispatcher には、複数の yii\log\Target をログの送り先として登録できます。Yii::error() や Yii::trace() の呼び出しは、一時的に yii\log\Logger にバッファされてから Dispatcher に送信されて、それらが効率的に複数の Target に送られます。

このような仕組みを持っているおかげで、特定のカテゴリのログだけをメールで通知したり、致命的なエラーを専用のデータベースに収集して、プログラムの修正すべき箇所を分析したりできます。

Yii 標準のアプリケーションテンプレートでは、config\web.php に、 error と warning レベルのすべてのカテゴリのログを受け取って、それをファイルに書き出すよう設定された、 yii\log\FileTarget が登録されています。

$config = [
    // ...
    'components' => [
        // ...
        'log' => [
            'targets' => [
                [
                    'class' => 'yii\log\FileTarget',
                    'levels' => ['error', 'warning'],
                ],
            ],
        ],
    ],
];

ここに、EmailTarget や DbTarget を追加すれば、それもログの配信先になります。SyslogTarget もあります。AWS の SMS に送るなど、ユーザーが独自のターゲットを作ることもできます。

自動テスト時のロギング

このように、アプリケーションはどこでログを収集しているかわかりませんし、それぞれのログターゲットがどれだけ遅いか、あるいは何に依存するか、わかりません。けれど、自動テストは大量で多様な処理を何度も繰り返します。ログを(設定によっては非常に遅かったり、寝ているインフラ担当者を叩き起こしたりするような)ターゲットに送っていては大変です。

Yii の場合、ログを取るのにわざわざロガーが DI されるようにセットアップする必要がなく、Yii クラスのスタティックコールで何とかなるという手軽さもあって、ますます「このテスト対象コードはログを出力していないから大丈夫」とは言い切れません。

そもそも、テストにログが必要かというと、必要であってはならないですよね。調べたいことはすべてアサーションで挙げてあるべきです。テスト実行のログを拾ってなにか調べようとするのは、自動テストのそもそもの意味を間違っています。(ログから問題分析したいなら、自動テストではなくブラウザを開いたほうが早いですよね)

自動テストにログは要らない。だからって、ログ出力コードをいちいち if (YII_TEST) {} で囲みなさいと規約を設けるのは、ばかげています。(幾度と無くそのばかげたコードを見たことはありますが、はい) だいたい、フレームワーク内やサードパーティのコードにどうやって...

というわけで、ここで実際にどうなっているかを見ましょう。次のコードは Codeception のファンクショナルテストで使う Yii2 のコネクタです。実はすでに、そこにはログターゲットをすべて無効化する仕掛けが組み込まれています。

namespace Codeception\Lib\Connector;

class Yii2 extends Client
{
    public function doRequest($request)
    {
         // ...

         // disabling logging. Logs are slowing test execution down
         foreach ($app->log->targets as $target) {
              $target->enabled = false;
         }
         // ...
    }
}

ファンクショナルテストは、中身がどうなっているかわからないけど外から叩いてみるテストだ、というわけなので、「勝手なのはわかってるけど安全側に振っておきました」という配慮です。納得ですね。使うのは画面の結果(とストレージ)だけなんですから。

いっぽう、単体テストの場合はそんな枠組みで制御することができません。テスト対象が個別のクラスになるので、アプリケーションのブートをテスティングフレームワークが支配するというのは、ちょっと難しくなります。(できなくもないですが、現状の yii-2.0.1 リリースではそうなっていません) もし絶対ロギング禁止をやってしまうと、ロギングそのものをテストすることができなくなります(次節)。

ユニットテストでは、ユーザーの責任で Codeception のコネクタと同じことを施してやるべきです。たとえば、 tests/codeception/config/unit.php を次のようにし、アプリケーション設定にあるログターゲットをすべて無効にします。

<?php
$config = yii\helpers\ArrayHelper::merge(
    require(__DIR__ . '/../../config/web.php'), // アプリ設定
    require(__DIR__ . '/config.php') // テスト用の追加設定
);

// 追加ここから
foreach ($config['components']['log']['targets'] as &$target) {
    $target['enabled'] = false;
}

return $config;

これをデフォルトのユニットテスト用設定としておけば、明示的に復活させないかぎり、ログが実際の送り先に送られることはありません。

ロギングをユニットテストしたい

特別に一部、ログが残ったかテストしたいんだという場合もあるでしょう。そんなときは、カスタムなモックログターゲットを持つ設定を別途作成し、テストコードをこうします。

$config = require __DIR__ . '/unit.php';
$config['components']['log']['targets'][] = [
    'class' => 'app\utils\test\MockLogTarget',
    // ...
];
return $config;

<?php
namespace tests\codeception\unit;

use yii\codeception\TestCase;

class HogeTest extends TestCase
{
    // モックのログターゲットを持つ設定で Yii::$app スタブを初期化
    public $appConfig = '@tests/codeception/config/unit-with-mock-log-target.php';

    public function testFugaErrorLog()
    {
        // なにかエラーログが出るようなことをする
        Yii::getLogger()->flush(true); // リクエスト終了時のflushに相当

        $this->specify('ログが出力されるべき', function() use($model) {
            // モックログターゲットの送り先を調べる
        });
    }

    protected function tearDown()
    {
        Yii::getLogger()->flush(true); // 念のためゴミは全て吐いておく
        parent::tearDown();
    }
}

実は Yii 2.0.1 には、ユニットテスト中に flush(true) して Logger のバッファを空にしておかないと、プロセス終了時のフラッシュでターゲットに送ろうとして Yii::$app を参照してしまい、そこでヌルポが出てしまうという不具合があります。tearDown() のゴミ吐きはそのためです。

プルリクエストを送ってわかったのですが、現在 Yii2 プロジェクトの issue では、自動テストでのログの必要性についてよく議論されているようです。この記事のような意識がないと、ロギングといえば単にファイルに書き出すだけだろう、自動テストのエビデンスにいいじゃないか、的な考えを持つ人も多いのではないかと思いました。

これは事前にひとこと言っておかなきゃ、というわけでまとめました。大部分は一般論です。Yii にかぎらず、自動テストではまずログを切るのが当たり前、というところから議論したいですね。