Add request-logging filter (#10)

.scalafmt.conf

@@ -1,6 +1,6 @@
 version = 3.7.17
 runner.dialect = scala3
 
-maxColumn = 100
+maxColumn = 120
 
 rewrite.trailingCommas.style = keep

app/controllers/HealthCheckController.scala

@@ -5,5 +5,5 @@ import play.api.mvc.*
 
 class HealthCheckController(val controllerComponents: ControllerComponents) extends BaseController {
 
-  def healthCheck(): Action[AnyContent] = Action(Ok)
+  def healthCheck(): Action[AnyContent] = Action(Ok("OK"))
 }

app/load/AppComponents.scala

@@ -1,6 +1,8 @@
 package load
 
+import logging.RequestLoggingFilter
 import play.api.ApplicationLoader.Context
+import play.api.mvc.EssentialFilter
 import play.api.{BuiltInComponentsFromContext, Configuration}
 import play.filters.HttpFiltersComponents
 import router.Routes
@@ -10,9 +12,7 @@ import software.amazon.awssdk.services.ssm.model.GetParameterRequest
 
 import scala.util.Using
 
-class AppComponents(context: Context)
-    extends BuiltInComponentsFromContext(context)
-    with HttpFiltersComponents {
+class AppComponents(context: Context) extends BuiltInComponentsFromContext(context) with HttpFiltersComponents {
 
   private val region = Region.EU_WEST_1
 
@@ -33,6 +33,9 @@ class AppComponents(context: Context)
       super.configuration
     else
       Configuration("play.http.secret.key" -> secretKey).withFallback(super.configuration)
+
+  override def httpFilters: Seq[EssentialFilter] = super.httpFilters :+ new RequestLoggingFilter(materializer)
+
   lazy val healthCheckController = new controllers.HealthCheckController(controllerComponents)
   lazy val router: Routes = new Routes(httpErrorHandler, healthCheckController)
 }

app/logging/LogEntry.scala

@@ -0,0 +1,47 @@
+package logging
+
+import play.api.http.HeaderNames.*
+import play.api.mvc.{RequestHeader, Result}
+
+case class LogEntry(message: String, otherFields: Map[String, Any])
+
+private[logging] object LogEntry {
+
+  private def commonFields(request: RequestHeader, duration: Long) =
+    Map(
+      "type" -> "access",
+      "origin" -> request.headers.get(X_FORWARDED_FOR).getOrElse(request.remoteAddress),
+      "referrer" -> request.headers.get(REFERER).getOrElse(""),
+      "method" -> request.method,
+      "duration" -> duration,
+      "protocol" -> request.version,
+      "requested_uri" -> request.uri,
+    )
+
+  def requestAndResponse(request: RequestHeader, response: Result, duration: Long): LogEntry = {
+    val fields = commonFields(request, duration) ++ Map(
+      "status" -> response.header.status,
+      "content_length" -> response.header.headers.getOrElse(CONTENT_LENGTH, 0),
+      "content_length" -> response.header.headers.get(CONTENT_LENGTH).map(_.toInt).getOrElse(0),
+    )
+    val message =
+      s"""${fields("origin")} -
+           |"${request.method} ${request.uri} ${request.version}"
+           |${response.header.status}
+           |${fields("content_length")}
+           |"${fields("referrer")}"
+           |${duration}ms""".stripMargin.replaceAll("\n", " ")
+    LogEntry(message, fields)
+  }
+
+  def error(request: RequestHeader, duration: Long): LogEntry = {
+    val fields = commonFields(request, duration)
+    val message =
+      s"""${fields("origin")} -
+           |"${request.method} ${request.uri} ${request.version}"
+           |ERROR
+           |"${fields("referrer")}"
+           |${duration}ms""".stripMargin.replaceAll("\n", " ")
+    LogEntry(message, fields)
+  }
+}

app/logging/RequestLoggingFilter.scala

@@ -0,0 +1,50 @@
+package logging
+
+import net.logstash.logback.marker.Markers.appendEntries
+import org.apache.pekko.stream.Materializer
+import play.api.mvc.{Filter, RequestHeader, Result}
+import play.api.{Logging, MarkerContext}
+
+import scala.concurrent.{ExecutionContext, Future}
+import scala.jdk.CollectionConverters.*
+import scala.util.{Failure, Success}
+
+/** Logs all requests and responses. Fields logged:
+  *   - type: always "access" to distinguish it from an app log entry
+  *   - origin: the IP address of the client
+  *   - referrer: the referrer header
+  *   - method: the HTTP method
+  *   - status: the HTTP status code
+  *   - duration: the duration of the request in milliseconds
+  *   - protocol: the HTTP protocol version
+  *   - requested_uri: the requested URI surprisingly
+  *   - content_length: the length of the response body
+  *   - message: summary for a successful request or error and stacktrace if request failed
+  *
+  * Largely stolen from
+  * https://github.com/guardian/cdk-playground/blob/02e91848c5c70f72c281a02a5f7107c6de0298d4/app/RequestLoggingFilter.scala
+  */
+class RequestLoggingFilter(override val mat: Materializer)(implicit ec: ExecutionContext) extends Filter with Logging {
+
+  override def apply(next: RequestHeader => Future[Result])(request: RequestHeader): Future[Result] = {
+    val start = System.currentTimeMillis()
+    val result = next(request)
+
+    def markerContext(logEntry: LogEntry) = MarkerContext(appendEntries(logEntry.otherFields.asJava))
+
+    result onComplete {
+      case Success(response) =>
+        val duration = System.currentTimeMillis() - start
+        val logEntry = LogEntry.requestAndResponse(request, response, duration)
+        logger.info(logEntry.message)(markerContext(logEntry))
+
+      case Failure(err) =>
+        val duration = System.currentTimeMillis() - start
+        val logEntry = LogEntry.error(request, duration)
+        logger.info(logEntry.message)(markerContext(logEntry))
+        logger.error(s"Error for ${request.method} ${request.uri}", err)
+    }
+
+    result
+  }
+}

build.sbt

@@ -16,6 +16,7 @@ lazy val root = (project in file("."))
     ),
     libraryDependencies ++= Seq(
       "software.amazon.awssdk" % "ssm" % "2.23.10",
+      "net.logstash.logback" % "logstash-logback-encoder" % "7.3",
       "org.scalatestplus.play" %% "scalatestplus-play" % "7.0.1" % Test,
     ),
   )

