【JavaでPlayFramwork2.4.6】ログ出力とフィルター

株式会社ジェニシス　技術開発事業部の遠藤　太志郎(Tacy)です。

業務多忙により更新が停滞していましたが、再びPlayFrameworkの連載を復活します。

ログ出力

システムを構築する時に最初にどこから作っていくか、というところは個人の趣味があるところかと思いますが、私の場合はまずログ出力から固めていきます。
今回はログ出力についてご紹介します。

出力本体

PlayFrameworkのログ出力と銘打ってこんな記事を書いていますが、PlayFrameworkはJavaを内包していますから、早い話が単なるLog4jなんですよね。

• https://www.playframework.com/documentation/ja/2.4.x/SettingsLogger

PlayFrameworkの中には最初からLog4jが入っていますので、素直にコレを使えば良いかと。
log4jの標準に従ってlogback.xmlを設置すればその通りに動いてくれるようになります。

この辺りはPlayFrameworkの話ではなくlog4jそのままの話ですので、この記事でわざわざ記述するほどの話ではないかと。

今回はここから一歩踏み込みまして「リクエストの開始と終了のログ」を出力する方法に行ってみたいと思います。

ロギングフィルター

純粋なJavaのフレームワークであれば、リクエストの開始と終了は「doGet」とか「doPost」のメソッドの最初と終了にログを出力するようAbstractの親クラスを作るだけの話ですが、PlayFrameworkはそういう風に出来ていませんのでちょっとしたコツが必要になります。

そのテクニックを「フィルター」と言います。

• https://www.playframework.com/documentation/ja/2.1.x/ScalaHttpFilters

フィルターとは、前回でご紹介したGrobal.javaに適応するものでして、
全てのリクエストの開始時に呼び出される共通処理を提供する機能です。

使い方はGrobal.javaのメソッド「filters()」にフィルタークラスをセットするだけでＯＫです。

 /**
  * Get the filters that should be used to handle each request.
  */
 @Override
 public  Class[] filters() {

  Class[] clazz = new Class[1];
  clazz[0] = RequestLogFilter.class;

  return clazz;
 }

これで全てのリクエストの開始時に「RequestLogFilter」が呼び出されますので、そこにログ出力の処理を書けば良いわけですね。
ただし、Filterはscalaで書かなければなりません。

PlayFrameworkでJavaを選択したプロジェクトであってもFilterクラスはscalaのみなのでご注意を。

しかしですので、Filterというのは開始時に呼び出されるものであって、終了時には呼び出されません。
よって「リクエストの終了ログはどうやって出すの？」という問題が発生します。

これにつきましてもPlayFrameworkとscalaならではの機能で実現してくれます。

traitとインターセプター

以下が私が使用しているログフィルターです。

class RequestLogFilter extends EssentialFilter {

  def apply(nextFilter: EssentialAction) = new EssentialAction {

    def apply(requestHeader: RequestHeader) = {

      def isTarget = RequestLogFilterUtils.isLonningTarget(requestHeader.uri);

      val startTime = System.currentTimeMillis

      if (isTarget) {
        Logger.info(RequestLogFilterUtils.getStartLog(requestHeader.method, requestHeader.uri))
      }

      nextFilter(requestHeader).map { result =>

        val requestTime = System.currentTimeMillis - startTime

        if (isTarget) {
          Logger.info(RequestLogFilterUtils.getEndLog(requestHeader.method, requestHeader.uri, result.header.status, requestTime))
        }

        result.withHeaders("Request-Time" -> requestTime.toString)

      }

    }

  }

}

RequestLogFilterUtilsというのは、私はscalaが不見識ですので文字列加工機能部分だけJavaに切り出しているだけなので気にする必要はありません。
今回のポイントはこちら。

nextFilter(requestHeader).map { result =>

nextFilterです。

resultという単語が出ていることから察せられるとおり、この中身がリクエストの終了時に呼び出されることになります。

？？？？？

Javaエンジニアには意味不明な機構ですね。

これはscalaが搭載している「trait」という機能でして、Javaで言うところのインターフェースに近い性質を持つものです。
ただし、インターフェースほどカッチリとはしておらず、より柔軟性を持たせたものである模様。

ともかく、流れたとしては、

1. リクエストが来る。
2. リクエストをフィルターでインターセプト（傍受）する。
3. リクエストにフィルターで定義した機能を挟み込む。

こういうちょっとメタっぽい形でリクエストにフィルター機能を持たせます。

そして開始ログを提供するメイン部分は普通にそのまま実行。
終了ログ部分は「trait」を使って定義しておいて、リクエスト終了時に後から呼び出す（chainするように）ようにフィルターの親クラスである「EssentialFilter」が作られている、とこういう構図なようです。

むむ。
これはPlayFrameworkの中でもかなりscala寄りの部分なようですね。
本格的に理解を深めるにはscalaの勉強を深めなければならなさそうですが、この連載は「JavaでPlayFramwork」なので掘り下げはこの辺り留めたいと思います。

終わりに

引き続きPlayFrameworkの勉強を進めます。