Play Frameworkで横断的なログを出力する


WebアプリケーションやAPIサーバーを作成する際に、アクセスログなどの横断的なログを出力するシーンがあるかと思います。これらのログをPlay Frameworkではどのように実現するか紹介します。

## はじめに
以下にログ出力する4つの方法を紹介しますが、出力内容に応じて使い分ける必要があるので表に示します。

|||||
|:---:|:---:|:---:|:---:|
|||ほとんどのリクエストでログ出力する？||
|||Yes|No|
|Request bodyもログ出力する？|Yes|EssentialFilter|複数BodyParser + ActionFilter|
||No|Filter|ActionFilter|

また、サンプルコード全体は以下のリポジトリにあります。
https://github.com/satouso0401/play-logging-sample


## Filter

play.api.mvcのFilterを使ってログ出力処理を実装し、application.confのplay.filters.enabledで有効にします。path毎に出力の有無を切り替える必要のない場合におすすめの方法です。

参考: https://www.playframework.com/documentation/2.7.x/ScalaHttpFilters

### サンプルコード

```scala:LoggingFilter.scala
class LoggingFilter @Inject()(implicit val mat: Materializer, ec: ExecutionContext) extends Filter {

  val logger: Logger = Logger(this.getClass)

  def apply(nextFilter: RequestHeader => Future[Result])(requestHeader: RequestHeader): Future[Result] = {

    val startTime = System.currentTimeMillis

    nextFilter(requestHeader).map { result =>
      val endTime     = System.currentTimeMillis
      val requestTime = endTime - startTime

      if (requestHeader.uri == "/filter-log" && result.header.status != 200) {
        logger.info(
          s"method:${requestHeader.method}, url:${requestHeader.uri}, status:${result.header.status}, took:${requestTime}ms, headers:${requestHeader.headers.toSimpleMap}")
      }

      result
    }
  }
}
```

### 利点
- 設定ファイルで有効、無効を切り替えられる
- レスポンスのステータスコードを参照して出力内容を変更できる

### 欠点
- Request bodyにアクセスできない

### 出力可能な情報
- Request header 全般(method, path, cookie等)
- Request query string
- Response header 全般
- Response body


## EssentialFilter

Filterの継承元であるEssentialFilterを利用する事で、Filterではアクセスする事のできなかったRequest bodyにもアクセスできるようにする方法です。Filterの場合と同様に、application.confのplay.filters.enabledで有効にします。

参考: https://www.playframework.com/documentation/2.7.x/ScalaHttpFilters#More-powerful-filters

### サンプルコード

```scala:LoggingEssentialFilter.scala
class LoggingEssentialFilter @Inject()(actorSystem: ActorSystem)(implicit ec: ExecutionContext) extends EssentialFilter {

  private val logger           = org.slf4j.LoggerFactory.getLogger(this.getClass)
  private implicit val logging = Logging(actorSystem.eventStream, logger.getName)

  override def apply(next: EssentialAction): EssentialAction = new EssentialAction {
    override def apply(request: RequestHeader): Accumulator[ByteString, Result] = {
      val accumulator: Accumulator[ByteString, Result] = next(request)

      val flow: Flow[ByteString, ByteString, NotUsed] = Flow[ByteString].log("byteflow")
      val sink =
        Sink.foreach[ByteString](x =>
          if (request.path == "/essential-filter-log") {
            logger.info(s"method:${request.method}, url:${request.uri}, body:${x.utf8String}")
        })

      def logGraph() = {
        Flow.fromGraph(
          GraphDSL.create() { implicit builder =>
            import GraphDSL.Implicits._
            val bcast = builder.add(Broadcast[ByteString](2, eagerCancel = false))
            bcast.out(1) ~> flow ~> sink
            FlowShape(bcast.in, bcast.out(0))
          }
        )
      }

      val accumulatorWithResult: Accumulator[ByteString, Result] =
        accumulator.through(logGraph()).map { result =>
          logger.info(s"method:${request.method}, url:${request.uri}, status:${result.header.status}")
          result
        }

      accumulatorWithResult
    }
  }
}
```

### 利点
- 設定ファイルで有効、無効を切り替えられる
- Request bodyにアクセスできる

