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

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

サンプルコード

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

サンプルコード

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

サンプルコード

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
  }
}

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 を組み合わせるで紹介されている複数のBodyParserを利用する方法を組み合わせて、ActionFilterだけを使う場合の「bodyそのものはロギング出来ない」、「具体的な型にparseするとうまくいかない」といった問題を解決する方法です。

サンプルコード

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
  }
}

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