Skip to content

Rework connector logging to avoid logging response bodies #332

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Open
DavidGregory084 wants to merge 1 commit into
base: main
Choose a base branch
from
Open

Rework connector logging to avoid logging response bodies #332

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
61 changes: 39 additions & 22 deletions app/uk/gov/hmrc/excisemovementcontrolsystemapi/connectors/EISSubmissionConnector.scala
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -17,27 +17,28 @@
package uk.gov.hmrc.excisemovementcontrolsystemapi.connectors

import com.codahale.metrics.MetricRegistry
import com.fasterxml.jackson.core.JacksonException
import play.api.Logging
import play.api.http.Status.INTERNAL_SERVER_ERROR
import play.api.libs.json.{JsResultException, Json, Reads}
import uk.gov.hmrc.excisemovementcontrolsystemapi.config.AppConfig
import uk.gov.hmrc.excisemovementcontrolsystemapi.models.EISErrorResponseDetails
import uk.gov.hmrc.excisemovementcontrolsystemapi.models.eis.EISSubmissionResponse.format
import uk.gov.hmrc.excisemovementcontrolsystemapi.models.eis._
import uk.gov.hmrc.excisemovementcontrolsystemapi.models.messages.IEMessage
import uk.gov.hmrc.excisemovementcontrolsystemapi.services.HttpHeader
import uk.gov.hmrc.excisemovementcontrolsystemapi.utils.DateTimeService.DateTimeFormat
import uk.gov.hmrc.excisemovementcontrolsystemapi.utils.{DateTimeService, EmcsUtils}
import uk.gov.hmrc.http.HttpReads.Implicits._
import uk.gov.hmrc.http.client.HttpClientV2
import uk.gov.hmrc.http.{HeaderCarrier, HttpErrorFunctions, HttpReads, HttpResponse, StringContextOps}
import uk.gov.hmrc.http.{HeaderCarrier, HttpErrorFunctions, HttpResponse, StringContextOps}

import java.time.Instant
import java.util.UUID
import javax.inject.Inject
import scala.concurrent.{ExecutionContext, Future}
import scala.util.control.NonFatal
import scala.xml.NodeSeq
import HttpReads.Implicits._
import play.api.http.Status.INTERNAL_SERVER_ERROR
import play.api.libs.json.{Json, Reads}
import uk.gov.hmrc.excisemovementcontrolsystemapi.models.eis.EISSubmissionResponse.format
import uk.gov.hmrc.excisemovementcontrolsystemapi.services.HttpHeader
import uk.gov.hmrc.excisemovementcontrolsystemapi.utils.DateTimeService.DateTimeFormat

import java.util.UUID

