Add functionality to tag logs (#267)

* inital commit after work with @dominickendrick

* implement @rtyley's suggested improvements

* slight refactoring - tagging logs is not specific to Sentry

* comment note updated

app/abtests/Test.scala

@@ -2,7 +2,6 @@ package abtests
 
 import actions.CommonActions.ABTestRequest
 import com.github.slugify.Slugify
-import play.api.Logger
 import play.api.db.Database
 import play.api.libs.json.{JsValue, Json, Writes}
 import play.api.mvc.AnyContent

app/configuration/Config.scala

@@ -2,12 +2,9 @@ package configuration
 import com.netaporter.uri.Uri
 import com.netaporter.uri.dsl._
 import com.typesafe.config.ConfigFactory
-import play.api.Logger
 
 object Config {
 
-  val logger = Logger(this.getClass)
-
   val config = ConfigFactory.load()
   val contributeUrl = config.getString("contribute.url")
   val domain = Uri.parse(contributeUrl).host

app/controllers/Contributions.scala

@@ -9,6 +9,7 @@ import com.gu.i18n._
 import com.netaporter.uri.dsl._
 import configuration.Config
 import models.ContributionAmount
+import monitoring.TagAwareLogger
 import play.api.mvc._
 import play.filters.csrf.{CSRF, CSRFAddToken}
 import services.PaymentServices
@@ -52,6 +53,7 @@ class Contributions(paymentServices: PaymentServices, addToken: CSRFAddToken) ex
 
   def contribute(countryGroup: CountryGroup, error: Option[PaymentError] = None) = addToken {
     (NoCacheAction andThen MobileSupportAction andThen ABTestAction) { implicit request =>
+
       val errorMessage = error.map(_.message)
       val stripe = paymentServices.stripeServiceFor(request)
       val cmp = request.getQueryString("CMP")

app/controllers/PaypalController.scala

@@ -10,10 +10,11 @@ import com.gu.i18n.{CountryGroup, Currency}
 import com.netaporter.uri.Uri
 import com.paypal.api.payments.Payment
 import models._
+import monitoring.TagAwareLogger
+import monitoring.LoggingTags
 import play.api.libs.ws.WSClient
 import play.api.mvc._
 import services.PaymentServices
-import play.api.Logger
 import play.api.data.Form
 import utils.MaxAmount
 import play.api.libs.json._
@@ -28,7 +29,7 @@ import utils.StoreMetaDataError
 import scala.concurrent.{ExecutionContext, Future}
 
 class PaypalController(ws: WSClient, paymentServices: PaymentServices, checkToken: CSRFCheck)(implicit ec: ExecutionContext)
-  extends Controller with Redirect {
+  extends Controller with Redirect with TagAwareLogger {
   import ContribTimestampCookieAttributes._
 
   def executePayment(
@@ -144,35 +145,35 @@ class PaypalController(ws: WSClient, paymentServices: PaymentServices, checkToke
       )
       authResponse.value map {
         case Right(url) => Ok(Json.toJson(AuthResponse(url)))
-        case Left(error) =>
-          Logger.error(s"Error getting PayPal auth url: $error")
+        case Left(err) =>
+          error(s"Error getting PayPal auth url: $err")
           InternalServerError("Error getting PayPal auth url")
       }
     }
   }
 
-  def handleError(countryGroup: CountryGroup, error: String) = {
-    Logger.error(error)
+  def handleError(countryGroup: CountryGroup, err: String)(implicit tags: LoggingTags) = {
+    error(err)
     Redirect(routes.Contributions.contribute(countryGroup, Some(PaypalError)).url, SEE_OTHER)
   }
 
-  def hook = NoCacheAction.async(parse.tolerantText) { request =>
+  def hook = NoCacheAction.async(parse.tolerantText) { implicit request =>
     val bodyText = request.body
     val bodyJson = Json.parse(request.body)
 
     val paypalService = paymentServices.paypalServiceFor(request)
     val validHook = paypalService.validateEvent(request.headers.toSimpleMap, bodyText)
 
-    def withParsedPaypalHook(paypalHookJson: JsValue)(block: PaypalHook => Future[Result]): Future[Result] = {
+    def withParsedPaypalHook(paypalHookJson: JsValue)(block: PaypalHook => Future[Result])(implicit tags: LoggingTags): Future[Result] = {
       bodyJson.validate[PaypalHook] match {
         case JsSuccess(paypalHook, _) if validHook =>
-          Logger.info(s"Received paymentHook: ${paypalHook.paymentId}")
+          info(s"Received paymentHook: ${paypalHook.paymentId}")
           block(paypalHook)
-        case JsError(errors) =>
-          Logger.error(s"Unable to parse Json, parsing errors: $errors")
+        case JsError(err) =>
+          error(s"Unable to parse Json, parsing errors: $err")
           Future.successful(InternalServerError("Unable to parse json payload"))
         case _ =>
-          Logger.error(s"A webhook request wasn't valid: $request, headers: ${request.headers.toSimpleMap},body: $bodyText")
+          error(s"A webhook request wasn't valid: $request, headers: ${request.headers.toSimpleMap},body: $bodyText")
           Future.successful(Forbidden("Request isn't signed by Paypal"))
       }
     }
@@ -198,7 +199,7 @@ class PaypalController(ws: WSClient, paymentServices: PaymentServices, checkToke
     val idUser = IdentityId.fromRequest(request)
     val contributor = request.session.data.get("email") match {
       case Some(email) => paypalService.updateMarketingOptIn(email, marketingOptIn, idUser).value
-      case None => Future.successful(Logger.error("email not found in session while trying to update marketing opt in"))
+      case None => Future.successful(error("email not found in session while trying to update marketing opt in"))
     }
 
     val url = request.session.get("amount").flatMap(ContributionAmount.apply)

app/controllers/StripeController.scala

@@ -16,8 +16,9 @@ import controllers.forms.ContributionRequest
 import cookies.ContribTimestampCookieAttributes
 import cookies.syntax._
 import models._
+import monitoring.LoggingTags
 import org.joda.time.DateTime
-import play.api.Logger
+import monitoring.TagAwareLogger
 import play.api.libs.json._
 import play.api.mvc._
 import services.PaymentServices
@@ -26,7 +27,7 @@ import utils.MaxAmount
 import scala.concurrent.{ExecutionContext, Future}
 
 class StripeController(paymentServices: PaymentServices, stripeConfig: Config)(implicit ec: ExecutionContext)
-  extends Controller with Redirect {
+  extends Controller with Redirect with TagAwareLogger {
 
   // THIS ENDPOINT IS USED BY BOTH THE FRONTEND AND THE MOBILE-APP
   def pay = (NoCacheAction andThen MobileSupportAction andThen ABTestAction)
@@ -111,15 +112,15 @@ class StripeController(paymentServices: PaymentServices, stripeConfig: Config)(i
   val webhookKey = stripeConfig.getString("webhook.key")
 
   def hook = SharedSecretAction(webhookKey) {
-    NoCacheAction.async(parse.json) { request =>
+    NoCacheAction.async(parse.json) { implicit request =>
 
-      def withParsedStripeHook(stripeHookJson: JsValue)(block: StripeHook => Future[Result]): Future[Result] = {
+      def withParsedStripeHook(stripeHookJson: JsValue)(block: StripeHook => Future[Result])(implicit tags: LoggingTags): Future[Result] = {
         stripeHookJson.validate[StripeHook] match {
-          case JsError(error) =>
-            Logger.error(s"Unable to parse the stripe hook: $error")
+          case JsError(err) =>
+            error(s"Unable to parse the stripe hook: $err")
             Future.successful(BadRequest("Invalid Json"))
           case JsSuccess(stripeHook, _) =>
-            Logger.info(s"Processing a stripe hook ${stripeHook.eventId}")
+            info(s"Processing a stripe hook ${stripeHook.eventId}")
             block(stripeHook)
         }
       }

app/controllers/UserController.scala

@@ -1,6 +1,7 @@
 package controllers
 
 import models.Autofill
+import monitoring.TagAwareLogger
 import play.api.libs.json._
 import play.api.mvc.{Action, AnyContent, Controller, Result}
 import services.IdentityService
@@ -9,13 +10,13 @@ import scala.concurrent.{ExecutionContext, Future}
 
 class UserController(identityService: IdentityService)(implicit ec: ExecutionContext) extends Controller {
 
-  def autofill: Action[AnyContent] = Action.async { req =>
+  def autofill: Action[AnyContent] = Action.async { implicit request =>
 
     def serialise(result: Autofill): Result = {
       NoCache(Ok(Json.toJson(result)))
     }
 
-    req.cookies.get("SC_GU_U") match {
+    request.cookies.get("SC_GU_U") match {
       case Some(cookie) => identityService.autofill(cookie.value).map(serialise)
       case None => Future.successful(serialise(Autofill.empty))
     }

app/data/ContributionData.scala

@@ -7,23 +7,24 @@ import cats.data.EitherT
 import cats.syntax.either._
 import data.AnormMappings._
 import models.{ContributionMetaData, Contributor, PaymentHook}
-import play.api.Logger
+import monitoring.LoggingTags
+import monitoring.TagAwareLogger
 import play.api.db.Database
 
 import scala.concurrent.{ExecutionContext, Future}
 import scala.util.Try
 
-class ContributionData(db: Database)(implicit ec: ExecutionContext) {
+class ContributionData(db: Database)(implicit ec: ExecutionContext) extends TagAwareLogger {
 
-  def withAsyncConnection[A](autocommit: Boolean = false)(block: Connection => A): EitherT[Future, String, A] = EitherT(Future {
+  def withAsyncConnection[A](autocommit: Boolean = false)(block: Connection => A)(implicit tags: LoggingTags): EitherT[Future, String, A] = EitherT(Future {
     val result = Try(db.withConnection(autocommit)(block))
     Either.fromTry(result).leftMap { exception =>
-      Logger.error("Error encountered during the execution of the sql query", exception)
+      error("Error encountered during the execution of the sql query", exception)
       "Error encountered during the execution of the sql query"
     }
   })
 
-  def insertPaymentHook(paymentHook: PaymentHook): EitherT[Future, String, PaymentHook] = {
+  def insertPaymentHook(paymentHook: PaymentHook)(implicit tags: LoggingTags): EitherT[Future, String, PaymentHook] = {
     withAsyncConnection(autocommit = true) { implicit conn =>
       val request = SQL"""
         INSERT INTO payment_hooks(
@@ -62,7 +63,7 @@ class ContributionData(db: Database)(implicit ec: ExecutionContext) {
     }
   }
 
-  def insertPaymentMetaData(pmd: ContributionMetaData): EitherT[Future, String, ContributionMetaData] = {
+  def insertPaymentMetaData(pmd: ContributionMetaData)(implicit tags: LoggingTags): EitherT[Future, String, ContributionMetaData] = {
     withAsyncConnection(autocommit = true) { implicit conn =>
       val request = SQL"""
         INSERT INTO contribution_metadata(
@@ -107,7 +108,7 @@ class ContributionData(db: Database)(implicit ec: ExecutionContext) {
     }
   }
 
-  def saveContributor(contributor: Contributor): EitherT[Future, String, Contributor] = {
+  def saveContributor(contributor: Contributor)(implicit tags: LoggingTags): EitherT[Future, String, Contributor] = {
     withAsyncConnection(autocommit = true) { implicit conn =>
       // Note that the contributor ID will only set on insert. it's not touched on update.
       val request = SQL"""

app/monitoring/ErrorHandler.scala

@@ -27,7 +27,7 @@ class ErrorHandler @Inject()(
 
   override def logServerError(request: RequestHeader, usefulException: UsefulException) {
     try {
-      for (identityUser <- identityAuthProvider(request)) { MDC.put(UserIdentityId, identityUser.id) }
+      for (identityUser <- identityAuthProvider(request)) MDC.put(UserIdentityId, identityUser.id)
 
       MDC.put(PlayErrorId, usefulException.id)
 

app/monitoring/LoggingTags.scala

@@ -0,0 +1,56 @@
+package monitoring
+
+import java.util.UUID
+
+import com.typesafe.scalalogging.LazyLogging
+import org.slf4j.MDC
+import play.api.mvc.Request
+
+// Tags to be included in a log statement using Mapped Diagnostic Context (MDC).
+// A MDC can be used to supplement log messages with additional contextual information,
+// or provide tags to a Sentry Appender.
+//
+// References:
+// - https://logback.qos.ch/manual/mdc.html, and
+// - https://github.com/getsentry/raven-java/blob/master/raven-logback/src/main/java/com/getsentry/raven/logback/SentryAppender.java
+case class LoggingTags(browserId: String, requestId: UUID) {
+
+  def toMap: Map[String, String] = Map(
+    LoggingTags.browserId -> browserId,
+    LoggingTags.requestId -> requestId.toString
+  )
+}
+
+object LoggingTags {
+
+  val browserId = "browserId"
+  val requestId = "requestId"
+
+  val allTags = Seq(browserId, requestId)
+
+  // Means that if `implicit request =>` is used in an Action, an implicit LoggingTags instance will be in scope.
+  implicit def fromRequest(implicit request: Request[Any]): LoggingTags = {
+    val browserId = request.cookies.get("bwid").map(_.value).getOrElse("unknown")
+    LoggingTags(browserId, UUID.randomUUID)
+  }
+}
+
+trait TagAwareLogger extends LazyLogging {
+
+  private[this] def withTags(loggingExpr: => Unit)(implicit tags: LoggingTags): Unit =
+    try {
+      for ((tagName, tagValue) <- tags.toMap) MDC.put(tagName, tagValue)
+      loggingExpr
+    } finally {
+      MDC.clear()
+    }
+
+  def info(msg: String)(implicit tags: LoggingTags): Unit =
+    withTags(logger.info(msg))
+
+  def error(msg: String, t: Throwable)(implicit tags: LoggingTags): Unit =
+    withTags(logger.error(msg, t))
+
+  def error(msg: String)(implicit tags: LoggingTags): Unit =
+    withTags(logger.error(msg))
+}

app/monitoring/SentryLogging.scala

@@ -5,13 +5,16 @@ import ch.qos.logback.classic.{Logger, LoggerContext}
 import com.getsentry.raven.RavenFactory
 import com.getsentry.raven.dsn.Dsn
 import com.getsentry.raven.logback.SentryAppender
+import com.typesafe.scalalogging.LazyLogging
 import configuration.Config
 import org.slf4j.Logger.ROOT_LOGGER_NAME
 import org.slf4j.LoggerFactory
 
 import scala.util.{Failure, Success, Try}
 
-object SentryLogging {
+// Don't have this object extend the SentryLogging trait.
+// There is no contextual information at this stage of the application's life-cycle.
+object SentryLogging extends LazyLogging {
 
   val UserIdentityId = "userIdentityId"
   val UserGoogleId = "userGoogleId"
@@ -21,9 +24,9 @@ object SentryLogging {
   def init(config: com.typesafe.config.Config) {
     Try(new Dsn(config.getString("sentry.dsn"))) match {
       case Failure(ex) =>
-        play.api.Logger.warn("No server-side Sentry logging configured (OK for dev)")
+        logger.warn("No server-side Sentry logging configured (OK for dev)")
       case Success(dsn) =>
-        play.api.Logger.info(s"Initialising Sentry logging for ${dsn.getHost}")
+        logger.info(s"Initialising Sentry logging for ${dsn.getHost}")
         val buildInfo: Map[String, Any] = app.BuildInfo.toMap
         val tags = Map("stage" -> Config.stage) ++ buildInfo
         val tagsString = tags.map { case (key, value) => s"$key:$value"}.mkString(",")
@@ -35,7 +38,7 @@ object SentryLogging {
           addFilter(filter)
           setTags(tagsString)
           setRelease(app.BuildInfo.gitCommitId)
-          setExtraTags(AllMDCTags.mkString(","))
+          setExtraTags((AllMDCTags ++ LoggingTags.allTags).mkString(","))
           setContext(LoggerFactory.getILoggerFactory.asInstanceOf[LoggerContext])
         }
         sentryAppender.start()

app/services/EmailService.scala

@@ -10,13 +10,14 @@ import com.amazonaws.services.sqs.AmazonSQSAsyncClient
 import com.amazonaws.services.sqs.model._
 import configuration.Config
 import models.ContributorRow
-import play.api.Logger
+import monitoring.LoggingTags
+import monitoring.TagAwareLogger
 import play.api.libs.json._
 import utils.AwsAsyncHandler
 
 import scala.concurrent.{ExecutionContext, Future}
 
-class EmailService(implicit ec: ExecutionContext) extends LazyLogging {
+class EmailService(implicit ec: ExecutionContext) extends TagAwareLogger {
 
   val credentialsProviderChain: AWSCredentialsProviderChain = new AWSCredentialsProviderChain(
     new EnvironmentVariableCredentialsProvider,
@@ -34,15 +35,15 @@ class EmailService(implicit ec: ExecutionContext) extends LazyLogging {
   // We don't want to send them an automatic email yet
   val noEmailCampaignCodes = Set("co_uk_ema_cns_a", "co_uk_ema_cns_b", "co_us_ema_cnsus_a", "co_int_email_patronask")
 
-  def thank(row: ContributorRow): EitherT[Future, Throwable, SendMessageResult] = {
+  def thank(row: ContributorRow)(implicit tags: LoggingTags): EitherT[Future, Throwable, SendMessageResult] = {
     if (noEmailCampaignCodes.exists(row.cmp.contains)) {
       EitherT.pure[Future, Throwable, SendMessageResult](new SendMessageResult)
     } else {
       sendEmailToQueue(thankYouQueueUrl, row)
     }
   }
 
-  def sendEmailToQueue(queueUrl: String, row: ContributorRow): EitherT[Future, Throwable, SendMessageResult] = {
+  def sendEmailToQueue(queueUrl: String, row: ContributorRow)(implicit tags: LoggingTags): EitherT[Future, Throwable, SendMessageResult] = {
     val payload = Json.stringify(Json.toJson(row))
 
     val handler = new AwsAsyncHandler[SendMessageRequest, SendMessageResult]
@@ -52,7 +53,7 @@ class EmailService(implicit ec: ExecutionContext) extends LazyLogging {
       Right(result)
     } recover {
       case t: Throwable =>
-        Logger.error(s"Unable to send message to the SQS queue $queueUrl", t)
+        error(s"Unable to send message to the SQS queue $queueUrl", t)
         Left(t)
     })
   }