Skip to content

Commit b93e574

Browse files
marjisoundmarjisound
committed
Include request ID in almost all logs generated during the request journey
1 parent 968f3f2 commit b93e574

30 files changed

+106
-75
lines changed

‎admin/app/controllers/admin/SwitchboardController.scala

+6-6
Original file line numberDiff line numberDiff line change
@@ -24,7 +24,7 @@ class SwitchboardController(
2424

2525
def renderSwitchboard(): Action[AnyContent] =
2626
Action.async { implicit request =>
27-
log.info("loaded Switchboard")
27+
logInfoWithRequestId("loaded Switchboard")
2828

2929
Future { Store.getSwitchesWithLastModified } map { switchesWithLastModified =>
3030
val configuration = switchesWithLastModified.map(_._1)
@@ -57,7 +57,7 @@ class SwitchboardController(
5757
)
5858
}
5959
} else {
60-
log.info("saving switchboard")
60+
logInfoWithRequestId("saving switchboard")
6161

6262
val requester: String =
6363
auth.readAuthenticatedUser(request) map (authed =>
@@ -75,27 +75,27 @@ class SwitchboardController(
7575
}
7676
}
7777

78-
private def saveSwitchesOrError(requester: String, updates: Seq[String]): Result =
78+
private def saveSwitchesOrError(requester: String, updates: Seq[String])(implicit request: RequestHeader): Result =
7979
try {
8080
val current = Switches.all map { switch =>
8181
switch.name + "=" + (if (switch.isSwitchedOn) "on" else "off")
8282
}
8383

8484
Store.putSwitches(updates mkString "\n")
8585

86-
log.info("switches successfully updated")
86+
logInfoWithRequestId("switches successfully updated")
8787

8888
val changes = updates filterNot { current contains _ }
8989
changes foreach { change =>
90-
log.info(s"Switch change by $requester: $change")
90+
logInfoWithRequestId(s"Switch change by $requester: $change")
9191
}
9292

9393
Redirect(routes.SwitchboardController.renderSwitchboard()).flashing(
9494
"success" -> changes.mkString("; "),
9595
)
9696
} catch {
9797
case e: Throwable =>
98-
log.error("exception saving switches", e)
98+
logErrorWithRequestId("exception saving switches", e)
9999

100100
Redirect(routes.SwitchboardController.renderSwitchboard()).flashing(
101101
"error" -> ("Error saving switches '%s'" format e.getMessage),

‎admin/app/controllers/admin/commercial/AdsDotTextEditController.scala

+1-1
Original file line numberDiff line numberDiff line change
@@ -50,7 +50,7 @@ class AdsDotTextEditController(val controllerComponents: ControllerComponents)(i
5050
},
5151
adsTextSellers => {
5252
S3.putPrivate(s3DotTextKey, adsTextSellers.sellers, "text/plain")
53-
log.info(s"Wrote new $name file to $s3DotTextKey")
53+
logInfoWithRequestId(s"Wrote new $name file to $s3DotTextKey")
5454
NoCache(Redirect(postSave))
5555
},
5656
)

‎admin/app/football/services/Client.scala

+3-4
Original file line numberDiff line numberDiff line change
@@ -5,15 +5,14 @@ import play.api.libs.ws.WSClient
55
import play.api.{Environment, Mode}
66
import org.joda.time.LocalDate
77
import java.io.File
8-
98
import scala.util.{Failure, Success}
109
import play.api.Logger
11-
1210
import common.GuLogging
1311
import pa.{Http, PaClient, PaClientErrorsException, Response, Season, Team}
1412
import conf.AdminConfiguration
1513
import football.model.PA
1614
import model.ApplicationContext
15+
import play.api.mvc.RequestHeader
1716

1817
trait Client extends PaClient with Http {
1918

@@ -94,13 +93,13 @@ trait PaFootballClient {
9493
lazy val client: Client =
9594
if (context.environment.mode == Mode.Test) TestClient(wsClient, context.environment) else RealClient(wsClient)
9695

97-
def fetchCompetitionsAndTeams: Future[(List[Season], List[Team])] =
96+
def fetchCompetitionsAndTeams(implicit request: RequestHeader): Future[(List[Season], List[Team])] =
9897
for {
9998
competitions <- client.competitions.map(PA.filterCompetitions)
10099
competitionTeams <- Future.traverse(competitions) { comp =>
101100
client.teams(comp.competitionId, comp.startDate, comp.endDate).recover { case e: PaClientErrorsException =>
102101
// 'No data' is returned as an error by PA API. Therefore we ignore exception and return an empty list
103-
log.error(s"PA Client error when fetching teams for competition $comp: ", e)
102+
logErrorWithRequestId(s"PA Client error when fetching teams for competition $comp: ", e)
104103
List()
105104
}
106105
}

‎applications/app/controllers/AllIndexController.scala

+4-4
Original file line numberDiff line numberDiff line change
@@ -172,9 +172,9 @@ class AllIndexController(
172172

173173
result.failed.foreach {
174174
case ContentApiError(404, _, _) =>
175-
log.warn(s"Cannot fetch content for request '${request.uri}'")
175+
logWarnWithRequestId(s"Cannot fetch content for request '${request.uri}'")
176176
case e: Exception =>
177-
log.error(e.getMessage, e)
177+
logErrorWithRequestId(e.getMessage, e)
178178
}
179179

180180
result
@@ -196,9 +196,9 @@ class AllIndexController(
196196

197197
result.failed.foreach {
198198
case ContentApiError(404, _, _) =>
199-
log.warn(s"Cannot fetch content for request '${request.uri}'")
199+
logWarnWithRequestId(s"Cannot fetch content for request '${request.uri}'")
200200
case e: Exception =>
201-
log.error(e.getMessage, e)
201+
logErrorWithRequestId(e.getMessage, e)
202202
}
203203

204204
result

‎applications/app/controllers/AtomPageController.scala

+3-3
Original file line numberDiff line numberDiff line change
@@ -72,7 +72,7 @@ class AtomPageController(
7272
.bindFromRequest()
7373
.fold(
7474
formWithErrors => {
75-
log.info(s"Form has been submitted with errors: ${formWithErrors.errors}")
75+
logInfoWithRequestId(s"Form has been submitted with errors: ${formWithErrors.errors}")
7676
Future.successful(Cors(NoCache(BadRequest("Invalid email"))))
7777
},
7878
form => {
@@ -83,12 +83,12 @@ class AtomPageController(
8383
Cors(NoCache(Created("Subscribed")))
8484

8585
case status =>
86-
log.error(s"Error posting to ExactTarget: HTTP $status")
86+
logErrorWithRequestId(s"Error posting to ExactTarget: HTTP $status")
8787
Cors(NoCache(InternalServerError("Internal error")))
8888

8989
})
9090
.recover { case e: Exception =>
91-
log.error(s"Error posting to ExactTarget: ${e.getMessage}")
91+
logErrorWithRequestId(s"Error posting to ExactTarget: ${e.getMessage}")
9292
Cors(NoCache(InternalServerError("Internal error")))
9393
}
9494
},

‎applications/app/controllers/CrosswordsController.scala

+1-1
Original file line numberDiff line numberDiff line change
@@ -65,7 +65,7 @@ trait CrosswordController extends BaseController with GuLogging with ImplicitCon
6565
} yield f(crossword, content)
6666
maybeCrossword getOrElse Future.successful(noResults())
6767
} recover { case t: Throwable =>
68-
log.error(s"Error retrieving $crosswordType crossword id $id from API", t)
68+
logErrorWithRequestId(s"Error retrieving $crosswordType crossword id $id from API", t)
6969
noResults()
7070
}
7171
}

‎applications/app/controllers/EmbedController.scala

+1-1
Original file line numberDiff line numberDiff line change
@@ -25,7 +25,7 @@ class EmbedController(contentApiClient: ContentApiClient, val controllerComponen
2525
private def lookup(path: String)(implicit request: RequestHeader): Future[Either[Result, Video]] = {
2626
val edition = Edition(request)
2727

28-
log.info(s"Fetching video: $path for edition $edition")
28+
logInfoWithRequestId(s"Fetching video: $path for edition $edition")
2929

3030
val response: Future[ItemResponse] = contentApiClient.getResponse(
3131
contentApiClient

‎applications/app/controllers/GalleryController.scala

+2-1
Original file line numberDiff line numberDiff line change
@@ -83,7 +83,8 @@ class GalleryController(
8383
request: RequestHeader,
8484
): Future[Either[Result, (GalleryPage, Blocks)]] = {
8585
val edition = Edition(request)
86-
log.info(s"Fetching gallery: $path for edition $edition")
86+
logInfoWithRequestId(s"Fetching gallery: $path for edition $edition")
87+
8788
contentApiClient
8889
.getResponse(
8990
contentApiClient

‎applications/app/controllers/LatestIndexController.scala

+1-1
Original file line numberDiff line numberDiff line change
@@ -100,7 +100,7 @@ class LatestIndexController(contentApiClient: ContentApiClient, val controllerCo
100100
}
101101

102102
result recover { case e: Exception =>
103-
log.error(e.getMessage, e)
103+
logErrorWithRequestId(e.getMessage, e)
104104
None
105105
}
106106
}

‎applications/app/controllers/MediaController.scala

+3-2
Original file line numberDiff line numberDiff line change
@@ -9,7 +9,7 @@ import implicits.{AppsFormat, JsonFormat}
99
import model._
1010
import model.dotcomrendering.{DotcomRenderingDataModel, PageType}
1111
import pages.ContentHtmlPage
12-
import play.api.libs.json.{Format, JsObject, Json, JsValue}
12+
import play.api.libs.json.{Format, JsObject, JsValue, Json}
1313
import play.api.libs.ws.WSClient
1414
import play.api.mvc._
1515
import renderers.DotcomRenderingService
@@ -58,7 +58,8 @@ class MediaController(
5858
private def lookup(path: String)(implicit request: RequestHeader): Future[Either[Result, (MediaPage, Blocks)]] = {
5959
val edition = Edition(request)
6060

61-
log.info(s"Fetching media: $path for edition $edition")
61+
logInfoWithRequestId(s"Fetching media: $path for edition $edition")
62+
6263
val response: Future[ItemResponse] = contentApiClient.getResponse(
6364
contentApiClient
6465
.item(path, edition)

‎applications/app/controllers/QuizController.scala

+2-2
Original file line numberDiff line numberDiff line change
@@ -55,7 +55,7 @@ class QuizController(
5555
hasErrors = errors => {
5656
val errorMessages = errors.errors.flatMap(_.messages.mkString(", ")).mkString(". ")
5757
val serverError = s"Problem with quiz form request: $errorMessages"
58-
log.error(serverError)
58+
logErrorWithRequestId(serverError)
5959
Future.successful(InternalServerError(serverError))
6060
},
6161
success = form => renderQuiz(quizId, path, form),
@@ -67,7 +67,7 @@ class QuizController(
6767
): Future[Result] = {
6868
val edition = Edition(request)
6969

70-
log.info(s"Fetching quiz atom: $quizId from content id: $path")
70+
logInfoWithRequestId(s"Fetching quiz atom: $quizId from content id: $path")
7171
val capiQuery = contentApiClient.item(path, edition).showAtoms("all")
7272
val result = contentApiClient.getResponse(capiQuery) map { itemResponse =>
7373
val maybePage: Option[QuizAnswersPage] = itemResponse.content.flatMap { content =>

‎applications/app/controllers/SignupPageController.scala

+3-3
Original file line numberDiff line numberDiff line change
@@ -50,7 +50,7 @@ class SignupPageController(
5050
),
5151
)
5252
case Left(e) =>
53-
log.error(s"API call to get newsletters failed: $e")
53+
logErrorWithRequestId(s"API call to get newsletters failed: $e")
5454
Future(NoCache(InternalServerError))
5555
}
5656
}
@@ -72,7 +72,7 @@ class SignupPageController(
7272
page = StaticPages.dcrSimpleNewsletterPage(request.path),
7373
)
7474
case Left(e) =>
75-
log.error(s"API call to get newsletters failed: $e")
75+
logErrorWithRequestId(s"API call to get newsletters failed: $e")
7676
Future(NoCache(InternalServerError))
7777
}
7878
}
@@ -93,7 +93,7 @@ class SignupPageController(
9393
Future.successful(common.renderJson(dataJson, page).as("application/json"))
9494
}
9595
case Left(e) =>
96-
log.error(s"API call to get newsletters failed: $e")
96+
logErrorWithRequestId(s"API call to get newsletters failed: $e")
9797
throw new RuntimeException()
9898
}
9999
}

‎applications/app/controllers/TagIndexController.scala

+2-2
Original file line numberDiff line numberDiff line change
@@ -18,11 +18,11 @@ class TagIndexController(val controllerComponents: ControllerComponents)(implici
1818
Action { implicit request =>
1919
TagIndexesS3.getIndex(keywordType, page) match {
2020
case Left(TagIndexNotFound) =>
21-
log.error(s"404 error serving tag index page for $keywordType $page")
21+
logErrorWithRequestId(s"404 error serving tag index page for $keywordType $page")
2222
NotFound
2323

2424
case Left(TagIndexReadError(error)) =>
25-
log.error(s"JSON parse error serving tag index page for $keywordType $page: $error")
25+
logErrorWithRequestId(s"JSON parse error serving tag index page for $keywordType $page: $error")
2626
InternalServerError
2727

2828
case Right(tagIndex) =>

‎applications/app/controllers/YoutubeController.scala

+1-1
Original file line numberDiff line numberDiff line change
@@ -29,7 +29,7 @@ class YoutubeController(
2929
response.transform {
3030
case result @ Success(_) => result
3131
case Failure(error) =>
32-
log.error(s"Failed to get atom ID for youtube ID $youtubeId", error)
32+
logErrorWithRequestId(s"Failed to get atom ID for youtube ID $youtubeId", error)
3333
Failure(error)
3434
}
3535
}

‎applications/app/services/ImageQuery.scala

+1-1
Original file line numberDiff line numberDiff line change
@@ -16,7 +16,7 @@ trait ImageQuery extends ConciergeRepository {
1616
request: RequestHeader,
1717
context: ApplicationContext,
1818
): Future[Either[PlayResult, (ImageContentPage, Option[Block])]] = {
19-
log.info(s"Fetching image content: $path for edition ${edition.id}")
19+
logInfoWithRequestId(s"Fetching image content: $path for edition ${edition.id}")
2020
val response = contentApiClient.getResponse(
2121
contentApiClient
2222
.item(path, edition)

‎archive/app/controllers/ArchiveController.scala

+1-11
Original file line numberDiff line numberDiff line change
@@ -126,20 +126,10 @@ class ArchiveController(redirects: RedirectService, val controllerComponents: Co
126126
val endOfPath = if (pathSuffixes.isEmpty) "" else s"/${pathSuffixes.mkString("/")}"
127127
val redirect = LinkTo(path) + endOfPath
128128

129-
log.info(s"""Archive $redirectHttpStatus, redirect to $redirect""")
129+
logInfoWithRequestId(s"""Archive $redirectHttpStatus, redirect to $redirect""")
130130
Cached(CacheTime.ArchiveRedirect)(WithoutRevalidationResult(Redirect(redirect, redirectHttpStatus)))
131131
}
132132

133-
private def log404(request: Request[AnyContent]) = {
134-
log.warn(s"Archive returned 404 for path: ${request.path}")
135-
136-
val GoogleBot = """.*(Googlebot).*""".r
137-
request.headers.get("User-Agent").getOrElse("no user agent") match {
138-
case GoogleBot(_) => GoogleBotMetric.Googlebot404Count.increment()
139-
case _ =>
140-
}
141-
}
142-
143133
private def lookupPath(path: String)(implicit request: RequestHeader): Future[Option[CacheableResult]] =
144134
destinationFor(path).map { _.flatMap(processLookupDestination(path).lift) }
145135

‎article/app/controllers/ArticleController.scala

+1-1
Original file line numberDiff line numberDiff line change
@@ -67,7 +67,7 @@ class ArticleController(
6767
headline
6868
.map(s => Cached(CacheTime.Default)(RevalidatableResult.Ok(s)))
6969
.getOrElse {
70-
log.warn(s"headline not found for $path")
70+
logWarnWithRequestId(s"headline not found for $path")
7171
Cached(10)(WithoutRevalidationResult(NotFound))
7272
}
7373
}

‎article/app/controllers/LiveBlogController.scala

+2-2
Original file line numberDiff line numberDiff line change
@@ -395,12 +395,12 @@ class LiveBlogController(
395395
*/
396396
val hasBlocks = nonLiveBlogArticle.fields.blocks.nonEmpty;
397397
val hasMinuteByMinuteTag = nonLiveBlogArticle.tags.isLiveBlog;
398-
log.error(
398+
logErrorWithRequestId(
399399
s"Requested non-liveblog article as liveblog: ${nonLiveBlogArticle.metadata.id}: { hasBlocks: ${hasBlocks}, hasMinuteByMinuteTag: ${hasMinuteByMinuteTag} }",
400400
)
401401
Left(InternalServerError)
402402
case unknown =>
403-
log.error(s"Requested non-liveblog: ${unknown.metadata.id}")
403+
logErrorWithRequestId(s"Requested non-liveblog: ${unknown.metadata.id}")
404404
Left(InternalServerError)
405405
}
406406

‎commercial/app/controllers/ContentApiOffersController.scala

+2-2
Original file line numberDiff line numberDiff line change
@@ -37,13 +37,13 @@ class ContentApiOffersController(
3737
.getOrElse(Future.successful(Nil))
3838

3939
latestContent.failed.foreach { case NonFatal(e) =>
40-
log.error(s"Looking up content by keyword failed: ${e.getMessage}")
40+
logErrorWithRequestId(s"Looking up content by keyword failed: ${e.getMessage}")
4141
}
4242

4343
val specificContent: Future[Seq[model.ContentType]] = capiAgent.contentByShortUrls(specificIds)
4444

4545
specificContent.failed.foreach { case NonFatal(e) =>
46-
log.error(s"Looking up content by short URL failed: ${e.getMessage}")
46+
logErrorWithRequestId(s"Looking up content by short URL failed: ${e.getMessage}")
4747
}
4848

4949
val futureContents = for {

‎common/app/common/GuLogging.scala

+39
Original file line numberDiff line numberDiff line change
@@ -5,6 +5,8 @@ import play.api.Logger
55
import org.apache.commons.lang.exception.ExceptionUtils
66
import net.logstash.logback.marker.LogstashMarker
77
import net.logstash.logback.marker.Markers._
8+
import play.api.mvc.RequestHeader
9+
810
import scala.jdk.CollectionConverters._
911
import scala.concurrent.{ExecutionContext, Future}
1012
import scala.language.implicitConversions
@@ -18,6 +20,43 @@ trait GuLogging {
1820
log.error(ExceptionUtils.getStackTrace(e))
1921
}
2022

23+
def logInfoWithRequestId(message: String)(implicit request: RequestHeader): Unit = {
24+
log.logger.info(
25+
customFieldMarkers(List("requestId" -> request.headers.get("x-gu-xid").getOrElse("request-id-not-provided"))),
26+
message,
27+
)
28+
}
29+
30+
def logWarnWithRequestId(message: String)(implicit request: RequestHeader): Unit = {
31+
log.logger.warn(
32+
customFieldMarkers(List("requestId" -> request.headers.get("x-gu-xid").getOrElse("request-id-not-provided"))),
33+
message,
34+
)
35+
}
36+
37+
def logWarnWithRequestId(message: String, error: Throwable)(implicit request: RequestHeader): Unit = {
38+
log.logger.warn(
39+
customFieldMarkers(List("requestId" -> request.headers.get("x-gu-xid").getOrElse("request-id-not-provided"))),
40+
message,
41+
error,
42+
)
43+
}
44+
45+
def logErrorWithRequestId(message: String)(implicit request: RequestHeader): Unit = {
46+
log.logger.error(
47+
customFieldMarkers(List("requestId" -> request.headers.get("x-gu-xid").getOrElse("request-id-not-provided"))),
48+
message,
49+
)
50+
}
51+
52+
def logErrorWithRequestId(message: String, error: Throwable)(implicit request: RequestHeader): Unit = {
53+
log.logger.error(
54+
customFieldMarkers(List("requestId" -> request.headers.get("x-gu-xid").getOrElse("request-id-not-provided"))),
55+
message,
56+
error,
57+
)
58+
}
59+
2160
def logInfoWithCustomFields(message: String, customFields: List[LogField]): Unit = {
2261
log.logger.info(customFieldMarkers(customFields), message)
2362
}

‎common/app/common/ModelOrResult.scala

+1-1
Original file line numberDiff line numberDiff line change
@@ -84,7 +84,7 @@ object InternalRedirect extends implicits.Requests with GuLogging {
8484
case g if g.isGallery => internalRedirect("applications", g.id)
8585
case a if a.isAudio => internalRedirect("applications", a.id)
8686
case unsupportedContent =>
87-
log.info(s"unsupported content: ${unsupportedContent.id}")
87+
logInfoWithRequestId(s"unsupported content: ${unsupportedContent.id}")
8888
NotFound
8989

9090
}

0 commit comments

Comments
 (0)