conf/logback.xml

@@ -1,44 +1,30 @@
-<?xml version="1.0" encoding="UTF-8" ?>
-
 <!-- https://www.playframework.com/documentation/latest/SettingsLogger -->
-
-<!DOCTYPE configuration>
-
 <configuration>
-  <import class="ch.qos.logback.classic.encoder.PatternLayoutEncoder"/>
-  <import class="ch.qos.logback.classic.AsyncAppender"/>
-  <import class="ch.qos.logback.core.FileAppender"/>
-  <import class="ch.qos.logback.core.ConsoleAppender"/>
-
-  <appender name="FILE" class="FileAppender">
-    <file>${application.home:-.}/logs/application.log</file>
-    <encoder class="PatternLayoutEncoder">
-      <charset>UTF-8</charset>
-      <pattern>%d{yyyy-MM-dd HH:mm:ss} %highlight(%-5level) %cyan(%logger{36}) %magenta(%X{pekkoSource}) %msg%n</pattern>
-    </encoder>
-  </appender>
-
-  <appender name="STDOUT" class="ConsoleAppender">
-    <encoder class="PatternLayoutEncoder">
-      <charset>UTF-8</charset>
-      <pattern>%d{yyyy-MM-dd HH:mm:ss} %highlight(%-5level) %cyan(%logger{36}) %magenta(%X{pekkoSource}) %msg%n</pattern>
-    </encoder>
-  </appender>
-
-  <appender name="ASYNCFILE" class="AsyncAppender">
-    <appender-ref ref="FILE"/>
-  </appender>
-
-  <appender name="ASYNCSTDOUT" class="AsyncAppender">
-    <appender-ref ref="STDOUT"/>
-  </appender>
-
-  <logger name="play" level="INFO"/>
-  <logger name="application" level="DEBUG"/>
 
