SLF4J provide logging backend that stores everything in MDC

[domdorn]

This corresponds to https://github.com/zio/zio/issues/6673 I'm using SLF4J and the LogStashEncoder. I'm trying to put all fields/spans into MDCFields and just keep the real message in the message field. The only way I was able to accomplish this was by creating my own implementation of the SLF4J backend like

  private def slf4jLogger(
                           rootLoggerName: ZTraceElement => String,
                           logLevel: LogLevel,
                           format: LogFormat
                         ): ZLogger[String, Unit] =
    new ZLogger[String, Unit] {
      val formatLogger: ZLogger[String, Option[String]] =
        format.toLogger.filterLogLevel(_ >= logLevel)

      override def apply(
                          trace: ZTraceElement,
                          fiberId: FiberId,
                          logLevel: LogLevel,
                          message: () => String,
                          cause: Cause[Any],
                          context: Map[FiberRef[_], Any],
                          spans: List[LogSpan],
                          annotations: Map[String, String]
                        ): Unit =
        formatLogger(trace, fiberId, logLevel, message, cause, context, spans, annotations).foreach { message =>
          val slf4jLogger = LoggerFactory.getLogger(rootLoggerName(trace))

          val now = System.currentTimeMillis()
          val newAnnotations = spans.map(span => span.label -> (now-span.startTime).toString).toMap ++ annotations ++ Map(
            "fiberId" -> fiberId.threadName.toString
          )

          val previous =
            if (newAnnotations.nonEmpty) {
              val previous =
                Some(Option(MDC.getCopyOfContextMap).getOrElse(java.util.Collections.emptyMap[String, String]()))
              MDC.setContextMap(newAnnotations.asJava)
              previous
            } else None

          try logLevel match {
            case LogLevel.All     => if (slf4jLogger.isTraceEnabled) slf4jLogger.trace(message)
            case LogLevel.Debug   => if (slf4jLogger.isDebugEnabled) slf4jLogger.debug(message)
            case LogLevel.Info    => if (slf4jLogger.isInfoEnabled) slf4jLogger.info(message)
            case LogLevel.Warning => if (slf4jLogger.isWarnEnabled) slf4jLogger.warn(message)
            case LogLevel.Error   => if (slf4jLogger.isErrorEnabled) slf4jLogger.error(message)
            case LogLevel.Fatal   => if (slf4jLogger.isErrorEnabled) slf4jLogger.error(message)
            case LogLevel.None    => ()
            case _                => ()
          } finally previous.foreach(MDC.setContextMap)
        }
    }

In general, when using SLF4J and one of the underlying backends, I want everything stored in fields so that I can leverage the logger-architecture of (in this case) Logback, where I can simply log a json string or create my custom logformat like for every other project.

[justcoon]

Hi @domdorn,

current version of zio-logging 2.1.1, should allow custom LogFormat definition which should allow put everything into MDC

LogAppender.appendKeyValue appending data into MDC

example:

  val line: LogFormat =
    LogFormat.make { (builder, _, _, _, line, _, _, _, _) =>
      builder.appendKeyValue("line", line())
    }

let me know, if this is solving your problem

Thanks

[calvinlfer]

Hey @justcoon I dont thinkbuilder.appendKeyValue is appending data into the MDC

For example, explicitly using the MDC works:

<?xml version="1.0" encoding="UTF-8"?>
<configuration>
    <appender name="local" class="ch.qos.logback.core.ConsoleAppender">
        <encoder>
            <pattern>%green(%d{HH:mm:ss.SSS}) %highlight(%-5level) class=%logger{30} fiber=%X{fiberId} spanInfo=%X{spanInfo} - %msg%n</pattern>
        </encoder>
    </appender>

    <root level="info">
        <appender-ref ref="local" />
    </root>
</configuration>

import org.slf4j.MDC
import zio.*
import zio.logging.LogFormat
import zio.logging.backend.SLF4J

import scala.jdk.CollectionConverters.*

