Symfonyでloggerが呼ばれた箇所にPHPStormでファイルジャンプしやすくする

f:id:okapon_pon:20151205123050p:plain

この記事はSymfony Advent Calender 2016 23日目の記事です。

はじめに

今回はloggerについてのお話です。

何か不測の事態にそなえて logger で記録するということは、本番環境でアプリを運用していくにあたり取り組まれていると思います。

ただ、何かログが吐かれて「やばい調査しないと！」となった時に、ログのメッセージでgrepして、ファイル探して開いて、該当行探してっとなると結構面倒だったりします。

モチベーション

そのため今回のモチベーションは以下の通りです。

errorログが記録された(loggerが呼びだされた)箇所のコードを素早く調べたい
PHPStormで該当ファイル行を素早く開いて調査したい

f:id:okapon_pon:20161223215003p:plain

実はPHPStormのNavigationのfile検索は最後に「:行番行」と入れると該当行にジャンプすることができます。

なのでloggerで「呼び出し元のファイル名 +:番号」をログに出力するようにしれあげれば、ログをコピーしてPHPStormに入力してすぐ該当ファイルにアクセスできるわけです。

「Symfonyのloggerを呼んだ箇所にPHPStormでファイルジャンプしやすくする」という内容についての記事ですが、PsrLoggerInterfaceを実装したLoggerを利用したその他フレームワークでも利用可能なテクニックとなっていると思います。

やったこと

PsrLoggerInterfaceのメソッドであるerror()関数は第２引数にcontextという配列を受け取ることができます。

contextはloggerが呼び出されたときの状況を記録するために利用することができます。

(例)ユーザー情報の更新に失敗した場合のロギング

