Merge pull request #984 from hmrc/DL-8490

[DL-8490] add trueClientIp and sessionId to logs

app/config/FeatureToggleSupport.scala

@@ -17,7 +17,7 @@
 package config
 
 import config.FeatureSwitch.FeatureSwitch
-import play.api.Logging
+import utils.Logging
 
 import scala.sys.SystemProperties
 

app/routing/VersionRoutingMap.scala

@@ -20,9 +20,10 @@ import com.google.inject.ImplementedBy
 import config.FeatureSwitch.PenaltiesEndpointsFeature
 import config.{AppConfig, FeatureToggleSupport}
 import definition.Versions.VERSION_1
-import javax.inject.Inject
-import play.api.Logging
 import play.api.routing.Router
+import utils.Logging
+
+import javax.inject.Inject
 
 // So that we can have API-independent implementations of
 // VersionRoutingRequestHandler and VersionRoutingRequestHandlerSpec

app/routing/VersionRoutingRequestHandler.scala

@@ -19,7 +19,7 @@ package routing
 import config.{AppConfig, FeatureSwitch, FeatureToggleSupport}
 import definition.Versions
 import javax.inject.{Inject, Singleton}
-import play.api.Logging
+import utils.Logging
 import play.api.http.{DefaultHttpRequestHandler, HttpConfiguration, HttpErrorHandler, HttpFilters}
 import play.api.libs.json.Json
 import play.api.mvc.{DefaultActionBuilder, Handler, RequestHeader, Results}

app/utils/ErrorHandler.scala

@@ -16,7 +16,6 @@
 
 package utils
 
-import javax.inject._
 import play.api._
 import play.api.http.Status._
 import play.api.libs.json.Json
@@ -30,6 +29,7 @@ import uk.gov.hmrc.play.bootstrap.config.HttpAuditEvent
 import uk.gov.hmrc.play.http.HeaderCarrierConverter
 import v1.models.errors._
 
+import javax.inject._
 import scala.concurrent._
 
 @Singleton