object ExampleApp extends ZIOAppDefault {
  val richLogFormat: LogFormat =
    LogFormat.make { (appender, _, fiberId, _, message, _, _, logSpans, annotations) =>
      val now = java.lang.System.currentTimeMillis
      val allAnnotations: Map[String, String] = {
        val spanInfo = "spanInfo" -> logSpans.reverse
          .map(span => s"${span.label}=${now - span.startTime} ms")
          .mkString("[", " -> ", "]")

        val fiberIdInfo = "fiberId" -> fiberId.threadName.toString

        annotations + fiberIdInfo + spanInfo
      }

      val prev = Option(MDC.getCopyOfContextMap)
      MDC.setContextMap(allAnnotations.asJava)

      try appender.appendText(message())
      finally prev.foreach(MDC.setContextMap)
    }

  override val bootstrap: ZLayer[ZIOAppArgs, Any, Any] = Runtime.removeDefaultLoggers >>> SLF4J.slf4j(richLogFormat)

  override def run: ZIO[ZIOAppArgs & Scope, Any, Any] =
    ZIO.logSpan("outest-span") {
      ZIO.logSpan("out-span") {
        ZIO.logSpan("in-span") {
          ZIO.logSpan("innest-span") {
            ZIO.logInfo("Hello World")
          }
        }
      }
    }
}

However, using the appender does not add it:

  val richLogFormat: LogFormat =
    LogFormat.make { (appender, _, fiberId, _, message, _, _, logSpans, annotations) =>
      val now = java.lang.System.currentTimeMillis
      val allAnnotations: Map[String, String] = {
        val spanInfo = "spanInfo" -> logSpans.reverse
          .map(span => s"${span.label}=${now - span.startTime} ms")
          .mkString("[", " -> ", "]")

        val fiberIdInfo = "fiberId" -> fiberId.threadName.toString

        annotations + fiberIdInfo + spanInfo
      }

      allAnnotations.foreach { case (k, v) => appender.appendKeyValue(k, v) }
      appender.appendText(message())
    }

[justcoon]

Hello @calvinlfer

i tried your example, with latest version of zio-logging-slf4j (2.1.9)

and I can see

09:39:05.523 INFO  class=zio.logging.example.ExampleApp fiber=zio-fiber-4 spanInfo=[outest-span=7 ms -> out-span=7 ms -> in-span=6 ms -> innest-span=6 ms] - Hello World

are you using zio-logging-slf4j or zio-logging-slf4j2 ?

[calvinlfer]

Hey @justcoon thank you so much for looking into this - Im sorry I forgot to add I'm using slf4j2:

      val zioLoggingV = "2.1.9"
// ...
        zio                   %% "zio-logging"              % zioLoggingV,
        zio                   %% "zio-logging-slf4j2"       % zioLoggingV,
        "ch.qos.logback"       % "logback-classic"          % "1.4.5",

I guess it must be some problem with slf4j2?

[calvinlfer]

I read your post on Discord and using %kvp in logback.xml works! Thank you 😄

[lmlynik]

Is there a way to make this working with json encoders like LogstashEncoder ?

[justcoon]

hi @lmlynik

not sure what exactly do you mean

if you mean zio-logging-slf4j2 which using key value pairs of slf4j v2, in such case I would ask LogstashEncoder developers when they add key value pairs support

otherwise you can still use zio-logging-slf4j which using MDC

[andreoss]

There's no need to manipulate MDC directly from LogFormat, it's enough to add all spans to annotations with builder in a LogFormat and combine it with the default one for example.

import zio.logging._
import zio.logging.backend._

object Logs {
  private val logSpans: LogFormat =
    LogFormat.make { (builder, _, fid, _, _, _, _, spans, _) =>
      val now = java.lang.System.currentTimeMillis
      spans.reverse
        .foreach { span => builder.appendKeyValue(s"span/${span.label}", s"${now - span.startTime}ms") }
      if (spans.nonEmpty)
        builder.appendKeyValue("fid", fid.threadName)
    }
  val Logger = zio.Runtime.removeDefaultLoggers >>> SLF4J.slf4j(logSpans + SLF4J.logFormatDefault)
}