-  <root level="WARN">
-    <appender-ref ref="ASYNCFILE"/>
-    <appender-ref ref="ASYNCSTDOUT"/>
-  </root>
+    <appender name="FILE" class="ch.qos.logback.core.FileAppender">
+        <file>${application.home:-.}/logs/application.log</file>
+        <encoder class="ch.qos.logback.classic.encoder.PatternLayoutEncoder">
+            <charset>UTF-8</charset>
+            <pattern>%d{yyyy-MM-dd HH:mm:ss} %highlight(%-5level) %cyan(%logger{36}) %magenta(%X{pekkoSource}) %msg%n
+            </pattern>
+        </encoder>
+    </appender>
+
+    <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
+        <encoder class="net.logstash.logback.encoder.LogstashEncoder"/>
+    </appender>
+
+    <appender name="ASYNCFILE" class="ch.qos.logback.classic.AsyncAppender">
+        <appender-ref ref="FILE"/>
+    </appender>
+
+    <appender name="ASYNCSTDOUT" class="ch.qos.logback.classic.AsyncAppender">
+        <appender-ref ref="STDOUT"/>
+    </appender>
+
+    <root level="INFO">
+        <appender-ref ref="ASYNCFILE"/>
+        <appender-ref ref="ASYNCSTDOUT"/>
+    </root>
 
 </configuration>

test/controllers/HealthCheckControllerSpec.scala

@@ -19,12 +19,16 @@ class HealthCheckControllerSpec extends PlaySpec with OneAppPerTestWithComponent
       val controller = new HealthCheckController(stubControllerComponents())
       val healthCheck = controller.healthCheck().apply(FakeRequest(GET, path))
       status(healthCheck) mustBe OK
+      contentType(healthCheck) mustBe Some("text/plain")
+      contentAsString(healthCheck) must be("OK")
     }
 
     "run health check from the router" in {
       val request = FakeRequest(GET, path)
       val healthCheck = route(app, request).get
       status(healthCheck) mustBe OK
+      contentType(healthCheck) mustBe Some("text/plain")
+      contentAsString(healthCheck) must be("OK")
     }
   }
 }

test/logging/LogEntrySpec.scala

@@ -0,0 +1,49 @@
+package logging
+
+import org.scalatestplus.play.*
+import play.api.mvc.Results.Ok
+import play.api.test.*
+import play.api.test.Helpers.*
+
+class LogEntrySpec extends PlaySpec {
+
+  "requestAndResponse" should {
+    val request = FakeRequest(GET, "/").withHeaders(REFERER -> "Referrer")
+    val entry = LogEntry.requestAndResponse(request, response = Ok.withHeaders(CONTENT_LENGTH -> "11"), duration = 7)
+    "give correct message" in {
+      entry.message mustBe """127.0.0.1 - "GET / HTTP/1.1" 200 11 "Referrer" 7ms"""
+    }
+    "give correct fields" in {
+      entry.otherFields mustBe Map(
+        "type" -> "access",
+        "origin" -> "127.0.0.1",
+        "referrer" -> "Referrer",
+        "method" -> "GET",
+        "status" -> 200,
+        "duration" -> 7,
+        "protocol" -> "HTTP/1.1",
+        "requested_uri" -> "/",
+        "content_length" -> 11
+      )
+    }
+  }
+
+  "error" should {
+    val request = FakeRequest(GET, "/").withHeaders(REFERER -> "Referrer")
+    val entry = LogEntry.error(request, duration = 17)
+    "give correct message" in {
+      entry.message mustBe """127.0.0.1 - "GET / HTTP/1.1" ERROR "Referrer" 17ms"""
+    }
+    "give correct fields" in {
+      entry.otherFields mustBe Map(
+        "type" -> "access",
+        "origin" -> "127.0.0.1",
+        "referrer" -> "Referrer",
+        "method" -> "GET",
+        "duration" -> 17,
+        "protocol" -> "HTTP/1.1",
+        "requested_uri" -> "/",
+      )
+    }
+  }
+}