replace logging of OIDC Headers

env/local.env

@@ -39,7 +39,7 @@ export TOS_GRACE_PERIOD_ENABLED="true"
 export TOS_BASE_URL="https://raw.githubusercontent.com/broadinstitute/terra-terms-of-service/main/versions"
 export TOS_VERSION="1"
 
-#export SAM_LOG_APPENDER="Console-Standard"
+export SAM_LOG_APPENDER="Console-Standard"
 export LANDINGZONES_REUSE_IDS=false
 
 export JANITOR_ENABLED=false

src/main/scala/org/broadinstitute/dsde/workbench/sam/api/SamRoutes.scala

@@ -9,22 +9,19 @@ import akka.http.scaladsl.server
 import akka.http.scaladsl.server.Directives._
 import akka.http.scaladsl.server.RouteResult.Complete
 import akka.http.scaladsl.server.directives.{DebuggingDirectives, LogEntry, LoggingMagnet}
-import akka.http.scaladsl.server.{Directive0, ExceptionHandler, RouteResult}
+import akka.http.scaladsl.server.{Directive0, ExceptionHandler}
 import akka.stream.Materializer
 import akka.stream.scaladsl.Sink
 import com.typesafe.scalalogging.LazyLogging
 import io.sentry.Sentry
-import net.logstash.logback.argument.StructuredArguments
 import org.broadinstitute.dsde.workbench.model.{ErrorReport, WorkbenchExceptionWithErrorReport}
 import org.broadinstitute.dsde.workbench.oauth2.OpenIDConnectConfiguration
 import org.broadinstitute.dsde.workbench.sam._
 import org.broadinstitute.dsde.workbench.sam.api.SamRoutes.myExceptionHandler
 import org.broadinstitute.dsde.workbench.sam.azure.{AzureRoutes, AzureService}
 import org.broadinstitute.dsde.workbench.sam.config.AppConfig.AdminConfig
 import org.broadinstitute.dsde.workbench.sam.config.{LiquibaseConfig, TermsOfServiceConfig}
-import org.broadinstitute.dsde.workbench.sam.model.api.SamUser
 import org.broadinstitute.dsde.workbench.sam.service._
-import scala.jdk.CollectionConverters._
 
 import scala.concurrent.{ExecutionContext, Future}
 
@@ -76,14 +73,12 @@ abstract class SamRoutes(
           userTermsOfServiceRoutes(samRequestContext) ~
           withActiveUser(samRequestContext) { samUser =>
             val samRequestContextWithUser = samRequestContext.copy(samUser = Option(samUser))
-            logRequestResultWithSamUser(samUser) {
-              resourceRoutes(samUser, samRequestContextWithUser) ~
-              adminRoutes(samUser, samRequestContextWithUser) ~
-              extensionRoutes(samUser, samRequestContextWithUser) ~
-              groupRoutes(samUser, samRequestContextWithUser) ~
-              azureRoutes(samUser, samRequestContextWithUser) ~
-              userRoutesV1(samUser, samRequestContextWithUser)
-            }
+            resourceRoutes(samUser, samRequestContextWithUser) ~
+            adminRoutes(samUser, samRequestContextWithUser) ~
+            extensionRoutes(samUser, samRequestContextWithUser) ~
+            groupRoutes(samUser, samRequestContextWithUser) ~
+            azureRoutes(samUser, samRequestContextWithUser) ~
+            userRoutesV1(samUser, samRequestContextWithUser)
           }
         }
       }
@@ -114,27 +109,6 @@ abstract class SamRoutes(
 
     DebuggingDirectives.logRequestResult(LoggingMagnet(log => myLoggingFunction(log)))
   }