$this->error('Update failed', ['user_id' => $user->getId());

今回の場合はloggerに行番号付きでファイルパスを渡します。以下のイメージです。

$this->get('logger')->error('Error occurred!', ['caller' => 'path/to/SampleFile.php:100']);

loggerのメソッドが呼ばれた時に、この'caller' という情報がデフォルトで入るようにするのが今回の目的です。

ではどうやって呼び出し元を取得してくるか？

PHPには debug_backtrace() という関数があります。

PHP: debug_backtrace - Manual

<?php
function foo()
{
    $trace = debug_backtrace();
    var_dump($trace);
}
foo();

結果

/PhpstormProjects/test.php:5:
array(1) {
  [0] =>
  array(4) {
    'file' =>
    string(47) "/PhpstormProjects/test.php"
    'line' =>
    int(7)
    'function' =>
    string(3) "foo"
    'args' =>
    array(0) {
    }
  }
}

配列を見てみると呼び出し元のファイル名や行番号が配列に入っていることが分かります。これを利用して呼び出し元のファイル行数を取得します。

詳細は後で掲載するサンプルコードを参照ください。

どうやって実装するか

既にloggerを利用している箇所が沢山あるのであれば、別のメソッドを足した新しいクラスを作るという選択肢はないでしょう。PsrLoggeerInterfaceを損なわない形でloggerクラスを差し替えたいところです。

幸いLoggerについてはPSR-3にて PsrLoggerInterfaceが定められており、十分安定したInterfaceであると考えられるのでこれに従うのが筋がいいと考えられるます。

１番思いつきそうな実装方法はサブクラスを作る方法

Interfaceの変更さえなければ既にloggerを利用している箇所も問題なく動きます。

悪くはないと思いますが、継承という手段を用いる以上親クラスの実装が置き換わったりすると壊れる可能性はあると思います。 (Loggerだとあまりないとは思いますが…)

そこでデコレータ

デコレータパターンはGoFのデザインパターンの一つで、既存のインターフェースを変更することなくクラスに機能追加することができるようにする設計パターンです。

個人的にとても好きなデザインパターンの１つです。

今回やりたいことはloggerの機能はそのままで「'caller'という呼び出し元の付加情報をデフォルトで付与する」という機能の追加になります。デコレーターパターンを使うのに向いているのではないでしょうか。

実装方法

実はSymfonyのDIには既存のServiceクラスをお手軽にデコレートする方法が提供されています。

http://symfony.com/doc/current/service_container/service_decoration.html

今回はloggerを置き換えてやればよいので以下の様な設定となります。

  app.traceable_logger:
    class: AppBundle\Logging\TraceableLogger
    decorates: logger
    arguments:
      - "@app.traceable_logger.inner"
      - "%kernel.root_dir%"

decorates オプションを指定することで元のlogger サービスを app.traceable_logger でデコレートすることをDIコンテナに伝えることができます。その際元の logger サービスは @app.traceable_logger.inner としてリネームされ、引き続きコンテナ内に残り続けます。

今回は元のloggerを利用したいのでargumentsで@app.traceable_logger.inner を渡してあげます。

肝心のTraceableLoggerクラスですがPsr/Log/LoggerInterfaceと SymfonyのDebugLoggerInterfaceを実装します。

Symfonyの場合loggerの実体はSymfony\Bridge\Monolog\Logger なので、DebugLoggerInterface も実装してあげた方が良いでしょう。

コードは以下の通りとなります。

<?php

namespace AppBundle\Logging;

use Psr\Log\LoggerInterface;
use Symfony\Component\HttpKernel\Log\DebugLoggerInterface;

class TraceableLogger implements LoggerInterface, DebugLoggerInterface
{
    const NUM_OF_TRACE = 1;

    /**
     * @var LoggerInterface
     */
    private $logger;
    private $projectRootDir;

    /**
     * @param LoggerInterface $logger
     * @param string $kernelRootDir
     */
    public function __construct(LoggerInterface $logger, $kernelRootDir)
    {
        $this->logger = $logger;
        $this->projectRootDir = realpath($kernelRootDir . '/../');
    }

    /**
     * {@inheritdoc}
     */
    public function emergency($message, array $context = [])
    {
        $context['caller'] = $this->getCallerPath();
        $this->logger->emergency($message, $context);
    }

    /**
     * {@inheritdoc}
     */
    public function alert($message, array $context = [])
    {
        $context['caller'] = $this->getCallerPath();
        $this->logger->alert($message, $context);
    }

    /**
     * {@inheritdoc}
     */
    public function critical($message, array $context = [])
    {
        $context['caller'] = $this->getCallerPath();
        $this->logger->critical($message, $context);
    }

    /**
     * {@inheritdoc}
     */
    public function error($message, array $context = [])
    {
        $context['caller'] = $this->getCallerPath();
        $this->logger->error($message, $context);
    }

    /**
     * {@inheritdoc}
     */
    public function warning($message, array $context = [])
    {
        $context['caller'] = $this->getCallerPath();
        $this->logger->warning($message, $context);
    }

    /**
     * {@inheritdoc}
     */
    public function notice($message, array $context = [])
    {
        $context['caller'] = $this->getCallerPath();
        $this->logger->notice($message, $context);
    }

    /**
     * {@inheritdoc}
     */
    public function info($message, array $context = [])
    {
        $context['caller'] = $this->getCallerPath();
        $this->logger->info($message, $context);
    }

    /**
     * {@inheritdoc}
     */
    public function debug($message, array $context = [])
    {
        $context['caller'] = $this->getCallerPath();
        $this->logger->debug($message, $context);
    }

    /**
     * {@inheritdoc}
     */
    public function log($level, $message, array $context = [])
    {
        $context['caller'] = $this->getCallerPath();
        $this->logger->log($level, $message, $context);
    }

    /**
     * {@inheritdoc}
     */
    public function getLogs()
    {
        if ($this->logger instanceof DebugLoggerInterface) {
            return $this->logger->getLogs();
        }

        return [];
    }

    /**
     * {@inheritdoc}
     */
    public function countErrors()
    {
        if ($this->logger instanceof DebugLoggerInterface) {
            return $this->logger->countErrors();
        }

        return 0;
    }

    /**
     * @return string
     */
    private function getCallerPath()
    {
        $trace = debug_backtrace();
        $callerInfo = $trace[self::NUM_OF_TRACE];
        if($callerInfo['file'] && $callerInfo['line']) {
            // project root 以下のパスで返す
            return $this->normalizePath($callerInfo['file']) . ':' . $callerInfo['line'];
        }

        return '';
    }

    private function normalizePath($realPath)
    {
        return str_replace($this->projectRootDir . '/', '', $realPath);
    }
}

LoggerInterfaceには、emergency, alert, critical… etc. と沢山のメソッドがあり、デコレートしなければならないメソッドが多いのはちょっとあれですが…

実際に呼び出し元のファイルパスを取得しているのは getCallerPath() メソッドの部分になります。

少し工夫している点としてdebug_backtrace()で得られるファイルパスは絶対パスのためそれをプロジェクトルート起点のパスに変更しています。

絶対パスはproduction環境とdevelop環境で異なるでしょうし、PHPStormの検索ではプロジェクトルート以下のパスで十分です。

実際に動かしてみると以下のようなlogが得られます。

f:id:okapon_pon:20161224024356p:plain

ファイル検索を実際にしてみると、該当行に直接ジャンプすることができました。

f:id:okapon_pon:20161224025959p:plain

このようにしてデコレーターを活用してあげると既存の機能も損なわず、またコードの利用側にも影響を与えることなく機能追加をすることができます。

デコレーターパターンはインターフェースのパワーを利用した素晴らしい設計手法ですね。

まとめ

PHPStormではファイル名の後に「:行番号」でファイルの該当行にジャンプすることができる
呼び出し元ファイルは debug_backtrace() で取得できる
SymfonyのDIにはDecorate 機能が用意されており、既存のサービスクラスを簡単に拡張することができる

今回は呼び出し元のファイルパスを取得して、それをloggerのcontextに付加情報として追加するという内容でした。

他にもloggerで常にアクセス元のURLを出すようにしたり、ログインユーザーのIDを出したりとかも簡単に実装できますね。

余談

余談ですが、Symfony フレームワーク内ではデコレーターが普通に利用されています。

ControllerResolverはdev環境で動かした場合にはTraceableControllerResolverによってデコレートされ、コントローラがresolveされるまでの時間を計測する機能が追加されています。

【参考】

https://github.com/symfony/symfony/blob/5129c4cf7e294b1a5ea30d6fec6e89b75396dcd2/src/Symfony/Component/HttpKernel/Controller/TraceableControllerResolver.php#L58

計測結果はプロファイラーでパフォーマンスとして見ることができます。

プログラミング - THIS IS IT !

より良い開発をすべく日々奮闘しているプログラマーのブログです。設計に興味があります。主にPHPネタを書いてます日本Symfonyユーザー会