Request tracing and audit loggingv0.9.7

4 files changed, 54 insertions, 44 deletions

diff --git a/src/main/scala/xyz/driver/core/app.scala b/src/main/scala/xyz/driver/core/app.scala
index e080e1b..8f892e8 100644
--- a/src/main/scala/xyz/driver/core/app.scala
+++ b/src/main/scala/xyz/driver/core/app.scala
@@ -7,12 +7,13 @@ import akka.http.scaladsl.model.StatusCodes._
 import akka.http.scaladsl.model.{HttpResponse, StatusCodes}
 import akka.http.scaladsl.server.Directives._
 import akka.http.scaladsl.server.RouteResult._
-import akka.http.scaladsl.server.{ExceptionHandler, Route, RouteConcatenation}
+import akka.http.scaladsl.server.{ExceptionHandler, RequestContext, Route, RouteConcatenation}
 import akka.stream.ActorMaterializer
 import com.typesafe.config.Config
 import org.slf4j.LoggerFactory
 import spray.json.DefaultJsonProtocol
 import xyz.driver.core
+import xyz.driver.core.auth.AuthService
 import xyz.driver.core.logging.{Logger, TypesafeScalaLogger}
 import xyz.driver.core.rest.Swagger
 import xyz.driver.core.stats.SystemStats
