zio-logging icon indicating copy to clipboard operation
zio-logging copied to clipboard

`zio.logging.LogAnnotation` work in unexpected way.

Open domdorn opened this issue 2 years ago • 1 comments

I tried to migrate code from zio 1 to zio 2. it looks like there is a discrepancy between the zio.LogAnnotation and zio.logging.LogAnnotation. The one provided by zio correctly puts annotations as fields into the log, whereas zio.logging.LogAnnotation just stores them in the fibers Fiberrefs so they can be used to construct a custom LogFormat (which is of limited use when e.g. used together with logstash+kibana where you want all these annotations as separate fields).

e.g. I have this directive to integrate with akka-http

  def zioUserEffect[E <: Throwable](f: ZIO[CorrelationId with UserId with Set[Role] with User, E, Route])(
    implicit r: zio.Runtime[Any]): Route =
    Route {
      (AuthDirective.extractUserPrincipal & Directives.extractRequest) { case (principal, req) =>
        val e: ZIO[Any, E, Route] = for {
          _ <- ZIO.unit
          c          = CorrelationId.random()
          baseEffect = ZIO.logDebug(s"Processing Req. ${req.method} ${req.uri}") *> f

          zioAnnotations = ZIO.logAnnotate(
            zio.LogAnnotation("correlation-id", c.value.toString),
            zio.LogAnnotation("user-id", principal.userId.userId),
            zio.LogAnnotation("request-uri", req.uri.toString()),
            zio.LogAnnotation("request-method", req.method.value)
          )

          annotated = baseEffect @@
            LogAnnotations.CorrelationId(c) @@
            LogAnnotations.UserId(principal.userId) @@
            LogAnnotations.RequestUri(req.uri.toString()) @@
            LogAnnotations.RequestMethod(req.method.value)

          provided = zioAnnotations(annotated).provide(
            ZLayer.succeed(c: CorrelationId),
            ZLayer.succeed(principal.userId: UserId),
            ZLayer.succeed(principal.roles: Set[Role]),
            ZLayer.succeed(principal: User)
          )
          running <- provided

        } yield running

        StandardRoute { ctx =>
          val future: Future[RouteResult] =
            Unsafe.unsafe(implicit u => r.unsafe.runToFuture(e)).flatMap(v => v(ctx))(ctx.executionContext)
          future
        }
      }
    }

I was expecting that the annotated effect would be enough to have the fields correctly put into the log. It took me 3 hours to figure out that I have to create a zio.LogAnnotation like done with zioAnnotations that I then have to apply to my effect so that it works correctly.

I'm using this logging layer in my app:

  private val logger =
    zio.Runtime.removeDefaultLoggers >>> SLF4J.slf4j(
      LogLevel.All, LogFormat.line
    )

together with this logback.xml:

...
  <appender class="ch.qos.logback.core.ConsoleAppender" name="JSON">
    <encoder encoding="UTF-8" class="net.logstash.logback.encoder.LogstashEncoder">
      <customFields>{"application":"acme-limit-service","stage":"${LOG_STAGE:-LOCAL}"}</customFields>
    </encoder>
  </appender>
  ...

domdorn avatar Jul 30 '22 21:07 domdorn

hi @domdorn,

sorry for inconvenience,

we know about inconsistency between zio annotations and log annotations (it was also reported in #453), in current released version (2.0.1), LogAnnotation-s are not propagated into slf4j MDC context we are working on fix and also another improvements, which should fix current issues in relation to slf4j integration

there is draft PR #479 created, which should address those problems

thank you very much, for your patience

justcoon avatar Jul 31 '22 16:07 justcoon

hi @domdorn, propagation of annotations to MDC context was fixed in 2.1.0 version, at this level zio LogAnnotation-s and zio-logging LogAnnotation-s got same behavior, documentation/example: slf4j logger annotations

can you check it. if it solved your problem?

thank you very much

justcoon avatar Aug 18 '22 09:08 justcoon

hi @domdorn, please let me know if my previous comment solving your problem, and I can close this issue. Thank you very much

justcoon avatar Oct 03 '22 18:10 justcoon

Hi @justcoon , yes, it looks like my problem is fixed - thanks!

domdorn avatar Oct 04 '22 12:10 domdorn