Create 'maproulette-request-id' for http requests (#1088)

MapRoulette will log requests to an access log appender and include a generated 'maproulette-request-id' to help identify buggy requests. The requestId is added as a response header so that clients can include the request id when creating issues for a particular request.
maproulette · Nov 30, 2023 · e60c9ce · e60c9ce
1 parent 4c94f34
commit e60c9ce
Show file tree

Hide file tree

Showing 6 changed files with 96 additions and 61 deletions.
diff --git a/app/org/maproulette/filters/Filters.scala b/app/org/maproulette/filters/Filters.scala
@@ -12,5 +12,8 @@ import play.filters.gzip.GzipFilter
 /**
   * @author cuthbertm
   */
-class Filters @Inject() (corsFilter: CORSFilter, gzipFilter: GzipFilter)
-    extends DefaultHttpFilters(corsFilter, gzipFilter)
+class Filters @Inject() (
+    corsFilter: CORSFilter,
+    gzipFilter: GzipFilter,
+    httpLoggingFilter: HttpLoggingFilter
+) extends DefaultHttpFilters(corsFilter, gzipFilter, httpLoggingFilter)
diff --git a/app/org/maproulette/filters/HttpLoggingFilter.scala b/app/org/maproulette/filters/HttpLoggingFilter.scala
@@ -2,56 +2,63 @@ package org.maproulette.filters
 
 import javax.inject.Inject
 import akka.stream.Materializer
-import org.maproulette.filters.HttpLoggingFilter.logger
-import org.slf4j.LoggerFactory
+import org.slf4j.{LoggerFactory, MarkerFactory}
 import play.api.mvc.Result
 import play.api.mvc.RequestHeader
 import play.api.mvc.Filter
-import play.api.routing.HandlerDef
 import play.api.routing.Router
 
 import scala.concurrent.Future
 import scala.concurrent.ExecutionContext
 
 /**
-  * Filter to provide an http request log at the service side. The HttpLoggingFilter is enabled by default within
-  * application.conf but will create no output until logback is set to the debug or trace levels.
+  * Filter to provide an http request log at the service side.
   */
-class HttpLoggingFilter @Inject() (implicit val mat: Materializer, ec: ExecutionContext)
-    extends Filter {
+class HttpLoggingFilter @Inject() (
+    implicit val mat: Materializer,
+    implicit val ec: ExecutionContext
+) extends Filter {
+  private val logger       = LoggerFactory.getLogger(getClass.getName)
+  private val accessLogger = LoggerFactory.getLogger("AccessLogger")
+
   def apply(
       nextFilter: RequestHeader => Future[Result]
   )(requestHeader: RequestHeader): Future[Result] = {
     val startTime = System.currentTimeMillis
+    // Create a uuid and associate it with a Marker
+    val uuid   = java.util.UUID.randomUUID.toString
+    val marker = MarkerFactory.getMarker(uuid)
 
     nextFilter(requestHeader).map { result =>
-      val handlerDef: HandlerDef = requestHeader.attrs(Router.Attrs.HandlerDef)
-      val action                 = handlerDef.controller + "." + handlerDef.method
-      val endTime                = System.currentTimeMillis
-      val requestTime            = endTime - startTime
-
-      logger.debug(
-        "id={} {}: '{}' took {}ms and returned {}",
-        requestHeader.id,
-        action,
+      val endTime          = System.currentTimeMillis
+      val requestTotalTime = endTime - startTime
+      val handlerDef       = requestHeader.attrs.get(Router.Attrs.HandlerDef)
+      val action = handlerDef match {
+        case Some(hd) => hd.controller + "." + hd.method
+        case None     => "unknown"
+      }
+
+      accessLogger.info(
+        marker,
+        "Request '{}' [{}] {}ms - Response {}",
         requestHeader.toString(),
-        requestTime,
+        action,
+        requestTotalTime,
         result.header.status
       )
 
-      logger.trace(
-        "id={} Request Headers: {}",
-        requestHeader.id,
-        requestHeader.headers.headers
-          .map({ case (k, v) => s"${k}=${v}" })
-          .mkString("  ;; ")
-      )
+      if (logger.isTraceEnabled()) {
+        logger.trace(
+          marker,
+          "id={} Request Headers: {}",
+          requestHeader.id,
+          requestHeader.headers.headers
+            .map({ case (k, v) => s"${k}=${v}" })
+            .mkString("  ;; ")
+        )
+      }
 
-      result
+      result.withHeaders("maproulette-request-id" -> uuid)
     }
   }
 }
-
-object HttpLoggingFilter {
-  private val logger = LoggerFactory.getLogger(getClass.getName)
-}
diff --git a/conf/application.conf b/conf/application.conf
@@ -339,17 +339,4 @@ osm {
 # You can disable evolutions if needed
 # evolutionplugin=disabled
 
-# Logger
-# ~~~~~
-# You can also configure logback (https://logback.qos.ch/),
-# by providing an application-logger.xml file in the conf directory.
-
-# Root logger:
-#logger.root=ERROR
-
-# Logger used by the framework:
-#logger.play=INFO
-
-# Logger provided to your application:
-#logger.application=DEBUG
 api.version="2.0"
diff --git a/conf/dev.conf.example b/conf/dev.conf.example
@@ -1,12 +1,5 @@
 include "application.conf"
 
-# Change logging levels to see more interesting things while developing.
-logger {
-  root=DEBUG
-  play=TRACE
-  application=TRACE
-}
-
 db.default {
   url="jdbc:postgresql://localhost:5432/mp_dev"
   url=${?MR_DATABASE_URL}

diff --git a/conf/logback-dev.xml b/conf/logback-dev.xml
@@ -3,11 +3,32 @@
 
     <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
         <encoder>
-            <Pattern>%date{"HH:mm:ss,SSS"} %coloredLevel [%thread] %class{15}.%M\(%file:%line\) - %message%n%xException</Pattern>
+            <Pattern>%date{"HH:mm:ss.SSS"} %coloredLevel[%marker][%thread] %logger{15}.%M\(%file:%line\) - %message%n%xException</Pattern>
         </encoder>
         <includeCallerData>true</includeCallerData>
     </appender>
 
+    <!-- Appender for general logs. This will drop TRACE/DEBUG/INFO logs when the queue fills. -->
+    <appender name="ASYNC_GENERAL" class="ch.qos.logback.classic.AsyncAppender">
+        <appender-ref ref="STDOUT" />
+        <queueSize>256</queueSize>
+        <discardingThreshold>0</discardingThreshold>
+        <includeCallerData>true</includeCallerData>
+    </appender>
+
+    <!-- Appender for Access Logs, set to not drop TRACE/DEBUG/INFO logs when the queue fills -->
+    <appender name="ASYNC_ACCESS" class="ch.qos.logback.classic.AsyncAppender">
+        <appender-ref ref="STDOUT" />
+        <queueSize>512</queueSize>
+        <discardingThreshold>0</discardingThreshold>
+        <includeCallerData>true</includeCallerData>
+    </appender>
+
+    <!-- Logger for Access Logs written by HttpLoggingFilter -->
+    <logger name="AccessLogger" level="INFO" additivity="false">
+        <appender-ref ref="ASYNC_ACCESS" />
+    </logger>
+
     <logger name="org.maproulette" level="DEBUG" />
 
     <!-- Set this to TRACE to see the client's provided HTTP request headers -->
@@ -19,20 +40,19 @@
 
     <!-- Use DEBUG for play to see useful information and the HTTP requests to overpass. At TRACE level it dumps tcp transactions, so avoid trace level. -->
     <logger name="play" level="DEBUG" />
+    <!-- Playframework database evolutions, DEBUG will log the SQL statements executed by evolutions -->
+    <logger name="play.api.db.evolutions" level="DEBUG" />
     <!-- Use TRACE for play.api.mvc to see what is happening with the HTTP requests to the backend -->
-    <logger name="play.api.mvc" level="TRACE" />
+    <logger name="play.api.mvc" level="INFO" />
 
     <!-- More akka logging tweaks can be made in the dev.conf, akka.actor.debug -->
     <logger name="akka" level="INFO" />
 
-    <!-- Playframework database evolutions, DEBUG will log the SQL statements executed by evolutions -->
-    <logger name="play.api.db.evolutions" level="DEBUG" />
-
     <!-- Unknown if these actually do anything -->
     <logger name="application" level="TRACE" />
     <logger name="controllers" level="TRACE" />
 
     <root level="INFO">
-        <appender-ref ref="STDOUT" />
+        <appender-ref ref="ASYNC_GENERAL" />
     </root>
 </configuration>
diff --git a/conf/logback.xml b/conf/logback.xml
@@ -1,12 +1,37 @@
-<configuration>
+<configuration debug="true" scan="true" scanPeriod="5 seconds">
     <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
-        <!-- encoders are assigned the type
-             ch.qos.logback.classic.encoder.PatternLayoutEncoder by default -->
         <encoder>
             <pattern>%d{HH:mm:ss.SSS} [%thread] %-5level %logger{36} - %msg%n</pattern>
         </encoder>
+        <encoder>
+            <pattern>%date{"HH:mm:ss.SSS"} %-5level [%marker][%thread][%logger{36}] - %message%n</pattern>
+        </encoder>
     </appender>
-    <root level="INFO">
+
+    <!-- Appender for general logs. This will drop TRACE/DEBUG/INFO logs when the queue fills. -->
+    <appender name="ASYNC_GENERAL" class="ch.qos.logback.classic.AsyncAppender">
         <appender-ref ref="STDOUT" />
+       <queueSize>256</queueSize>
+        <discardingThreshold>0</discardingThreshold>
+    </appender>
+
+    <!-- Appender for Access Logs, set to not drop TRACE/DEBUG/INFO logs when the queue fills -->
+    <appender name="ASYNC_ACCESS" class="ch.qos.logback.classic.AsyncAppender">
+        <appender-ref ref="STDOUT" />
+        <queueSize>512</queueSize>
+        <discardingThreshold>0</discardingThreshold>
+    </appender>
+
+    <!-- Logger for Access Logs written by HttpLoggingFilter -->
+    <logger name="AccessLogger" level="INFO" additivity="false">
+        <appender-ref ref="ASYNC_ACCESS" />
+    </logger>
+
+    <logger name="play" level="WARN" />
+    <!-- More akka logging tweaks can be made in the dev.conf, akka.actor.debug -->
+    <logger name="akka" level="WARN" />
+
+    <root level="INFO">
+        <appender-ref ref="ASYNC_GENERAL" />
     </root>
 </configuration>