diff --git a/logging.md b/logging.md new file mode 100644 index 00000000..6831871d --- /dev/null +++ b/logging.md @@ -0,0 +1,40 @@ +# Logging + +We want traceability from HTTP calls. +- Each HTTP call needs to generate a call ID (preferable on the proxy). This ID must be should be pass to the scope of the ZIO application. So every log will mention this ID. This ID must also be returned to the user as a HTTP header. +- In case of errors and problem reports those IDs can be use by the user to get support. + +Level 3 support can be provided to user during the logging retention policies. We user need to provide the value in the header `X-Request-Id` to get this support. + +## Annotates + +We have special annotations in the log so there is traceability between the different logs. +Here is the list of annotations and their meaning that we currently have: + +- `request-id` - Is the HTTP header `X-Request-Id` from the caller. + - If this header is missing, it is create by the APISIX https://apisix.apache.org/docs/apisix/plugins/request-id/. See the configuration how to enable in the file [apisixroute.yaml](https://github.com/input-output-hk/atala-prism-mediator/blob/eb6d822f125bea7b3da8f[…]0a378/infrastructure/charts/mediator/templates/apisixroute.yaml) +- `msg_sha256` - Is the Hash (sha256) of the DID Comm message + +## Code + +To have a concise code we have created a Middleware that modifies the Annotations in the Scope before each execution of that endpoint, to include the trace ID of the request. +See code in file `TraceIdMiddleware` (`mediator/src/main/scala/io/iohk/atala/mediator/TraceIdMiddleware.scala`). + +## Logging Backend + +We use the Simple Logging Facade for Java (SLF4J) API to call the logging backend is determined at runtime. + +### Logging Pattern + +`%d{yyyy-MM-dd_HH:mm:ss.SSS} %highlight(%-5level) %cyan(%logger{5}@L%line:[%-4.30thread]) {%mdc} - %msg%xException%n` + +- `%d{yyyy-MM-dd_HH:mm:ss.SSS}` is the date/timestamp of the log in the human-readable way +- `%highlight(%-5level)` the log level +- `%cyan(%logger{5}@L%line:[%-4.30thread])` + - `%cyan` - Is just modify the color to make easy to read + - `%logger{5}` - class name that originated the log + - `@L%line` - line of the code that originated the log + - `%-4.30thread` - the id of the thread. The ZIO fiber name +- `%mdc` - the mapped diagnostic context [MDC](https://logback.qos.ch/manual/layouts.html#mdc) +- `%msg` - the log message +- `%xException` - exception info diff --git a/mediator/src/main/resources/logback.xml b/mediator/src/main/resources/logback.xml index adefab30..8a20ab7c 100644 --- a/mediator/src/main/resources/logback.xml +++ b/mediator/src/main/resources/logback.xml @@ -3,8 +3,7 @@ true - - %d{yyyy-MM-dd_HH:mm:ss.SSS} [%highlight(%-5level)] %cyan(%logger{5}@L%line:[%-4.30thread]) %mdc - %msg%xException%n + %d{yyyy-MM-dd_HH:mm:ss.SSS} %highlight(%-5level) %cyan(%logger{5}@L%line:[%-4.30thread]) {%mdc} - %msg%xException%n diff --git a/mediator/src/main/scala/io/iohk/atala/mediator/AgentExecutorMediator.scala b/mediator/src/main/scala/io/iohk/atala/mediator/AgentExecutorMediator.scala index 49a69da6..42e425fa 100644 --- a/mediator/src/main/scala/io/iohk/atala/mediator/AgentExecutorMediator.scala +++ b/mediator/src/main/scala/io/iohk/atala/mediator/AgentExecutorMediator.scala @@ -20,8 +20,8 @@ case class AgentExecutorMediator( protocolHandler: ProtocolExecuter[OperatorImp.Services, MediatorError | StorageError], userAccountRepo: UserAccountRepo, messageItemRepo: MessageItemRepo, + scope: Scope, ) extends AgentExecutar { - val scope = Scope.global // TODO do not use global val indentityLayer = ZLayer.succeed(agent) val userAccountRepoLayer = ZLayer.succeed(userAccountRepo) val messageItemRepoLayer = ZLayer.succeed(messageItemRepo) @@ -251,7 +251,6 @@ case class AgentExecutorMediator( } } yield () } yield () - } object AgentExecutorMediator { @@ -261,11 +260,20 @@ object AgentExecutorMediator { protocolHandler: ProtocolExecuter[OperatorImp.Services, MediatorError | StorageError], userAccountRepo: UserAccountRepo, messageItemRepo: MessageItemRepo, + scope: Scope, ): ZIO[TransportFactory, Nothing, AgentExecutar] = for { _ <- ZIO.logInfo(s"Make Madiator AgentExecutor for ${agent.id}") transportManager <- MediatorTransportManager.make - mediator = AgentExecutorMediator(agent, transportManager, protocolHandler, userAccountRepo, messageItemRepo) + + mediator = AgentExecutorMediator( + agent, + transportManager, + protocolHandler, + userAccountRepo, + messageItemRepo, + scope + ) } yield mediator // TODO move to another place & move validations and build a contex diff --git a/mediator/src/main/scala/io/iohk/atala/mediator/DIDCommRoutes.scala b/mediator/src/main/scala/io/iohk/atala/mediator/DIDCommRoutes.scala index e6b74a6c..dcbbede4 100644 --- a/mediator/src/main/scala/io/iohk/atala/mediator/DIDCommRoutes.scala +++ b/mediator/src/main/scala/io/iohk/atala/mediator/DIDCommRoutes.scala @@ -16,7 +16,7 @@ import fmgp.did.method.peer.DIDPeer.AgentDIDPeer object DIDCommRoutes { - def app: HttpApp[Operator & Operations & Resolver] = routes.toHttpApp + def app: HttpApp[Operator & Operations & Resolver & Scope] = routes.@@(TraceIdMiddleware.addTraceId).toHttpApp def routes: Routes[Operator & Operations & Resolver, Nothing] = Routes( Method.GET / "ws" -> handler { (req: Request) => @@ -75,7 +75,6 @@ object DIDCommRoutes { .tapErrorCause(ZIO.logErrorCause("Error", _)) .catchAllCause(cause => ZIO.succeed(Response.fromCause(cause))) case Some(_) | None => ZIO.succeed(Response.badRequest(s"The content-type must be $SignedTyp or $EncryptedTyp")) - }, ) } diff --git a/mediator/src/main/scala/io/iohk/atala/mediator/MediatorAgent.scala b/mediator/src/main/scala/io/iohk/atala/mediator/MediatorAgent.scala index 111a4969..7de4d47c 100644 --- a/mediator/src/main/scala/io/iohk/atala/mediator/MediatorAgent.scala +++ b/mediator/src/main/scala/io/iohk/atala/mediator/MediatorAgent.scala @@ -30,9 +30,11 @@ case class MediatorAgent( object MediatorAgent { + def didCommApp = didCommAppAux.@@(TraceIdMiddleware.addTraceId).toHttpApp + def make(id: DID, keyStore: KeyStore): ZIO[Any, Nothing, MediatorAgent] = ZIO.succeed(MediatorAgent(id, keyStore)) - def didCommApp = { + def didCommAppAux = { Routes( Method.GET / "headers" -> handler { (req: Request) => val data = req.headers.toSeq.map(e => (e.headerName, e.renderedValue)) @@ -99,6 +101,6 @@ object MediatorAgent { Handler.fromResource(fullPath).map(_.addHeader(headerContentType)) }.flatten ) - }.sandbox.toHttpApp + }.sandbox } diff --git a/mediator/src/main/scala/io/iohk/atala/mediator/MediatorStandalone.scala b/mediator/src/main/scala/io/iohk/atala/mediator/MediatorStandalone.scala index b2b36c1f..44e7b64a 100644 --- a/mediator/src/main/scala/io/iohk/atala/mediator/MediatorStandalone.scala +++ b/mediator/src/main/scala/io/iohk/atala/mediator/MediatorStandalone.scala @@ -55,10 +55,10 @@ object MediatorStandalone extends ZIOAppDefault { allAnnotations |-| cause.highlight - // override val bootstrap: ZLayer[ZIOAppArgs, Any, Any] = - // Runtime.removeDefaultLoggers >>> SLF4J.slf4j(mediatorColorFormat) + override val bootstrap: ZLayer[ZIOAppArgs, Any, Any] = + Runtime.removeDefaultLoggers >>> SLF4J.slf4j(mediatorColorFormat) - override val run = for { + def mainProgram = for { _ <- Console.printLine( // https://patorjk.com/software/taag/#p=display&f=ANSI%20Shadow&t=Mediator """███╗ ███╗███████╗██████╗ ██╗ █████╗ ████████╗ ██████╗ ██████╗ |████╗ ████║██╔════╝██╔══██╗██║██╔══██╗╚══██╔══╝██╔═══██╗██╔══██╗ @@ -88,25 +88,17 @@ object MediatorStandalone extends ZIOAppDefault { .nested("problem") .nested("mediator") .load(Config.string("escalateTo")) - _ <- ZIO.log(s"Problem reports escalated to : $escalateTo") + _ <- ZIO.log(s"Problem reports escalated to: $escalateTo") transportFactory = Scope.default >>> (Client.default >>> TransportFactoryImp.layer) - repos = { - AsyncDriverResource.layer - >>> ReactiveMongoApi.layer(mediatorDbConfig.connectionString) - >>> (MessageItemRepo.layer ++ UserAccountRepo.layer) - } - // inboundHub <- Hub.bounded[String](5) + mongo = AsyncDriverResource.layer >>> ReactiveMongoApi.layer(mediatorDbConfig.connectionString) + repos = mongo >>> (MessageItemRepo.layer ++ UserAccountRepo.layer ++ OutboxMessageRepo.layer) myServer <- Server .serve((MediatorAgent.didCommApp ++ DIDCommRoutes.app) @@ (Middleware.cors)) .provideSomeLayer(DidPeerResolver.layerDidPeerResolver) .provideSomeLayer(agentLayer) - .provideSomeLayer((agentLayer ++ transportFactory ++ repos) >>> OperatorImp.layer) - .provideSomeLayer( - AsyncDriverResource.layer - >>> ReactiveMongoApi.layer(mediatorDbConfig.connectionString) - >>> MessageItemRepo.layer.and(UserAccountRepo.layer).and(OutboxMessageRepo.layer) - ) + .provideSomeLayer((agentLayer ++ transportFactory ++ repos ++ Scope.default) >>> OperatorImp.layer) .provideSomeLayer(Operations.layerDefault) + .provideSomeLayer(Scope.default) .provide(Server.defaultWithPort(port)) .debug .fork @@ -115,4 +107,8 @@ object MediatorStandalone extends ZIOAppDefault { _ <- ZIO.log(s"*" * 100) } yield () + override val run = ZIO.logAnnotate( + zio.LogAnnotation("version", MediatorBuildInfo.version) + ) { mainProgram } + } diff --git a/mediator/src/main/scala/io/iohk/atala/mediator/OperatorImp.scala b/mediator/src/main/scala/io/iohk/atala/mediator/OperatorImp.scala index 17478c82..e5674796 100644 --- a/mediator/src/main/scala/io/iohk/atala/mediator/OperatorImp.scala +++ b/mediator/src/main/scala/io/iohk/atala/mediator/OperatorImp.scala @@ -29,7 +29,7 @@ object OperatorImp { )(MissingProtocolExecuter) // (NullProtocolExecute.mapError(didFail => ProtocolExecutionFailToParse(didFail))) ) - val layer: ZLayer[MediatorAgent & UserAccountRepo & MessageItemRepo & TransportFactory, Nothing, Operator] = + val layer: ZLayer[Scope & MediatorAgent & UserAccountRepo & MessageItemRepo & TransportFactory, Nothing, Operator] = protocolHandlerLayer >>> ZLayer.fromZIO( for { @@ -37,7 +37,8 @@ object OperatorImp { mediator <- ZIO.service[MediatorAgent] userAccountRepo <- ZIO.service[UserAccountRepo] messageItemRepo <- ZIO.service[MessageItemRepo] - self <- AgentExecutorMediator.make(mediator, protocolHandlerAux, userAccountRepo, messageItemRepo) + scope <- ZIO.service[Scope] + self <- AgentExecutorMediator.make(mediator, protocolHandlerAux, userAccountRepo, messageItemRepo, scope) _ <- ZIO.log("Layer Operator: " + self.subject.toString) operator = Operator( selfOperator = self, diff --git a/mediator/src/main/scala/io/iohk/atala/mediator/TraceIdMiddleware.scala b/mediator/src/main/scala/io/iohk/atala/mediator/TraceIdMiddleware.scala new file mode 100644 index 00000000..bcd3eb38 --- /dev/null +++ b/mediator/src/main/scala/io/iohk/atala/mediator/TraceIdMiddleware.scala @@ -0,0 +1,26 @@ +package io.iohk.atala.mediator + +import zio.* +import zio.http.* + +object TraceIdMiddleware { + + private val NAME_TRACE_ID = "requestid" + + private def requestId(req: Request) = ZIO.logAnnotateScoped( + req.headers + .find(h => h.headerName.equalsIgnoreCase("x-request-id")) + .toSet + .map(h => LogAnnotation(NAME_TRACE_ID, h.renderedValue)) + ) + + def addTraceId = { + HandlerAspect.interceptHandler( + Handler.fromFunctionZIO[Request] { request => + val effect = requestId(request) + effect.map(_ => (request, ())) + } + )(Handler.identity) + } + +}