-
-  private def logRequestResultWithSamUser(samUser: SamUser): Directive0 = {
-
-    def logSamUserRequest(unusedLogger: LoggingAdapter)(req: HttpRequest)(res: RouteResult): Unit =
-      res match {
-        case Complete(resp) =>
-          logger.info(
-            s"Request from user ${samUser.id} (${samUser.email})",
-            StructuredArguments.keyValue(
-              "eventMetrics",
-              Map("request" -> req.uri, "metricsLog" -> true, "event" -> "sam:api-request:complete", "status" -> resp.status.intValue.toString).asJava
-            )
-          )
-        case _ =>
-          logger.warn(
-            s"Request from user ${samUser.id} (${samUser.email})",
-            StructuredArguments.keyValue("eventMetrics", Map("request" -> req.uri, "metricsLog" -> true, "event" -> "sam:api-request:incomplete").asJava)
-          )
-      }
-    DebuggingDirectives.logRequestResult(LoggingMagnet(log => logSamUserRequest(log)))
-  }
 }
 
 object SamRoutes {

src/main/scala/org/broadinstitute/dsde/workbench/sam/api/StandardSamUserDirectives.scala

@@ -1,10 +1,13 @@
 package org.broadinstitute.dsde.workbench.sam
 package api
 
-import akka.http.scaladsl.model.StatusCodes
+import akka.event.LoggingAdapter
+import akka.http.scaladsl.model.{HttpRequest, StatusCodes}
 import akka.http.scaladsl.model.headers.OAuth2BearerToken
 import akka.http.scaladsl.server.Directives._
+import akka.http.scaladsl.server.RouteResult.{Complete, Rejected}
 import akka.http.scaladsl.server._
+import akka.http.scaladsl.server.directives.{DebuggingDirectives, LoggingMagnet}
 import akka.http.scaladsl.server.directives.OnSuccessMagnet._
 import cats.effect.IO
 import cats.effect.unsafe.implicits.global
@@ -14,12 +17,20 @@ import org.broadinstitute.dsde.workbench.model.google.ServiceAccountSubjectId
 import org.broadinstitute.dsde.workbench.sam.api.StandardSamUserDirectives._
 import org.broadinstitute.dsde.workbench.sam.azure.ManagedIdentityObjectId
 import org.broadinstitute.dsde.workbench.sam.config.TermsOfServiceConfig
+import org.broadinstitute.dsde.workbench.sam.metrics.{
+  MetricsLoggable,
+  RegisteredUserApiEvent,
+  RequestEventDetails,
+  ResponseEventDetails,
+  UnregisteredUserApiEvent
+}
 import org.broadinstitute.dsde.workbench.sam.model.api.SamUser
 import org.broadinstitute.dsde.workbench.sam.service.UserService._
 import org.broadinstitute.dsde.workbench.sam.service.UserService
 import org.broadinstitute.dsde.workbench.sam.util.SamRequestContext
 
-import scala.concurrent.ExecutionContext
+import scala.concurrent.{ExecutionContext, Future}
+import scala.jdk.CollectionConverters._
 import scala.util.Try
 import scala.util.matching.Regex
 
@@ -29,33 +40,42 @@ trait StandardSamUserDirectives extends SamUserDirectives with LazyLogging with
   def withActiveUser(samRequestContext: SamRequestContext): Directive1[SamUser] = requireOidcHeaders.flatMap { oidcHeaders =>
     onSuccess {
       getActiveSamUser(oidcHeaders, userService, termsOfServiceConfig, samRequestContext).unsafeToFuture()
-    }.tmap { samUser =>
+    }.flatMap { samUser =>
       logger.debug(s"Handling request for active Sam User: $samUser")
-      samUser
+      logRequestResultWithSamUser(samUser, oidcHeaders)
     }
   }
 
   def asAdminServiceUser: Directive0 = requireOidcHeaders.flatMap { oidcHeaders =>
-    Directives.mapInnerRoute { r =>
-      if (!adminConfig.serviceAccountAdmins.contains(oidcHeaders.email)) {
-        reject(AuthorizationFailedRejection)
-      } else {
-        logger.info(s"Handling request for service admin account: ${oidcHeaders.email}")
-        r
+    Directives
+      .mapInnerRoute { r =>
+        if (!adminConfig.serviceAccountAdmins.contains(oidcHeaders.email)) {
+          reject(AuthorizationFailedRejection)
+        } else {
+          logger.info(s"Handling request for service admin account: ${oidcHeaders.email}")
+          r
+        }
       }
-    }
+      .tflatMap(_ => logAdminServiceAdminUserRequestResult(oidcHeaders))
   }
 
   def withUserAllowInactive(samRequestContext: SamRequestContext): Directive1[SamUser] = requireOidcHeaders.flatMap { oidcHeaders =>
     onSuccess {
       getSamUser(oidcHeaders, userService, samRequestContext).unsafeToFuture()
-    }.tmap { samUser =>
+    }.flatMap { samUser =>
       logger.debug(s"Handling request for (in)active Sam User: $samUser")
-      samUser
+      logRequestResultWithSamUser(samUser, oidcHeaders)
     }
   }
 
-  def withNewUser(samRequestContext: SamRequestContext): Directive1[SamUser] = requireOidcHeaders.map(buildSamUser)
+  def withNewUser(samRequestContext: SamRequestContext): Directive1[SamUser] = requireOidcHeaders.flatMap { oidcHeaders =>
+    onSuccess {
+      Future.successful(buildSamUser(oidcHeaders))
+    }.flatMap { samUser =>
+      logger.debug(s"Handling request for new Sam User: $samUser")
+      logRequestResultWithSamUser(samUser, oidcHeaders)
+    }
+  }
 
   private def buildSamUser(oidcHeaders: OIDCHeaders): SamUser = {
     // google id can either be in the external id or google id from azure headers, favor the external id as the source
@@ -75,7 +95,7 @@ trait StandardSamUserDirectives extends SamUserDirectives with LazyLogging with
       optionalHeaderValueByName(managedIdentityObjectIdHeader).map(_.map(ManagedIdentityObjectId)))
       .as(OIDCHeaders)
       .map { oidcHeaders =>
-        logger.info(s"Auth Headers: $oidcHeaders")
+        logger.debug(s"Auth Headers: $oidcHeaders")
         oidcHeaders
       }
 
@@ -85,6 +105,63 @@ trait StandardSamUserDirectives extends SamUserDirectives with LazyLogging with
       _ => Left(GoogleSubjectId(idString)) // id is a number which is what google subject ids look like
     )
   }
