Skip to content

Commit

Permalink
fix: re-enable the logging based on X-Request-Id header (#211)
Browse files Browse the repository at this point in the history
  • Loading branch information
FabioPinheiro authored Feb 6, 2024
1 parent 26a1623 commit dee7dc2
Show file tree
Hide file tree
Showing 8 changed files with 98 additions and 27 deletions.
40 changes: 40 additions & 0 deletions logging.md
Original file line number Diff line number Diff line change
@@ -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
3 changes: 1 addition & 2 deletions mediator/src/main/resources/logback.xml
Original file line number Diff line number Diff line change
Expand Up @@ -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">
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -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)
Expand Down Expand Up @@ -251,7 +251,6 @@ case class AgentExecutorMediator(
}
} yield ()
} yield ()

}

object AgentExecutorMediator {
Expand All @@ -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
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -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) =>
Expand Down Expand Up @@ -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"))

},
)
}
Original file line number Diff line number Diff line change
Expand Up @@ -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))
Expand Down Expand Up @@ -99,6 +101,6 @@ object MediatorAgent {
Handler.fromResource(fullPath).map(_.addHeader(headerContentType))
}.flatten
)
}.sandbox.toHttpApp
}.sandbox

}
Original file line number Diff line number Diff line change
Expand Up @@ -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
"""███╗ ███╗███████╗██████╗ ██╗ █████╗ ████████╗ ██████╗ ██████╗
|████╗ ████║██╔════╝██╔══██╗██║██╔══██╗╚══██╔══╝██╔═══██╗██╔══██╗
Expand Down Expand Up @@ -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
Expand All @@ -115,4 +107,8 @@ object MediatorStandalone extends ZIOAppDefault {
_ <- ZIO.log(s"*" * 100)
} yield ()

override val run = ZIO.logAnnotate(
zio.LogAnnotation("version", MediatorBuildInfo.version)
) { mainProgram }

}
Original file line number Diff line number Diff line change
Expand Up @@ -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,
Expand Down
Original file line number Diff line number Diff line change
@@ -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)
}

}

0 comments on commit dee7dc2

Please sign in to comment.