@@ -63,48 +64,51 @@ object app {
       val swaggerRoutes  = swaggerService.routes ~ swaggerService.swaggerUI
       val versionRt      = versionRoute(version, gitHash, time.currentTime())
 
-      val generalExceptionHandler = ExceptionHandler {
-
-        case is: IllegalStateException =>
-          extractUri { uri =>
-            // TODO: extract `requestUuid` from request or thread, provided by linkerd/zipkin
-            def requestUuid = java.util.UUID.randomUUID.toString
-
-            log.debug(s"Request is not allowed to $uri ($requestUuid)", is)
-            complete(
-              HttpResponse(BadRequest,
-                           entity = s"""{ "requestUuid": "$requestUuid", "message": "${is.getMessage}" }"""))
-          }
-
-        case cm: ConcurrentModificationException =>
-          extractUri { uri =>
-            // TODO: extract `requestUuid` from request or thread, provided by linkerd/zipkin
-            def requestUuid = java.util.UUID.randomUUID.toString
-
-            log.debug(s"Concurrent modification of the resource $uri ($requestUuid)", cm)
-            complete(
-              HttpResponse(Conflict, entity = s"""{ "requestUuid": "$requestUuid", "message": "${cm.getMessage}" }"""))
-          }
-
-        case t: Throwable =>
-          extractUri { uri =>
-            // TODO: extract `requestUuid` from request or thread, provided by linkerd/zipkin
-            def requestUuid = java.util.UUID.randomUUID.toString
-
-            log.error(s"Request to $uri could not be handled normally ($requestUuid)", t)
-            complete(
-              HttpResponse(InternalServerError,
-                           entity = s"""{ "requestUuid": "$requestUuid", "message": "${t.getMessage}" }"""))
-          }
-      }
-
       val _ = Future {
-        http.bindAndHandle(route2HandlerFlow(handleExceptions(generalExceptionHandler) {
-          logRequestResult("log")(modules.map(_.route).foldLeft(versionRt ~ healthRoute ~ swaggerRoutes)(_ ~ _))
+        http.bindAndHandle(route2HandlerFlow(handleExceptions(exceptionHandler) { ctx =>
+          log.audit(s"Received request ${ctx.request}")
+          modules.map(_.route).foldLeft(versionRt ~ healthRoute ~ swaggerRoutes)(_ ~ _)(ctx)
         }), interface, port)(materializer)
       }
     }
 
+    protected def extractTrackingId(ctx: RequestContext) = {
+      ctx.request.headers
+        .find(_.name == AuthService.TrackingIdHeader)
+        .map(_.value())
+        .getOrElse(java.util.UUID.randomUUID.toString)
+      // TODO: In the case when absent, should be taken the same generated id, as in `authorize`
+    }
+
+    protected def exceptionHandler = ExceptionHandler {
+
+      case is: IllegalStateException =>
+        ctx =>
+          val trackingId = extractTrackingId(ctx)
+          log.debug(s"Request is not allowed to ${ctx.request.uri} ($trackingId)", is)
+          complete(
+            HttpResponse(BadRequest, entity = s"""{ "trackingId": "$trackingId", "message": "${is.getMessage}" }"""))(
+            ctx)
+
+      case cm: ConcurrentModificationException =>
+        ctx =>
+          val trackingId                    = extractTrackingId(ctx)
+          val concurrentModificationMessage = "Resource was changed concurrently, try requesting a newer version"
+          log.audit(s"Concurrent modification of the resource ${ctx.request.uri} ($trackingId)", cm)
+          complete(
+            HttpResponse(
+              Conflict,
+              entity = s"""{ "trackingId": "$trackingId", "message": "$concurrentModificationMessage" }"""))(ctx)
+
+      case t: Throwable =>
+        ctx =>
+          val trackingId = extractTrackingId(ctx)
+          log.error(s"Request to ${ctx.request.uri} could not be handled normally ($trackingId)", t)
+          complete(
+            HttpResponse(InternalServerError,
+                         entity = s"""{ "trackingId": "$trackingId", "message": "${t.getMessage}" }"""))(ctx)
+    }
+
     protected def versionRoute(version: String, gitHash: String, startupTime: Time): Route = {
       import DefaultJsonProtocol._
       import SprayJsonSupport._
diff --git a/src/main/scala/xyz/driver/core/auth.scala b/src/main/scala/xyz/driver/core/auth.scala
index 874f1e1..17f89c0 100644
--- a/src/main/scala/xyz/driver/core/auth.scala
+++ b/src/main/scala/xyz/driver/core/auth.scala
@@ -72,12 +72,13 @@ object auth {
 
   final case class Base64[T](value: String)
 
-  final case class AuthToken(value: Base64[Macaroon])
+  final case class AuthToken(value: Base64[Macaroon], trackingId: String)
 
   final case class PasswordHash(value: String)
 
   object AuthService {
     val AuthenticationTokenHeader = "WWW-Authenticate"
+    val TrackingIdHeader          = "l5d-ctx-trace" // https://linkerd.io/doc/0.7.4/linkerd/protocol-http/
   }
 
   trait AuthService[U <: User] {
@@ -90,16 +91,20 @@ object auth {
     def authorize(permissions: Permission*): Directive1[(AuthToken, U)] = {
       parameters('authToken.?).flatMap { parameterTokenValue =>
         optionalHeaderValueByName(AuthService.AuthenticationTokenHeader).flatMap { headerTokenValue =>
-          verifyAuthToken(headerTokenValue.orElse(parameterTokenValue), permissions.toSet)
+          optionalHeaderValueByName(AuthService.TrackingIdHeader).flatMap { trackingIdValue =>
+            verifyAuthToken(headerTokenValue.orElse(parameterTokenValue), trackingIdValue, permissions.toSet)
+          }
         }
       }
     }
 
     private def verifyAuthToken(tokenOption: Option[String],
+                                trackingIdValue: Option[String],
                                 permissions: Set[Permission]): Directive1[(AuthToken, U)] =
       tokenOption match {
         case Some(tokenValue) =>
-          val token = AuthToken(Base64[Macaroon](tokenValue))
+          val trackingId = trackingIdValue.getOrElse(java.util.UUID.randomUUID.toString)
+          val token      = AuthToken(Base64[Macaroon](tokenValue), trackingId)
 
           onComplete(authStatus(token).run).flatMap { tokenUserResult =>
             checkPermissions(tokenUserResult, permissions, token)
diff --git a/src/main/scala/xyz/driver/core/rest.scala b/src/main/scala/xyz/driver/core/rest.scala
index bfb4ddd..eaf97db 100644
--- a/src/main/scala/xyz/driver/core/rest.scala
+++ b/src/main/scala/xyz/driver/core/rest.scala
@@ -54,7 +54,8 @@ object rest {
 
       val request = (if(requestStub.entity.isKnownEmpty()) requestStub else {
         requestStub.withEntity(requestStub.entity.transformDataBytes(encryptionFlow))
-      }).withHeaders(RawHeader(AuthService.AuthenticationTokenHeader, authToken.value.value))
+      }).withHeaders(RawHeader(AuthService.AuthenticationTokenHeader, authToken.value.value),
+        RawHeader(AuthService.TrackingIdHeader, authToken.trackingId))
 
       log.audit(s"Sending to ${request.uri} request $request")
 
diff --git a/src/test/scala/xyz/driver/core/AuthTest.scala b/src/test/scala/xyz/driver/core/AuthTest.scala
index fef3eda..97279de 100644
--- a/src/test/scala/xyz/driver/core/AuthTest.scala
+++ b/src/test/scala/xyz/driver/core/AuthTest.scala
@@ -40,7 +40,7 @@ class AuthTest extends FlatSpec with Matchers with MockitoSugar with ScalatestRo
 
   it should "throw error is authorized user is not having the requested permission" in {
 
-    val referenceAuthToken = AuthToken(Base64("I am a pathologist's token"))
+    val referenceAuthToken = AuthToken(Base64("I am a pathologist's token"), "BC131CD")
 
     Post("/administration/attempt").addHeader(
       RawHeader(AuthService.AuthenticationTokenHeader, referenceAuthToken.value.value)
@@ -60,7 +60,7 @@ class AuthTest extends FlatSpec with Matchers with MockitoSugar with ScalatestRo
 
   it should "pass and retrieve the token to client code, if token is in request and user has permission" in {
 
-    val referenceAuthToken = AuthToken(Base64("I am token"))
+    val referenceAuthToken = AuthToken(Base64("I am token"), "AAADDDFFF")
 
     Get("/valid/attempt/?a=2&b=5").addHeader(
       RawHeader(AuthService.AuthenticationTokenHeader, referenceAuthToken.value.value)