@@ -44,7 +44,7 @@ class ErrorHandler @Inject()(config: Configuration,
 
     implicit val headerCarrier: HeaderCarrier = HeaderCarrierConverter.fromRequestAndSession(request, request.session)
 
-    logger.warn(s"[LegacyErrorHandler][onClientError] error in version 1, for (${request.method}) [${request.uri}] with status:" +
+    logger.warn(s"[ErrorHandler][onClientError] error in version 1, for (${request.method}) [${request.uri}] with status:" +
       s" $statusCode and message: $message")
     statusCode match {
       case BAD_REQUEST =>

app/utils/LegacyErrorHandler.scala

@@ -20,7 +20,7 @@ import play.api._
 import play.api.http.DefaultHttpErrorHandler
 import play.api.libs.json.Json
 import play.api.mvc.Results.{BadRequest, NotImplemented}
-import play.api.mvc.{RequestHeader, Result}
+import play.api.mvc.{Request, RequestHeader, Result}
 import play.api.routing.Router
 import uk.gov.hmrc.http.NotImplementedException
 import v1.models.errors._

app/utils/Logging.scala

@@ -16,8 +16,38 @@
 
 package utils
 
-import play.api.Logger
+import org.slf4j.{Logger, LoggerFactory}
+import play.api.{LoggerLike, MarkerContext}
+import play.api.mvc.Request
+import uk.gov.hmrc.http.{HeaderNames, HttpResponse, SessionKeys}
 
-trait Logging {
-  lazy val logger: Logger = Logger(this.getClass)
+trait Logging extends LoggerLike {
+
+  lazy val trueClientIp: Request[_] => Option[String] = request => request.headers.get(HeaderNames.trueClientIp).map(trueClientIp => s"trueClientIp: $trueClientIp ")
+
+  lazy val sessionId: Request[_] => Option[String] = request => request.session.get(SessionKeys.sessionId).map(sessionId => s"sessionId: $sessionId ")
+
+  lazy val identifiers: Request[_] => String = request => Seq(trueClientIp(request), sessionId(request)).flatten.foldLeft("")(_ + _)
+
+  lazy val trueClientIpFromHttpResponse: HttpResponse => Option[String] = httpResponse => httpResponse.headers.get(HeaderNames.trueClientIp).map(trueClientIp => s"trueClientIp: $trueClientIp")
+  lazy val sessionIdFromHttpResponse: HttpResponse => Option[String] = httpResponse => httpResponse.headers.get(HeaderNames.xSessionId).map(sessionId => s"sessionId: $sessionId")
+  lazy val identifiersFromHttpResponse: HttpResponse => String = request => Seq(trueClientIpFromHttpResponse(request), sessionIdFromHttpResponse(request)).flatten.foldLeft("")(_ + _)
+
+  lazy val logger: Logger = LoggerFactory.getLogger(getClass)
+
+  def infoLog(message: => String)(implicit mc: MarkerContext, request: Request[_]): Unit = this.info(s"$message (${identifiers(request)})")
+
+  def infoConnectorLog(message: => String)(implicit mc: MarkerContext, httpResponse: HttpResponse): Unit = this.info(s"$message (${identifiersFromHttpResponse(httpResponse)})")
+
+  def warnLog(message: => String)(implicit mc: MarkerContext, request: Request[_]): Unit = this.warn(s"$message (${identifiers(request)})")
+
+  def warnLog(message: => String, throwable: Throwable)(implicit mc: MarkerContext, request: Request[_]): Unit = this.warn(s"$message (${identifiers(request)})", throwable)
+
+  def warnConnectorLog(message: => String)(implicit httpResponse: HttpResponse): Unit = this.warn(s"$message (${identifiersFromHttpResponse(httpResponse)})")
+
+  def errorLog(message: => String)(implicit mc: MarkerContext, request: Request[_]): Unit = this.error(s"$message (${identifiers(request)})")
+
+  def errorLog(message: => String, throwable: Throwable)(implicit mc: MarkerContext, request: Request[_]): Unit = this.error(s"$message (${identifiers(request)})", throwable)
+
+  def errorConnectorLog(message: => String)(implicit httpResponse: HttpResponse): Unit = this.error(s"$message (${identifiersFromHttpResponse(httpResponse)})")
 }

app/utils/Timer.scala

@@ -18,6 +18,7 @@ package utils
 
 import com.codahale.metrics._
 import com.kenshoo.play.metrics.Metrics
+import play.api.mvc.Request
 
 import scala.concurrent.{ExecutionContext, Future}
 
@@ -30,12 +31,13 @@ trait Timer {
   val metrics: Metrics
 
   def timeFuture[A](name: String, metric: Metric, timerGroup: String = defaultTimerGroup)(block: => Future[A])(
-    implicit ec: ExecutionContext): Future[A] = {
+    implicit ec: ExecutionContext, request: Request[_]): Future[A] = {
     val timer = startTimer(metric, timerGroup)
     block andThen { case _ => stopAndLog(name, timer) }
   }
 
-  def time[A](name: String, metric: Metric, timerGroup: String = defaultTimerGroup)(block: => A): A = {
+  def time[A](name: String, metric: Metric, timerGroup: String = defaultTimerGroup)(block: => A)
+             (implicit request: Request[_]): A = {
     val timer = startTimer(metric, timerGroup)
     try block
     finally stopAndLog(name, timer)
@@ -44,11 +46,11 @@ trait Timer {
   protected def startTimer(metric: Metric, timerGroup: String): Timer.Context =
     metrics.defaultRegistry.timer(s"$metric-$timerGroup").time()
 
-  protected def stopAndLog[A](name: String, timer: Timer.Context): Unit = {
+  protected def stopAndLog[A](name: String, timer: Timer.Context)(implicit request: Request[_]): Unit = {
     val timeMillis = timer.stop() / 1000000
 
     if (timeMillis > 1000) {
-      logger.info(getClass.getName + s" $name took $timeMillis ms")
+      infoLog(getClass.getName + s" $name took $timeMillis ms")
     } else {
       logger.debug(getClass.getName + s" $name took $timeMillis ms")
     }

app/v1/connectors/LiabilitiesConnector.scala

@@ -62,7 +62,7 @@ class LiabilitiesConnector @Inject()(val http: HttpClient,
 
         val logDetails = s"request failed. ${e.getMessage}"
 
-        logger.error(ConnectorError.log(
+        errorLog(ConnectorError.log(
           logContext = "[LiabilitiesConnector][retrieveLiabilities]",
           vrn = vrn,
           details = logDetails,
@@ -72,7 +72,7 @@ class LiabilitiesConnector @Inject()(val http: HttpClient,
           pagerDutyLoggingEndpointName = Endpoint.RetrieveLiabilities.requestFailedMessage,
           status = Status.INTERNAL_SERVER_ERROR,
           body = logDetails,
-          f = logger.error(_),
+          f = errorLog(_),
           affinityGroup = userRequest.userDetails.userType
         )
 

app/v1/connectors/ObligationsConnector.scala

@@ -63,13 +63,13 @@ class ObligationsConnector @Inject()(val http: HttpClient, val appConfig: AppCon
       queryParams = queryParams
     ).andThen {
       case Success(Left(ResponseWrapper(_, DesErrors(errorCodes)))) if errorCodes.exists(_.code == NOT_FOUND_BPKEY) =>
-        logger.warn(s"[ObligationsConnector] [retrieveObligations] - Backend returned $NOT_FOUND_BPKEY error")
+        warnLog(s"[ObligationsConnector] [retrieveObligations] - Backend returned $NOT_FOUND_BPKEY error")
     }.recover {
       case e =>
 
         val logDetails = s"request failed. ${e.getMessage}"
 
-        logger.error(ConnectorError.log(
+        errorLog(ConnectorError.log(
           logContext = "[ObligationsConnector][retrieveObligations]",
           vrn = vrn,
           details = logDetails,
@@ -79,7 +79,7 @@ class ObligationsConnector @Inject()(val http: HttpClient, val appConfig: AppCon
           pagerDutyLoggingEndpointName = Endpoint.RetrieveObligations.requestFailedMessage,
           status = Status.INTERNAL_SERVER_ERROR,
           body = logDetails,
-          f = logger.error(_),
+          f = errorLog(_),
           affinityGroup = userRequest.userDetails.userType
         )
 

app/v1/connectors/PaymentsConnector.scala

@@ -64,7 +64,7 @@ class PaymentsConnector @Inject()(val http: HttpClient,
 
         val logDetails = s"request failed. ${e.getMessage}"
 
-        logger.error(ConnectorError.log(
+        errorLog(ConnectorError.log(
           logContext = "[PaymentsConnector][retrievePayments]",
           vrn = vrn,
           details = logDetails,
@@ -74,7 +74,7 @@ class PaymentsConnector @Inject()(val http: HttpClient,
           pagerDutyLoggingEndpointName = Endpoint.RetrievePayments.requestFailedMessage,
           status = Status.INTERNAL_SERVER_ERROR,
           body = logDetails,
-          f = logger.error(_),
+          f = errorLog(_),
           affinityGroup = userRequest.userDetails.userType
         )
 

app/v1/connectors/PenaltiesConnector.scala

@@ -66,7 +66,7 @@ class PenaltiesConnector @Inject()(val http: HttpClient,
       case e =>
         val logDetails = s"request failed. ${e.getMessage}"
 
-        logger.error(ConnectorError.log(
+        errorLog(ConnectorError.log(
           logContext = "[PenaltiesConnector][retrievePenaltiesData]",
           vrn = vrn,
           details = logDetails,
@@ -76,7 +76,7 @@ class PenaltiesConnector @Inject()(val http: HttpClient,
           pagerDutyLoggingEndpointName = Endpoint.RetrievePenalties.requestFailedMessage,
           status = Status.INTERNAL_SERVER_ERROR,
           body = logDetails,
-          f = logger.error(_),
+          f = errorLog(_),
           affinityGroup = userRequest.userDetails.userType
         )
         Left(ErrorWrapper(correlationId, MtdError("DOWNSTREAM_ERROR", e.getMessage)))
@@ -101,7 +101,7 @@ class PenaltiesConnector @Inject()(val http: HttpClient,
       case e =>
         val logDetails = s"request failed. ${e.getMessage}"
 
-        logger.error(ConnectorError.log(
+        errorLog(ConnectorError.log(
           logContext = "[PenaltiesConnector][retrieveFinancialData]",
           vrn = vrn,
           details = logDetails,
@@ -111,7 +111,7 @@ class PenaltiesConnector @Inject()(val http: HttpClient,
           pagerDutyLoggingEndpointName = Endpoint.RetrieveFinancialData.requestFailedMessage,
           status = Status.INTERNAL_SERVER_ERROR,
           body = logDetails,
-          f = logger.error(_),
+          f = errorLog(_),
           affinityGroup = userRequest.userDetails.userType
         )
 

app/v1/connectors/SubmitReturnConnector.scala

@@ -53,7 +53,7 @@ class SubmitReturnConnector @Inject()(val http: HttpClient,
       case e =>
         val logDetails = s"request failed. ${e.getMessage}"
 
-        logger.error(ConnectorError.log(
+        errorLog(ConnectorError.log(
           logContext = "[SubmitReturnConnector][submitReturn]",
           vrn = vrn,
           details = logDetails,
@@ -63,7 +63,7 @@ class SubmitReturnConnector @Inject()(val http: HttpClient,
           pagerDutyLoggingEndpointName = Endpoint.SubmitReturn.requestFailedMessage,
           status = Status.INTERNAL_SERVER_ERROR,
           body = logDetails,
-          f = logger.error(_),
+          f = errorLog(_),
           affinityGroup = userRequest.userDetails.userType
         )
         Left(ResponseWrapper(correlationId, DesErrors(List(DesErrorCode("DOWNSTREAM_ERROR"))))) }

app/v1/connectors/ViewReturnConnector.scala

@@ -59,7 +59,7 @@ class ViewReturnConnector @Inject()(val http: HttpClient,
       case e =>
         val logDetails = s"request failed. ${e.getMessage}"
 
-        logger.error(ConnectorError.log(
+        errorLog(ConnectorError.log(
           logContext = "[ViewReturnConnector][viewReturn]",
           vrn = vrn,
           details = logDetails,
@@ -69,7 +69,7 @@ class ViewReturnConnector @Inject()(val http: HttpClient,
           pagerDutyLoggingEndpointName = Endpoint.RetrieveReturns.requestFailedMessage,
           status = Status.INTERNAL_SERVER_ERROR,
           body = logDetails,
-          f = logger.error(_),
+          f = errorLog(_),
           affinityGroup = userRequest.userDetails.userType
         )
 

app/v1/connectors/httpparsers/FinancialDataHttpParser.scala

@@ -88,12 +88,12 @@ object FinancialDataHttpParser extends Logging {
         case OK => response.json.validate[FinancialDataResponse] match {
           case JsSuccess(model, _) => Right(ResponseWrapper(responseCorrelationId, model))
           case JsError(errors) =>
-            logger.error(s"[FinancialDataResponseReads][read] invalid JSON errors: $errors")
+            errorConnectorLog(s"[FinancialDataResponseReads][read] invalid JSON errors: $errors")(response)
             Left(ErrorWrapper(responseCorrelationId, InvalidJson))
         }
         case status =>
           val mtdErrors = errorHelper(response.json)
-          logger.error(s"[FinancialDataHttpParser][read] status: ${status} with Error ${mtdErrors}")
+          errorConnectorLog(s"[FinancialDataHttpParser][read] status: ${status} with Error ${mtdErrors}")(response)
           Left(ErrorWrapper(responseCorrelationId, mtdErrors))
       }
     }

app/v1/connectors/httpparsers/HttpParser.scala

@@ -18,6 +18,7 @@ package v1.connectors.httpparsers
 
 import utils.Logging
 import play.api.libs.json._
+import play.api.mvc.Request
 import uk.gov.hmrc.http.HttpResponse
 import v1.models.errors._
 
@@ -27,20 +28,20 @@ trait HttpParser extends Logging {
 
   implicit class KnownJsonResponse(response: HttpResponse) {
 
-    def validateJson[T](implicit reads: Reads[T]): Option[T] = {
+    def validateJson[T](implicit reads: Reads[T], request: Request[_]): Option[T] = {
       Try(response.json) match {
         case Success(json: JsValue) => parseResult(json)
         case _ =>
-          logger.warn("[KnownJsonResponse][validateJson] No JSON was returned")
+          warnLog("[KnownJsonResponse][validateJson] No JSON was returned")
           None
       }
     }
 
-    def parseResult[T](json: JsValue)(implicit reads: Reads[T]): Option[T] = json.validate[T] match {
+    def parseResult[T](json: JsValue)(implicit reads: Reads[T], request: Request[_]): Option[T] = json.validate[T] match {
 
       case JsSuccess(value, _) => Some(value)
       case JsError(error) =>
-        logger.warn(s"[KnownJsonResponse][validateJson] Unable to parse JSON: $error")
+        warnLog(s"[KnownJsonResponse][validateJson] Unable to parse JSON: $error")
         None
     }
   }
@@ -53,11 +54,11 @@ trait HttpParser extends Logging {
     (__ \ "bvrfailureResponseElement" \ "validationRuleFailures").read[Seq[DesErrorCode]]
   }
 
-  def parseErrors(response: HttpResponse): DesError = {
+  def parseErrors(response: HttpResponse)(implicit request: Request[_]): DesError = {
     val singleError         = response.validateJson[DesErrorCode].map(err => DesErrors(List(err)))
-    lazy val bvrErrors      = response.validateJson(bvrErrorReads).map(errs => OutboundError(BVRError, Some(errs.map(_.toMtd))))
+    lazy val bvrErrors      = response.validateJson(bvrErrorReads, request).map(errs => OutboundError(BVRError, Some(errs.map(_.toMtd))))
     lazy val unableToParseJsonError = {
-      logger.warn(s"unable to parse errors from response: ${response.body}")
+      warnLog(s"unable to parse errors from response: ${response.body}")
       OutboundError(DownstreamError)
     }
 

app/v1/connectors/httpparsers/PenaltiesHttpParser.scala

@@ -67,12 +67,12 @@ object PenaltiesHttpParser extends Logging {
         case OK => response.json.validate[PenaltiesResponse] match {
           case JsSuccess(model, _) => Right(ResponseWrapper(responseCorrelationId, model))
           case JsError(errors) =>
-            logger.error(s"[PenaltiesHttpParser][read] invalid JSON errors: $errors")
+            errorConnectorLog(s"[PenaltiesHttpParser][read] invalid JSON errors: $errors")(response)
             Left(ErrorWrapper(responseCorrelationId, InvalidJson))
         }
         case status =>
           val mtdErrors = errorHelper(response.json)
-          logger.error(s"[PenaltiesHttpParser][read] status: ${status} with Error ${mtdErrors}")
+          errorConnectorLog(s"[PenaltiesHttpParser][read] status: ${status} with Error ${mtdErrors}")(response)
           Left(ErrorWrapper(responseCorrelationId, mtdErrors))
       }
     }

app/v1/connectors/httpparsers/StandardDesHttpParser.scala

@@ -55,15 +55,15 @@ object StandardDesHttpParser extends HttpParser {
     val responseCorrelationId = retrieveCorrelationId(response)
 
     if (response.status != successCode.status) {
-      logger.info(
+      infoLog(
         "[StandardDesHttpParser][read] - " +
           s"Error response received from DES with status: ${response.status} and body\n" +
           s"${response.body} and correlationId: $responseCorrelationId when calling $url - " +
           s"vrn: ${connectorError.vrn}, requestId: ${connectorError.requestId}")
     }
     response.status match {
       case successCode.status =>
-        logger.info(
+        infoLog(
           "[StandardDesHttpParser][read] - " +
             s"Success response received from DES with correlationId: $responseCorrelationId when calling $url")
         successOutcomeFactory(responseCorrelationId)
@@ -72,10 +72,10 @@ object StandardDesHttpParser extends HttpParser {
            FORBIDDEN |
            CONFLICT |
            UNPROCESSABLE_ENTITY =>
-        PagerDutyLogging.log(pagerDutyLoggingEndpointName, response.status, response.body, logger.info(_), userRequest.userDetails.userType)
+        PagerDutyLogging.log(pagerDutyLoggingEndpointName, response.status, response.body, infoLog(_), userRequest.userDetails.userType)
         Left(ResponseWrapper(responseCorrelationId, parseErrors(response)))
       case _ =>
-        PagerDutyLogging.log(pagerDutyLoggingEndpointName, response.status, response.body, logger.error(_), userRequest.userDetails.userType)
+        PagerDutyLogging.log(pagerDutyLoggingEndpointName, response.status, response.body, errorLog(_), userRequest.userDetails.userType)
         Left(ResponseWrapper(responseCorrelationId, OutboundError(DownstreamError)))
     }
   }

app/v1/controllers/AuthorisedController.scala

@@ -53,7 +53,7 @@ abstract class AuthorisedController(cc: ControllerComponents)(implicit ec: Execu
       val clientId = request.headers.get("X-Client-Id").getOrElse("N/A")
 
       if (VrnValidation.validate(vrn) == Nil) {
-        authService.authorised(predicate(vrn), nrsRequired).flatMap[Result] {
+        authService.authorised(predicate(vrn), nrsRequired)(headerCarrier,executionContext, request).flatMap[Result] {
           case Right(userDetails) => block(UserRequest(userDetails.copy(clientId = clientId), request))
           case Left(LegacyUnauthorisedError) => Future.successful(Forbidden(Json.toJson(LegacyUnauthorisedError)))
           case Left(ForbiddenDownstreamError) => Future.successful(Forbidden(Json.toJson(DownstreamError)))