+
+  private def logAdminServiceAdminUserRequestResult(oidcHeaders: OIDCHeaders): Directive0 = {
+    def logRequest(unusedLogger: LoggingAdapter)(req: HttpRequest)(res: RouteResult): Unit =
+      res match {
+        case Complete(resp) =>
+          logger.info(
+            s"Request from Service Admin user ${oidcHeaders.email}",
+            UnregisteredUserApiEvent(
+              "apiRequest:serviceAdmin:complete",
+              RequestEventDetails(req, Some(oidcHeaders)),
+              Option(ResponseEventDetails(resp))
+            ).toStructuredArguments
+          )
+        case Rejected(rejections) =>
+          logger.warn(
+            s"Request from Service Admin user ${oidcHeaders.email}",
+            UnregisteredUserApiEvent(
+              "apiRequest:serviceAdmin:incomplete",
+              RequestEventDetails(req, Some(oidcHeaders)),
+              None,
+              rejections
+            ).toStructuredArguments
+          )
+      }
+
+    DebuggingDirectives.logRequestResult(LoggingMagnet(log => logRequest(log)))
+  }
+
+  private def logRequestResultWithSamUser(samUser: SamUser, oidcHeaders: OIDCHeaders): Directive1[SamUser] = {
+
+    def logSamUserRequest(unusedLogger: LoggingAdapter)(req: HttpRequest)(res: RouteResult): Unit =
+      res match {
+        case Complete(resp) =>
+          logger.info(
+            s"Request from user ${samUser.id} (${samUser.email})",
+            RegisteredUserApiEvent(
+              samUser.id,
+              "apiRequest:user:complete",
+              RequestEventDetails(req, Some(oidcHeaders)),
+              Option(ResponseEventDetails(resp))
+            ).toStructuredArguments
+          )
+        case Rejected(rejections) =>
+          logger.warn(
+            s"Request from user ${samUser.id} (${samUser.email})",
+            RegisteredUserApiEvent(
+              samUser.id,
+              "apiRequest:user:incomplete",
+              RequestEventDetails(req, Some(oidcHeaders)),
+              None,
+              rejections
+            ).toStructuredArguments
+          )
+      }
+
+    DebuggingDirectives.logRequestResult(LoggingMagnet(log => logSamUserRequest(log))).tmap(_ => samUser)
+  }
 }
 
 object StandardSamUserDirectives {
@@ -180,7 +257,15 @@ final case class OIDCHeaders(
     email: WorkbenchEmail,
     googleSubjectIdFromAzure: Option[GoogleSubjectId],
     managedIdentityObjectId: Option[ManagedIdentityObjectId] = None
-) {
+) extends MetricsLoggable {
+
+  override def toLoggableMap: java.util.Map[String, Any] = Map[String, Any](
+    "googleSubjectId" -> externalId.left.toOption.map(_.value).orNull,
+    "azureB2CId" -> externalId.map(_.value).toOption.orNull,
+    "email" -> email.value,
+    "googleSubjectIdFromAzure" -> googleSubjectIdFromAzure.map(_.value).orNull,
+    "managedIdentityObjectId" -> managedIdentityObjectId.map(_.value).orNull
+  ).asJava
 
   // Customized toString method so that fields are labeled and we must ensure that we do not log the Bearer Token
   override def toString: String = {

src/main/scala/org/broadinstitute/dsde/workbench/sam/metrics/ApiEvent.scala

@@ -0,0 +1,35 @@
+package org.broadinstitute.dsde.workbench.sam.metrics
+
+import akka.http.scaladsl.server.Rejection
+import net.logstash.logback.argument.{StructuredArgument, StructuredArguments}
+
+import java.util
+import scala.jdk.CollectionConverters._
+
+trait ApiEvent extends MetricsLoggable {
+
+  def event: String
+  def request: RequestEventDetails
+  def response: Option[ResponseEventDetails] = None
+  def rejections: Seq[Rejection] = Seq()
+
+  override def toLoggableMap: util.Map[String, Any] =
+    toScalaMap.asJava
+
+  protected def toScalaMap: Map[String, Any] = {
+    val baseMap = Map[String, Any](
+      "event" -> event
+    ) + ("request" -> request.toLoggableMap)
+
+    val responseMap = response.map(headers => baseMap + ("response" -> headers.toLoggableMap)).getOrElse(baseMap)
+
+    if (rejections.isEmpty) {
+      responseMap
+    } else {
+      responseMap + ("rejections" -> rejections.map(_.getClass.getSimpleName).asJava)
+    }
+  }
+
+  def toStructuredArguments: StructuredArgument =
+    StructuredArguments.keyValue("eventProperties", toLoggableMap)
+}

src/main/scala/org/broadinstitute/dsde/workbench/sam/metrics/MetricsLoggable.scala

@@ -0,0 +1,7 @@
+package org.broadinstitute.dsde.workbench.sam.metrics
+
+trait MetricsLoggable {
+
+  def toLoggableMap: java.util.Map[String, Any]
+
+}

src/main/scala/org/broadinstitute/dsde/workbench/sam/metrics/RegisteredUserApiEvent.scala

@@ -0,0 +1,19 @@
+package org.broadinstitute.dsde.workbench.sam.metrics
+
+import akka.http.scaladsl.server.Rejection
+import org.broadinstitute.dsde.workbench.model.WorkbenchUserId
+
+import java.util
+import scala.jdk.CollectionConverters._
+
+case class RegisteredUserApiEvent(
+    samUserId: WorkbenchUserId,
+    override val event: String,
+    override val request: RequestEventDetails,
+    override val response: Option[ResponseEventDetails] = None,
+    override val rejections: Seq[Rejection] = Seq()
+) extends ApiEvent {
+
+  override def toLoggableMap: util.Map[String, Any] =
+    (super.toScalaMap + ("samUserId" -> samUserId.value)).asJava
+}

src/main/scala/org/broadinstitute/dsde/workbench/sam/metrics/RequestEventDetails.scala

@@ -0,0 +1,17 @@
+package org.broadinstitute.dsde.workbench.sam.metrics
+
+import akka.http.scaladsl.model.HttpRequest
+import org.broadinstitute.dsde.workbench.sam.api.OIDCHeaders
+
+import java.util
+import scala.jdk.CollectionConverters._
+
+case class RequestEventDetails(httpRequest: HttpRequest, oidcHeaders: Option[OIDCHeaders]) extends MetricsLoggable {
+  override def toLoggableMap: util.Map[String, Any] = {
+    val baseMap = Map[String, Any](
+      "uri" -> httpRequest.uri.toString,
+      "method" -> httpRequest.method.value
+    )
+    oidcHeaders.map(headers => (baseMap + ("oidcHeaders" -> headers.toLoggableMap)).asJava).getOrElse(baseMap.asJava)
+  }
+}

src/main/scala/org/broadinstitute/dsde/workbench/sam/metrics/ResponseEventDetails.scala

@@ -0,0 +1,12 @@
+package org.broadinstitute.dsde.workbench.sam.metrics
+
+import akka.http.scaladsl.model.HttpResponse
+
+import java.util
+import scala.jdk.CollectionConverters._
+
+case class ResponseEventDetails(httpResponse: HttpResponse) extends MetricsLoggable {
+  override def toLoggableMap: util.Map[String, Any] = Map[String, Any](
+    "status" -> httpResponse.status.intValue
+  ).asJava
+}

src/main/scala/org/broadinstitute/dsde/workbench/sam/metrics/UnregisteredUserApiEvent.scala

@@ -0,0 +1,10 @@
+package org.broadinstitute.dsde.workbench.sam.metrics
+
+import akka.http.scaladsl.server.Rejection
+
+case class UnregisteredUserApiEvent(
+    override val event: String,
+    override val request: RequestEventDetails,
+    override val response: Option[ResponseEventDetails] = None,
+    override val rejections: Seq[Rejection] = Seq()
+) extends ApiEvent