fix: re-enable the logging based on X-Request-Id header (#211)

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

mediator/src/main/resources/logback.xml

@@ -3,8 +3,7 @@
     <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
         <withJansi>true</withJansi>
         <encoder>
-            <!--    TODO include mediator release version in the logs     />-->
-            <pattern>%d{yyyy-MM-dd_HH:mm:ss.SSS} [%highlight(%-5level)] %cyan(%logger{5}@L%line:[%-4.30thread])  %mdc - %msg%xException%n</pattern>
+            <pattern>%d{yyyy-MM-dd_HH:mm:ss.SSS} %highlight(%-5level) %cyan(%logger{5}@L%line:[%-4.30thread]) {%mdc} - %msg%xException%n</pattern>
         </encoder>
     </appender>
     <appender name="logstash" class="ch.qos.logback.core.ConsoleAppender">

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

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"))
-
     },
   )
 }

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
 
 }

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 }
+
 }

mediator/src/main/scala/io/iohk/atala/mediator/OperatorImp.scala

@@ -29,15 +29,16 @@ 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 {
           protocolHandlerAux <- ZIO.service[ProtocolExecuter[Services, MediatorError | StorageError]]
           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,

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)
+  }
+
+}