class EISSubmissionConnector @Inject() (
httpClient: HttpClientV2,
Expand All @@ -59,7 +60,18 @@ class EISSubmissionConnector @Inject() (
(hc.withExtraHeaders(HttpHeader.xCorrelationId -> correlationId), correlationId)
}

implicit def errorRead(status: Int): Reads[EISErrorResponseDetails] =
private def internalError(timestamp: Instant, correlationId: String): Either[EISErrorResponseDetails, Nothing] =
Left(
EISErrorResponseDetails(
INTERNAL_SERVER_ERROR,
timestamp,
"Internal server error",
"Unexpected error occurred while processing Submission request",
correlationId
)
)

private def errorRead(status: Int): Reads[EISErrorResponseDetails] =
Json
.reads[EISErrorResponse]
.map(error => EISErrorResponseDetails.createFromEISError(status, dateTimeService.timestamp(), error))
Expand Down Expand Up @@ -94,22 +106,27 @@ class EISSubmissionConnector @Inject() (
if (is2xx(response.status)) {
Right(response.json.as[EISSubmissionResponse])
} else {
Left(response.json.as[EISErrorResponseDetails](errorRead(response.status)))
val errorDetails = response.json.as[EISErrorResponseDetails](errorRead(response.status))
logger.warn(EISErrorMessage(createdDateTime, s"status: ${errorDetails.status}", correlationId, messageType))
Left(errorDetails)
}
}
.andThen { case _ => timer.stop() }
.recover { case NonFatal(ex) =>
logger.warn(EISErrorMessage(createdDateTime, ex.getMessage, correlationId, messageType), ex)
.recover {
case _: JacksonException =>
Copy link
Copy Markdown
Contributor Author

@DavidGregory084 DavidGregory084 Jan 21, 2026

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

JacksonException is the subtype of exceptions we can get from play-json's Json.parse, which is what HttpReads does under the hood

// JSON parsing error
logger.error(EISErrorMessage.parseError(createdDateTime, correlationId, messageType))
internalError(timestamp, correlationId)

case _: JsResultException =>
Copy link
Copy Markdown
Contributor Author

@DavidGregory084 DavidGregory084 Jan 21, 2026

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

JsResultException is the kind of exception we can get from .as[A], .validate[A] and HttpReads' automatic JSON deserialization.

// JSON deserialization error
logger.error(EISErrorMessage.readError(createdDateTime, correlationId, messageType))
internalError(timestamp, correlationId)

Left(
EISErrorResponseDetails(
INTERNAL_SERVER_ERROR,
timestamp,
"Internal server error",
"Unexpected error occurred while processing Submission request",
correlationId
)
)
case NonFatal(ex) =>
// Something else
logger.error(EISErrorMessage(createdDateTime, ex.getMessage, correlationId, messageType), ex)
Copy link
Copy Markdown
Contributor Author

@DavidGregory084 DavidGregory084 Jan 21, 2026

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I am in two minds about the logging of ex.getMessage here - I think that we have covered all of the typical cases where user data could be involved above

internalError(timestamp, correlationId)
}
}

Expand Down
131 changes: 90 additions & 41 deletions app/uk/gov/hmrc/excisemovementcontrolsystemapi/connectors/PreValidateTraderConnector.scala
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -17,12 +17,13 @@
package uk.gov.hmrc.excisemovementcontrolsystemapi.connectors

import com.codahale.metrics.MetricRegistry
import com.fasterxml.jackson.core.JacksonException
import play.api.Logging
import play.api.libs.json.Json
import play.api.http.Status.{BAD_REQUEST, NOT_FOUND, UNAUTHORIZED}
import play.api.libs.json.{JsResultException, Json}
import play.api.mvc.Result
import play.api.mvc.Results.InternalServerError
import play.api.mvc.Results.{InternalServerError, Status}
import uk.gov.hmrc.excisemovementcontrolsystemapi.config.AppConfig
import uk.gov.hmrc.excisemovementcontrolsystemapi.connectors.util.{PreValidateTraderETDSHttpReader, PreValidateTraderHttpReader}
import uk.gov.hmrc.excisemovementcontrolsystemapi.models.EisErrorResponsePresentation
import uk.gov.hmrc.excisemovementcontrolsystemapi.models.eis._
import uk.gov.hmrc.excisemovementcontrolsystemapi.models.preValidateTrader.request.{ExciseTraderETDSRequest, PreValidateTraderRequest}
Expand All @@ -31,8 +32,10 @@ import uk.gov.hmrc.excisemovementcontrolsystemapi.services.HttpHeader
import uk.gov.hmrc.excisemovementcontrolsystemapi.utils.DateTimeService
import uk.gov.hmrc.excisemovementcontrolsystemapi.utils.DateTimeService.DateTimeFormat
import uk.gov.hmrc.http.client.HttpClientV2
import uk.gov.hmrc.http.{HeaderCarrier, HttpReads, StringContextOps}
import uk.gov.hmrc.http.HttpReads.Implicits._
import uk.gov.hmrc.http.{HeaderCarrier, StringContextOps, UpstreamErrorResponse}

import java.time.Instant
import java.util.UUID
import javax.inject.Inject
import scala.concurrent.{ExecutionContext, Future}
Expand All @@ -56,6 +59,14 @@ class PreValidateTraderConnector @Inject() (
(hc.withExtraHeaders(HttpHeader.xCorrelationId -> correlationId), correlationId)
}

private def internalError(timestamp: Instant, correlationId: String) =
EisErrorResponsePresentation(
timestamp,
"Internal Server Error",
"Unexpected error occurred while processing PreValidateTrader request",
correlationId
)

def submitMessage(request: PreValidateTraderRequest, ern: String)(implicit
hc: HeaderCarrier
): Future[Either[Result, PreValidateTraderEISResponse]] = {
Expand All @@ -69,29 +80,44 @@ class PreValidateTraderConnector @Inject() (
val timestamp = dateTimeService.timestamp()
val createdDateTime = timestamp.asStringInMilliseconds

implicit val reader: HttpReads[Either[Result, PreValidateTraderEISResponse]] = PreValidateTraderHttpReader(
correlationId = correlationId,
ern = ern,
createDateTime = createdDateTime,
dateTimeService = dateTimeService
)
httpClient
.post(url"${appConfig.preValidateTraderUrl}")(hc2)
.setHeader(build(correlationId, createdDateTime, appConfig.preValidateTraderBearerToken): _*)
.withBody(Json.toJson(request))
.execute[Either[Result, PreValidateTraderEISResponse]]
.execute[PreValidateTraderEISResponse]
.map(Right.apply[Result, PreValidateTraderEISResponse])
.andThen { case _ => timer.stop() }
.recover { case NonFatal(ex) =>
logger.warn(EISErrorMessage(createdDateTime, ex.getMessage, correlationId, "PreValidateTrader"), ex)

val error = EisErrorResponsePresentation(
timestamp,
"Internal Server Error",
"Unexpected error occurred while processing PreValidateTrader request",
correlationId
)

Left(InternalServerError(Json.toJson(error)))
.recover {
case _: JacksonException =>
// JSON parsing error
logger.error(EISErrorMessage.parseError(createdDateTime, correlationId, "PreValidateTrader"))
Left(InternalServerError(Json.toJson(internalError(timestamp, correlationId))))

case _: JsResultException =>
// JSON deserialization error
logger.error(EISErrorMessage.readError(createdDateTime, correlationId, "PreValidateTrader"))
Left(InternalServerError(Json.toJson(internalError(timestamp, correlationId))))

case response: UpstreamErrorResponse =>
Copy link
Copy Markdown
Contributor Author

@DavidGregory084 DavidGregory084 Jan 21, 2026

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I have essentially inlined the logic of the PreValidateTraderHttpReader here.

I don't think that splitting up this logic was helpful as it just spread all of the possible error handling outcomes across multiple files.

// Upstream error
logger.warn(
EISErrorMessage(createdDateTime, s"status: ${response.statusCode}", correlationId, "PreValidateTrader")
)

//Not expecting EIS response bodies to have any payload here
val ourErrorResponse = EisErrorResponsePresentation(
dateTimeService.timestamp(),
"PreValidateTrader error",
"Error occurred during PreValidateTrader request",
correlationId
)

Left(Status(response.statusCode)(Json.toJson(ourErrorResponse)))
Copy link
Copy Markdown
Contributor Author

@DavidGregory084 DavidGregory084 Jan 21, 2026

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I don't think that we should pass through the response.statusCode here; it would be better if we passed through only 404 responses and otherwise used response.reportAs, which converts client errors to 500 status and server errors to 502 status.

However, I don't really want to change the behaviour of the service in production as users are presumably used to its quirks now.


case NonFatal(ex) =>
// Something else
logger.error(EISErrorMessage(createdDateTime, ex.getMessage, correlationId, "PreValidateTrader"), ex)
Left(InternalServerError(Json.toJson(internalError(timestamp, correlationId))))
}

}
Expand All @@ -109,30 +135,53 @@ class PreValidateTraderConnector @Inject() (
val timestamp = dateTimeService.timestamp()
val createdDateTime = timestamp.asStringInMilliseconds

implicit val reader: HttpReads[Either[Result, ExciseTraderValidationETDSResponse]] =
PreValidateTraderETDSHttpReader(
correlationId = correlationId,
ern = ern,
createDateTime = createdDateTime,
dateTimeService = dateTimeService
)
httpClient
.post(url"${appConfig.preValidateTraderETDSUrl}")(hc2)
.setHeader(buildETDS(correlationId, createdDateTime, appConfig.preValidateTraderETDSBearerToken): _*)
.withBody(Json.toJson(request))
.execute[Either[Result, ExciseTraderValidationETDSResponse]]
.execute[ExciseTraderValidationETDSResponse]
.map(Right.apply[Result, ExciseTraderValidationETDSResponse])
.andThen { case _ => timer.stop() }
.recover { case NonFatal(ex) =>
logger.warn(EISErrorMessage(createdDateTime, ex.getMessage, correlationId, "PreValidateTrader"), ex)

val error = EisErrorResponsePresentation(
timestamp,
"Internal Server Error",
"Unexpected error occurred while processing PreValidateTrader request",
correlationId
)

Left(InternalServerError(Json.toJson(error)))
.recover {
case _: JacksonException =>
// JSON parsing error
logger.error(EISErrorMessage.parseError(createdDateTime, correlationId, "PreValidateTrader"))
Left(InternalServerError(Json.toJson(internalError(timestamp, correlationId))))

case _: JsResultException =>
// JSON deserialization error
logger.error(EISErrorMessage.readError(createdDateTime, correlationId, "PreValidateTrader"))
Left(InternalServerError(Json.toJson(internalError(timestamp, correlationId))))

case response: UpstreamErrorResponse =>
Copy link
Copy Markdown
Contributor Author

@DavidGregory084 DavidGregory084 Jan 21, 2026

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This is the logic of PreValidateTraderETDSHttpReader inlined here

// Upstream error
logger.warn(
EISErrorMessage(createdDateTime, s"status: ${response.statusCode}", correlationId, "PreValidateTrader")
)

val ourErrorResponse = response.statusCode match {
case BAD_REQUEST | NOT_FOUND | UNAUTHORIZED =>
EisErrorResponsePresentation(
dateTimeService.timestamp(),
"PreValidateTrader error",
"Error occurred during PreValidateTrader request",
correlationId
)
case _ =>
EisErrorResponsePresentation(
dateTimeService.timestamp(),
"Internal Server Error",
"Unexpected error occurred while processing PreValidateTrader request",
correlationId
)
}

Left(Status(response.statusCode)(Json.toJson(ourErrorResponse)))
Copy link
Copy Markdown
Contributor Author

@DavidGregory084 DavidGregory084 Jan 21, 2026

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Same comment as above about response.statusCode


case NonFatal(ex) =>
// Something else
logger.error(EISErrorMessage(createdDateTime, ex.getMessage, correlationId, "PreValidateTrader"), ex)
Left(InternalServerError(Json.toJson(internalError(timestamp, correlationId))))
}

}
Expand Down
71 changes: 44 additions & 27 deletions app/uk/gov/hmrc/excisemovementcontrolsystemapi/connectors/PushNotificationConnector.scala
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -16,21 +16,23 @@

package uk.gov.hmrc.excisemovementcontrolsystemapi.connectors

import com.fasterxml.jackson.core.JacksonException
import play.api.Logging
import play.api.http.Status.INTERNAL_SERVER_ERROR
import play.api.http.{HeaderNames, MimeTypes}
import play.api.libs.json.Json
import play.api.libs.json.{JsResultException, Json}
import play.api.mvc.Result
import play.api.mvc.Results.{BadRequest, InternalServerError, NotFound}
import uk.gov.hmrc.excisemovementcontrolsystemapi.config.AppConfig
import uk.gov.hmrc.excisemovementcontrolsystemapi.connectors.util.ResponseHandler
import uk.gov.hmrc.excisemovementcontrolsystemapi.models.eis.EISErrorMessage
import uk.gov.hmrc.excisemovementcontrolsystemapi.models.notification.NotificationResponse._
import uk.gov.hmrc.excisemovementcontrolsystemapi.models.notification._
import uk.gov.hmrc.excisemovementcontrolsystemapi.services.HttpHeader
import uk.gov.hmrc.excisemovementcontrolsystemapi.utils.DateTimeService
import uk.gov.hmrc.http.HttpReads.Implicits._
import uk.gov.hmrc.http.client.HttpClientV2
import uk.gov.hmrc.http.{HeaderCarrier, HttpResponse, StringContextOps}
import uk.gov.hmrc.http.{HeaderCarrier, HttpResponse, StringContextOps, UpstreamErrorResponse}

import java.util.UUID
import javax.inject.Inject
Expand All @@ -54,6 +56,12 @@ class PushNotificationConnector @Inject() (
hc.withExtraHeaders(HttpHeader.xCorrelationId -> correlationId)
}

private def internalError(boxId: String, notification: Notification) =
FailedPushNotification(
INTERNAL_SERVER_ERROR,
s"An exception occurred when sending a notification with excise number: ${notification.ern}, boxId: $boxId, messageId: ${notification.messageId}"
)

def getDefaultBoxId(
clientId: String
)(implicit hc: HeaderCarrier): Future[Either[Result, SuccessBoxNotificationResponse]] = {
Expand Down Expand Up @@ -94,33 +102,42 @@ class PushNotificationConnector @Inject() (
.post(url"$url")(hc2)
.withBody(Json.toJson(notification))
.setHeader(HeaderNames.CONTENT_TYPE -> MimeTypes.JSON)
.execute[HttpResponse]
.execute[SuccessPushNotificationResponse]
.map { response =>
extractIfSuccessful[SuccessPushNotificationResponse](response)
.fold(
error => {
logger.error(
s"[PushNotificationConnector] - error sending notification with boxId: $boxId, status: ${response.status}, message: ${response.body}"
)
FailedPushNotification(error.status, error.body)
},
success => {
logger.info(
s"[PushNotificationConnector] - notification successfully sent to boxId: $boxId, for messageId: ${notification.messageId}"
)
success
}
)
}
.recover { case NonFatal(ex) =>
logger.error(
s"[PushNotificationConnector] - error sending notification with boxId: $boxId error, for messageId: ${notification.messageId}",
ex
)
FailedPushNotification(
INTERNAL_SERVER_ERROR,
s"An exception occurred when sending a notification with excise number: ${notification.ern}, boxId: $boxId, messageId: ${notification.messageId}"
logger.info(
s"[PushNotificationConnector] - notification successfully sent to boxId: $boxId, for messageId: ${notification.messageId}"
)
response
}
.recover {
case _: JacksonException =>
// JSON parsing error
logger.error(
s"[PushNotificationConnector] - error parsing response for notification with boxId: $boxId, for messageId: ${notification.messageId}"
)
internalError(boxId, notification)

case _: JsResultException =>
// JSON deserialization error
logger.error(
s"[PushNotificationConnector] - error deserializing response for notification with boxId: $boxId, for messageId: ${notification.messageId}"
)
internalError(boxId, notification)

case response: UpstreamErrorResponse =>
// Upstream error
logger.error(
s"[PushNotificationConnector] - error sending notification with boxId: $boxId, status: ${response.statusCode}"
)
FailedPushNotification(response.statusCode, response.message)

case NonFatal(ex) =>
// Something else
logger.error(
s"[PushNotificationConnector] - error sending notification with boxId: $boxId error, for messageId: ${notification.messageId}",
ex
)
internalError(boxId, notification)
}
}

Expand Down
Loading