Skip to content

Commit

Permalink
feat: [PAGOPA-2687] Housekeeping on endpoint logs for better request …
Browse files Browse the repository at this point in the history
…tracing (#87)

* [PAGOPA-2687] fix: updated gitignore
* [PAGOPA-2687] fix: refactoring logging for NodoInviaFlussoRendicontazioneFTP
* [PAGOPA-2687] fix: refactoring logging for register-for-validation
* [PAGOPA-2687] feat: refactoring end log, using common logEndProcess method
* reduced log severity (#86)
* [PAGOPA-2687] fix: reducing other unneeded logs and refactored logEndProcess method
* [PAGOPA-2687] fix: refactoring NodoRoute's soapFunction method
* [PAGOPA-2687] fix: removing method for terminate called actor
* [PAGOPA-2687] chore: setting APIConfig's Actor on logback to ERROR

---------

Co-authored-by: pagopa-github-bot <[email protected]>
Co-authored-by: Francesco Cesareo <[email protected]>
  • Loading branch information
3 people authored Feb 27, 2025
1 parent 6fbb324 commit 4f43df8
Show file tree
Hide file tree
Showing 29 changed files with 127 additions and 105 deletions.
1 change: 1 addition & 0 deletions .gitignore
Original file line number Diff line number Diff line change
Expand Up @@ -34,3 +34,4 @@ lightbend.sbt
.run/MainTest dev.run.xml
.run/MainTest local.run.xml
*.tmp
/localresources/config-app-local.conf
Original file line number Diff line number Diff line change
Expand Up @@ -51,7 +51,7 @@ class ActorUtility {
akka.http.scaladsl.model.HttpRequest(method = req.method, uri = req.uri, headers = akkaheaders)
}
val redate = Util.now()
log.info(s"HTTP NODO -> [${req.uri}] will timeout in [${req.timeout.toString}]")
log.debug(s"HTTP NODO -> [${req.uri}] will timeout in [${req.timeout.toString}]")
(for {
httpResponse <- dispatchRequest(req.timeout, req.proxyData, akkaReq, actorProps.httpsConnectionContext)
payload <- Unmarshaller.stringUnmarshaller(httpResponse.entity)
Expand All @@ -76,7 +76,7 @@ class ActorUtility {
),
reExtra = Some(ReExtra(uri = Some(req.uri), httpMethod = Some(req.method.value), soapProtocol = isSoapProtocol))
)
log.info(FdrLogConstant.callBundle(Constant.KeyName.RE_FEEDER))
log.debug(FdrLogConstant.callBundle(Constant.KeyName.RE_FEEDER))
sendReEvent(actorProps, reRequest)
}

Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -53,7 +53,7 @@ trait FuturePerRequestActor extends Actor with NodoLogging {
val f: Future[akka.http.scaladsl.server.RouteResult] = requestContext.complete(m)
f.onComplete(a => donePromise.complete(a))
log.debug(s"FuturePerRequest - DESTROY FutureActorPerRequest [$actorPathName]")
log.info(FdrLogConstant.logEnd(s"[${actorName}] $actorClassId"))
log.debug(FdrLogConstant.logEnd(s"[${actorName}] $actorClassId"))
context.stop(context.self)
}
}
Original file line number Diff line number Diff line change
Expand Up @@ -7,7 +7,9 @@ import eu.sia.pagopa.ActorProps
import eu.sia.pagopa.Main.ConfigData
import eu.sia.pagopa.common.exception
import eu.sia.pagopa.common.exception.{DigitPaErrorCodes, DigitPaException}
import eu.sia.pagopa.common.message.{RestResponse, SoapResponse}
import eu.sia.pagopa.common.repo.Repositories
import eu.sia.pagopa.common.util.FdrLogConstant

import java.util.concurrent.TimeUnit
import scala.concurrent.duration.{FiniteDuration, _}
Expand Down Expand Up @@ -71,4 +73,36 @@ trait PerRequestActor extends Actor with NodoLogging {
actor.ask(req)(BUNDLE_IDLE_TIMEOUT).mapTo[S]
}

def logEndProcess(soapResponse: SoapResponse): Unit = {
soapResponse.throwable match {
case Some(_) => logEndProcess(soapResponse.throwable)
case None => {
if (soapResponse.payload.getOrElse("").contains("fault")) {
log.error(FdrLogConstant.logEndKO(actorClassId, "Error response: [" + soapResponse.payload.getOrElse("Generic error") + "]"))
} else {
log.info(FdrLogConstant.logEndOK(actorClassId))
}
}
}
}

def logEndProcess(restResponse: RestResponse): Unit = {
restResponse.throwable match {
case Some(_) => logEndProcess(restResponse.throwable)
case None => {
if (restResponse.statusCode > 299) {
log.error(FdrLogConstant.logEndKO(actorClassId, "Error response: [" + restResponse.payload.getOrElse("Generic error") + "]"))
} else {
log.info(FdrLogConstant.logEndOK(actorClassId))
}
}
}
}

def logEndProcess(throwable: Option[Throwable]): Unit = {
throwable match {
case Some(ex) => log.error(FdrLogConstant.logEndKO(actorClassId, Some(ex)))
case None => log.info(FdrLogConstant.logEndOK(actorClassId))
}
}
}
10 changes: 3 additions & 7 deletions fdr/src/main/scala/eu/sia/pagopa/common/util/ConfigUtil.scala
Original file line number Diff line number Diff line change
Expand Up @@ -62,7 +62,7 @@ object ConfigUtil {
import scala.concurrent.duration._
val settings = ConnectionPoolSettings(system).withConnectionSettings(ClientConnectionSettings(system).withIdleTimeout(timeout.seconds).withConnectingTimeout(5.seconds))
val uri = s"$apiConfigUrl$path"
log.info(s"calling ApiConfigCache on [$uri]")
log.debug(s"calling ApiConfigCache on [$uri]")
for{
req <- Future.fromTry(Try(HttpRequest(uri = uri, headers = Seq(RawHeader(HEADER_SUBSCRIPTION_KEY, subKey)))))
res <- if (uri.startsWith("https")) {
Expand Down Expand Up @@ -98,15 +98,15 @@ object ConfigUtil {
}

def refreshConfigHttp(actorProps:ActorProps,manual:Boolean)(implicit log: NodoLogger, system: ActorSystem, ex: ExecutionContext): Future[ConfigData] = {
log.info(s"${if(manual) "manual" else "automatic"} refresh config")
log.debug(s"${if(manual) "manual" else "automatic"} refresh config")
if(!reloading){
reloading = true
(for {
res <- callApiConfig(s"?refresh=true", actorProps.httpsConnectionContext)
resDec = decodeResponse(res)
resBody <- Unmarshaller.stringUnmarshaller(resDec.entity)
d = mapper.readValue(resBody, classOf[ConfigData])
_ = log.info("force refresh config done")
_ = log.debug("force refresh config done")
_ = reloading = false
} yield d).recoverWith({
case e=>
Expand All @@ -119,10 +119,6 @@ object ConfigUtil {

}

def getGdeConfigKey(primitiva: String, primitivaType: String): String = {
s"${primitiva}_$primitivaType".toUpperCase
}

def serializeJson(value: Any): String = {
val objmapper = new ObjectMapper().findAndRegisterModules()
objmapper.writeValueAsString(value)
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -8,6 +8,9 @@ object FdrLogConstant {
def logGeneraPayload(pr: String): String = s"Make payload [$pr]"
def logStart(actorClass: String): String = s"Start process [$actorClass]"
def logEnd(actorClass: String): String = s"End process [$actorClass]"
def logEndOK(actorClass: String): String = s"End process [$actorClass] -> [OK]"
def logEndKO(actorClass: String, exception: Option[Throwable]): String = s"End process [$actorClass] -> [KO] ${exception.getOrElse(None)}"
def logEndKO(actorClass: String, exMessage: String): String = s"End process [$actorClass] -> [KO] ${exMessage}"
def jobEnd(actorClass: String, key: String): String = s"End process [$actorClass][$key]"
def callBundle(bundle: String): String = s"Call bundle [$bundle]"
def forward(primitive: String): String = s"Forward [$primitive]"
Expand Down
17 changes: 7 additions & 10 deletions fdr/src/main/scala/eu/sia/pagopa/common/util/web/NodoRoute.scala
Original file line number Diff line number Diff line change
Expand Up @@ -473,8 +473,7 @@ case class NodoRoute(
val payload = Util.faultXmlResponse(dpe.faultCode, dpe.faultString, Some("Internal timeout"))
MDC.put(Constant.MDCKey.SESSION_ID, sessionId)
Util.logPayload(log, Some(payload))
log.debug(s"END request Http for AKKA HTTP TIMEOUT")
log.info(FdrLogConstant.logEnd(Constant.KeyName.SOAP_INPUT))
log.info(FdrLogConstant.logEndKO(Constant.KeyName.SOAP_INPUT, "AKKA HTTP Timeout"))
HttpResponse(status = StatusCodes.ServiceUnavailable, entity = HttpEntity(MediaTypes.`application/xml` withCharset HttpCharsets.`UTF-8`, payload))
}

Expand All @@ -483,8 +482,7 @@ case class NodoRoute(
val payload = Util.faultXmlResponse(dpe.faultCode, dpe.faultString, Some(s"Error, data encoding is not $charset"))
MDC.put(Constant.MDCKey.SESSION_ID, sessionId)
Util.logPayload(log, Some(payload))
log.debug(s"END request Http for AKKA HTTP TIMEOUT")
log.info(FdrLogConstant.logEnd(Constant.KeyName.SOAP_INPUT))
log.info(FdrLogConstant.logEndKO(Constant.KeyName.SOAP_INPUT, "AKKA HTTP Timeout"))
HttpResponse(status = StatusCodes.BadRequest, entity = HttpEntity(MediaTypes.`application/xml` withCharset HttpCharsets.`UTF-8`, payload))
}

Expand All @@ -510,7 +508,6 @@ case class NodoRoute(
path("webservices" / "input") {
val sessionId = UUID.randomUUID().toString
MDC.put(Constant.MDCKey.SESSION_ID, sessionId)
log.info(FdrLogConstant.logStart(Constant.KeyName.SOAP_INPUT))
import scala.concurrent.duration._
val httpSeverRequestTimeout = FiniteDuration(httpSeverRequestTimeoutParam, SECONDS)
withRequestTimeout(httpSeverRequestTimeout, _ => akkaHttpTimeout(sessionId)) {
Expand All @@ -520,7 +517,7 @@ case class NodoRoute(
optionalHeaderValueByName(X_PDD_HEADER) { originalRequestAddresOpt =>
log.debug(s"Request headers:\n${req.headers.map(s => s"${s.name()} => ${s.value()}").mkString("\n")}")
optionalHeaderValueByName("SOAPAction") { soapActionHeader =>
log.info(s"Ricevuta request [${soapActionHeader.getOrElse("No SOAPAction")}] @ ${LocalDateTime.now()}")
log.info(FdrLogConstant.logStart(soapActionHeader.getOrElse(Constant.KeyName.SOAP_INPUT)))
optionalHeaderValueByName("testCaseId") { headerTestCaseId =>
extractRequestContext { ctx =>
entity(as[ByteString]) { bs =>
Expand All @@ -536,7 +533,7 @@ case class NodoRoute(
payloadTry match {
case Success(payload) =>
val request = ctx.request
log.info(s"Content-Type [${request.entity.contentType}]")
log.debug(s"Content-Type [${request.entity.contentType}]")
val soapRouterRequest = SoapRouterRequest(
sessionId,
payload,
Expand Down Expand Up @@ -611,7 +608,7 @@ case class NodoRoute(
private def restRoute(primitiva: String, httpmethod: String, pathParams: Map[String, String]) = {
val sessionId = UUID.randomUUID().toString
MDC.put(Constant.MDCKey.SESSION_ID, sessionId)
log.info(s"Ricevuta request [$sessionId] @ ${LocalDateTime.now()} : [$primitiva]")
log.debug(s"Ricevuta request [$sessionId] @ ${LocalDateTime.now()} : [$primitiva]")
MDC.put(Constant.MDCKey.ACTOR_CLASS_ID, primitiva)
val httpSeverRequestTimeout = FiniteDuration(httpSeverRequestTimeoutParam, SECONDS)
withRequestTimeout(httpSeverRequestTimeout, _ => akkaHttpTimeout(sessionId)) {
Expand All @@ -633,9 +630,9 @@ case class NodoRoute(
})
payloadTry match {
case Success(payload) =>
log.info(FdrLogConstant.logStart(Constant.KeyName.REST_INPUT))
log.info(FdrLogConstant.logStart(if (primitiva != null) primitiva else Constant.KeyName.REST_INPUT))
val request = ctx.request
log.info(s"Content-Type [${request.entity.contentType}]")
log.debug(s"Content-Type [${request.entity.contentType}]")

val restRouterRequest: RestRouterRequest = RestRouterRequest(
sessionId,
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -42,7 +42,7 @@ final case class ApiConfigActor(repositories: Repositories, actorProps: ActorPro
context.system.scheduler.scheduleOnce(scheduleMinutes, self, CheckCache(UUID.randomUUID().toString))
})
case GetCache(_, cacheId) =>
log.info(s"GetCache $cacheId requested")
log.debug(s"GetCache $cacheId requested")
val env = scala.util.Properties.envOrNone("INSTANCE")
(for {
cacheData <- ConfigUtil.getConfigHttp(actorProps.httpsConnectionContext)
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -105,7 +105,7 @@ final case class FdRMetadataActor(repositories: Repositories, actorProps: ActorP
val fdrMetadataEnabled = system.settings.config.getBoolean("fdrMetadataEnabled")
log.debug(s"fdrMetadataEnabled ${fdrMetadataEnabled}")
if (fdrMetadataEnabled) {
log.info(s"FdREventToHistory ${event.retry}")
log.debug(s"FdREventToHistory ${event.retry}")
saveForHistory(event)
context.become(idle) // clear reference after processing
}
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -56,7 +56,7 @@ final case class FtpRetryActorPerRequest(repositories: Repositories, actorProps:
}

override def receive: Receive = { case sch: WorkRequest =>
log.info(s"FTP Retry message received[${sch.sessionId}]")
log.debug(s"FTP Retry message received[${sch.sessionId}]")
replyTo = sender()

val jobName = Jobs.FTP_UPLOAD_RETRY.name
Expand All @@ -76,7 +76,7 @@ final case class FtpRetryActorPerRequest(repositories: Repositories, actorProps:
for {
filesIdServerId <- fdrRepository.findToRetry(Constant.Sftp.RENDICONTAZIONI, maxRetry, timeLimit)
grouped = filesIdServerId.groupBy(_._1)
_ = log.info(s"File summary found to upload:\n${grouped.map(g => s"Server[${g._1}], files number[${g._2.size}]").mkString("\n")}")
_ = log.debug(s"File summary found to upload:\n${grouped.map(g => s"Server[${g._1}], files number[${g._2.size}]").mkString("\n")}")
subreqs = grouped.map(f => FTPRetryRequest(sch.sessionId, Constant.Sftp.RENDICONTAZIONI, f._1, f._2.map(_._2)))
_ <- FutureUtils.groupedSerializeFuture(log, subreqs, 50)(d => uploadFile(d.sessionId, d.messageType, d.ftpServerId, d.fileIds))
_ <- fdrRepository
Expand Down Expand Up @@ -111,7 +111,7 @@ final case class FtpRetryActorPerRequest(repositories: Repositories, actorProps:
}

def uploadFile(sessionId: String, tipo: String, ftpServerId: Long, fileIds: Seq[Long]): Future[Unit] = {
log.info(FdrLogConstant.logStart(actorClassId) + "-per-request")
log.debug(FdrLogConstant.logStart(actorClassId) + "-per-request")

log.debug(s"Received [FTPRetryRequest] [${sessionId}][$tipo]")
val ftpconfigopt =
Expand All @@ -123,7 +123,7 @@ final case class FtpRetryActorPerRequest(repositories: Repositories, actorProps:

val pipeline = for {
ftpconfig <- Future.successful(ftpconfigopt.get._2)
_ = log.info(FdrLogConstant.logSemantico(Constant.KeyName.FTP_RETRY) + "-per-request")
_ = log.debug(FdrLogConstant.logSemantico(Constant.KeyName.FTP_RETRY) + "-per-request")
_ = log.debug(s"File recovery from DB")
files <- fdrRepository.findFtpFilesByIds(fileIds, tipo)

Expand All @@ -149,10 +149,10 @@ final case class FtpRetryActorPerRequest(repositories: Repositories, actorProps:
_ <- SSHFuture.ftp(ssh) { ftp: SSHFtp =>
Future.sequence(filesWithData.map(f => {
Try {
log.info(s"File [${f._3}]")
log.debug(s"File [${f._3}]")
log.debug(s"Destination directory existence check")
createDirs(f._2)(ftp)
log.info(s"File upload in progress")
log.debug(s"File upload in progress")
ftp.putBytes(f._1.content, f._3)
log.debug(s"File upload completed")
} match {
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -42,15 +42,15 @@ final case class FtpSenderActorPerRequest(repositories: Repositories, actorProps

val pipeline = for {
ftpconfig <- Future.successful(ftpconfigopt.get._2)
_ = log.info(FdrLogConstant.logSemantico(Constant.KeyName.FTP_SENDER))
_ = log.debug(FdrLogConstant.logSemantico(Constant.KeyName.FTP_SENDER))
_ <- Future(validateInput(filename))
_ = log.debug(s"File recovery from DB with fileId=[$fileId]")
file <- repositories.fdrRepository.findFtpFileById(fileId, tipo).flatMap {
case Some(b) =>
Future.successful(b)
case None =>
val message = s"File not found on database"
log.info(message)
log.error(message)
Future.failed(DigitPaException(message, DigitPaErrorCodes.PPT_SYSTEM_ERROR))
}
inPath =
Expand All @@ -75,7 +75,7 @@ final case class FtpSenderActorPerRequest(repositories: Repositories, actorProps
Try({
log.debug(s"Destination directory existence check")
createDirs(destpath)(ftp)
log.info(s"File upload in progress")
log.debug(s"File upload in progress")
ftp.putBytes(file.content, destfile)
log.debug(s"File upload completed")
}) match {
Expand All @@ -95,7 +95,7 @@ final case class FtpSenderActorPerRequest(repositories: Repositories, actorProps
Future.successful(FTPResponse(sessionId, testCaseId, Some(DigitPaErrorCodes.PPT_SYSTEM_ERROR)))
}
.map(resp => {
log.info(FdrLogConstant.logEnd(actorClassId))
logEndProcess(resp.throwable)
sendto ! resp
complete()
})
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -62,7 +62,7 @@ case class PollerActor(repositories: Repositories, actorProps: ActorProps) exten
replyTo ! TriggerJobResponse(req.sessionId, SchedulerStatus.OK, Some(s"Job triggered"), req.testCaseId)
})
.recover({ case e =>
log.info(s"job actor terminated with error ${req.job},${e.getMessage}")
log.error(s"job actor terminated with error ${req.job},${e.getMessage}")
replyTo ! TriggerJobResponse(req.sessionId, SchedulerStatus.KO, Some(e.getMessage), req.testCaseId)
})
} else {
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -167,7 +167,7 @@ trait BaseFlussiRendicontazioneActor { this: NodoLogging =>
}

def checks(ddataMap: ConfigData, nodoInviaFlussoRendicontazione: NodoInviaFlussoRendicontazione, checkPassword: Boolean, actorClassId: String)(implicit log: NodoLogger) = {
log.info(FdrLogConstant.logSemantico(actorClassId) + " psp, broker, channel, password, ci")
log.debug(FdrLogConstant.logSemantico(actorClassId) + " psp, broker, channel, password, ci")
val paaa = for {
(psp, canale) <- DDataChecks
.checkPspIntermediarioPspCanale(
Expand All @@ -192,7 +192,7 @@ trait BaseFlussiRendicontazioneActor { this: NodoLogging =>
}

def checkFormatoIdFlussoRendicontazione(identificativoFlusso: String, idPsp: String, actorClassId: String)(implicit log: NodoLogger) = {
log.info(FdrLogConstant.logSemantico(actorClassId) + " checkFormatoIdFlussoRendicontazione")
log.debug(FdrLogConstant.logSemantico(actorClassId) + " checkFormatoIdFlussoRendicontazione")
(for {
_ <- CheckRendicontazioni.checkFormatoIdFlussoRendicontazione(identificativoFlusso, idPsp)
} yield ()).recoverWith({
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -56,7 +56,7 @@ case class GetAllRevisionFdrActorPerRequest(repositories: Repositories, actorPro

(for {
_ <- Future.successful(())
_ = log.info(FdrLogConstant.logSintattico(actorClassId))
_ = log.debug(FdrLogConstant.logSintattico(actorClassId))

organizationId = req.pathParams("organizationId")
fdr = req.pathParams("fdr")
Expand Down Expand Up @@ -119,7 +119,7 @@ case class GetAllRevisionFdrActorPerRequest(repositories: Repositories, actorPro
Future.successful(generateErrorResponse(Some(pmae)))
}).map( res => {
callTrace(traceInterfaceRequest, reActor, req, reFlow.get, req.reExtra)
log.info(FdrLogConstant.logEnd(actorClassId))
logEndProcess(res)
replyTo ! res
complete()
})
Expand Down Expand Up @@ -159,15 +159,15 @@ case class GetAllRevisionFdrActorPerRequest(repositories: Repositories, actorPro
}

private def generateErrorResponse(exception: Option[RestException]) = {
log.info(FdrLogConstant.logGeneraPayload(actorClassId + "Response"))
log.debug(FdrLogConstant.logGeneraPayload(actorClassId + "Response"))
val httpStatusCode = exception.map(_.statusCode).getOrElse(StatusCodes.OK.intValue)
log.debug(s"Generating response $httpStatusCode")
val payload = exception.map(v => Error(v.getMessage).toJson.toString())
RestResponse(req.sessionId, payload, httpStatusCode, reFlow, req.testCaseId, exception)
}

private def generateErrorResponseFromSoap(exception: Option[Exception]) = {
log.info(FdrLogConstant.logGeneraPayload(actorClassId + "Response"))
log.debug(FdrLogConstant.logGeneraPayload(actorClassId + "Response"))
val httpStatusCode = StatusCodes.BadRequest.intValue
log.debug(s"Generating response $httpStatusCode")
val payload = exception.map(v => Error(v.getMessage).toJson.toString())
Expand Down
Loading

0 comments on commit 4f43df8

Please sign in to comment.