### 欠点
- Responseのステータスに応じてログの出し分けが制御できない
- ログ出力処理を実装する際にPlayがバックエンドに使用しているAkka Streams知識が必要

### 出力可能な情報
- Request header 全般(method, path, cookie等)
- Request query string
- Requset body
- Filterを利用した場合と同様の、Response header、body ただし、__Request bodyとは同時には出力できない__




## ActionFilter

Actions composition を使った方法です。ActionFilterを実装して、ログが必要なAction毎にandThenで処理を追加します。一部のActionにのみログ出力が必要な場合におすすめの方法です。

以下のサンプルコードではActionFilterとしてログ出力処理を実装していますが、横断的にログが必要な場合はActionBuilderで独自のActionを作成して同様のロギング処理を追加して、そちらを使うようにしてもよいかもしれません。詳しくは参考のurlを参照してください。

参考: https://www.playframework.com/documentation/2.7.x/ScalaActionsComposition

### サンプルコード

```scala:JsonLoggingActionFilter.scala
class JsonLoggingActionFilter @Inject()(implicit ec: ExecutionContext) extends ActionFilter[Request] {

  val logger: Logger = Logger(this.getClass)

  def executionContext = ec
  def filter[A](input: Request[A]) = Future.successful {
    input.body match {
      case x: JsObject => logger.info(s"path: ${input.path}, body: ${x.toString()}")
      case _           =>
    }
    None
  }
}
```

```scala:SampleController.scala
@Singleton
class SampleController @Inject()(
    cc: ControllerComponents,
    jsonLogging: JsonLoggingActionFilter
) extends AbstractController(cc) {

  def actionFilterLog() = (Action(parse.json) andThen jsonLogging) { implicit request: Request[JsValue] =>
    request.body.validate[SampleRequestBody] match {
      case _: JsSuccess[SampleRequestBody] => Ok(Json.toJson(Map("status"         -> "OK")))
      case _: JsError                      => BadRequest(Json.toJson(Map("status" -> "Error")))
    }
  }
}
```


### 利点
- Action毎にロギング処理を差し込むかどうかを指定できる
- Request bodyには直接アクセスできないもののbodyのparse後の情報を参照できる

### 欠点
- Responseのステータスに応じてログの出し分けが制御できない
- ActionのBodyParserにcase classなどの具体的な型を指定してparseするスタイルの場合、共通化しにくくまたログ用に文字列に戻す処理に無駄がある

### 出力可能な情報
- Request header 全般(method, path, cookie等)
- Request query string
- Requset bodyのparse後のオブジェクト


## 複数BodyParser + ActionFilter

上記のActionFilterを使った方法に [Play の BodyParser を組み合わせる](https://qiita.com/kawachi/items/0fae7b3ee984f965b783) で紹介されている複数のBodyParserを利用する方法を組み合わせて、ActionFilterだけを使う場合の「bodyそのものはロギング出来ない」、「具体的な型にparseするとうまくいかない」といった問題を解決する方法です。

### サンプルコード

```scala:RawBufferLoggingActionFilter.scala
class RawBufferLoggingActionFilter @Inject()(implicit ec: ExecutionContext) extends ActionFilter[Request] {

  val logger: Logger = Logger(this.getClass)

  def executionContext = ec
  def filter[A](input: Request[A]) = Future.successful {
    input.body match {
      case (_, x: RawBuffer) =>
        logger.info(s"path: ${input.path}, body: ${x.asBytes().get.utf8String}")
      case _ =>
    }
    None
  }
}
```

```scala:SampleController.scala
@Singleton
class SampleController @Inject()(
    cc: ControllerComponents,
    rawBuffLogging: RawBufferLoggingActionFilter
) extends AbstractController(cc) {

  def actionFilterLog2() = (Action(parse.json[SampleRequestBody] and parse.raw) andThen rawBuffLogging) { implicit request =>
    Ok(Json.toJson(Map("status" -> s"OK ${request.body._1.key1}")))
  }
}
```

### 利点
- Action毎にロギング処理を差し込むかどうかを指定できる
- Request bodyにアクセスできる

### 欠点
- Responseのステータスに応じてログの出し分けが制御できない
- ログ出力処理を実装する際にPlayがバックエンドに使用しているAkka Streams知識が必要

### 出力可能な情報
- Request header 全般(method, path, cookie等)
- Request query string
- Requset body