slf4j/logback MDC context reset/rewritten with other Fiber before it is logged

[justcoon]

in case of parallel execution, it may happen, that MDC context will be reset/rewritten with other Fiber, before it is logged

package zio.logging.backend

import zio.logging.LogAnnotation
import zio.test.Assertion._
import zio.test._
import zio.{ LogLevel, Runtime, ZIO, ZIOAspect, _ }

import java.util.UUID

object SLF4JParSpec extends ZIOSpecDefault {

  val loggerDefault: ZLayer[Any, Nothing, Unit] =
    Runtime.removeDefaultLoggers >>> SLF4J.slf4j

  val spec: Spec[Environment, Any] = suite("SLF4JParSpec")(
    test("log all annotations into MDC with custom logger name") {
      val users = Chunk.fill(2)(UUID.randomUUID())
      for {
        traceId <- ZIO.succeed(UUID.randomUUID())
        _        = TestAppender.reset()
        _       <- ZIO.foreachPar(users) { uId =>
                     {
                       ZIO.logInfo("Starting operation") *> ZIO.sleep(500.millis) *> ZIO.logInfo("Stopping operation")
                     } @@ ZIOAspect.annotated("user", uId.toString)
                   } @@ LogAnnotation.TraceId(traceId)
        _       <- ZIO.logInfo("Done")
      } yield {
        val loggerOutput = TestAppender.logOutput
        assertTrue(loggerOutput.size == 5) && assertTrue(
          loggerOutput.forall(_.loggerName == "zio.logging.backend.SLF4JParSpec")
        ) && assertTrue(loggerOutput.forall(_.logLevel == LogLevel.Info)) && assert(loggerOutput.map(_.message).toSet)(
          equalTo(
            Set(
              "Starting operation",
              "Stopping operation",
              "Starting operation",
              "Stopping operation",
              "Done"
            )
          )
        ) && assert(loggerOutput.map(_.mdc.get(LogAnnotation.TraceId.name)).sorted)(
          equalTo(
            (Chunk.fill(4)(Some(traceId.toString)) :+ None).sorted
          )
        ) && assert(loggerOutput.map(_.mdc.get("user")).sorted)(
          equalTo((users.flatMap(u => Chunk.fill(2)(Some(u.toString))) :+ None).sorted)
        )
      }
    }.provide(loggerDefault)
  ) @@ TestAspect.sequential @@ TestAspect.withLiveClock
}

+ SLF4JParSpec
11:25:51,254 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Found resource [logback-test.xml] at [file:/Users/coon/workspace/git/zio-logging/slf4j/target/scala-2.13/test-classes/logback-test.xml]
11:25:51,307 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - debug attribute not set
11:25:51,307 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [zio.logging.backend.TestAppender]
11:25:51,311 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [STDOUT]
11:25:51,314 |-ERROR in ch.qos.logback.core.joran.spi.Interpreter@5:62 - no applicable action for [layout], current ElementPath  is [[configuration][appender][layout]]
11:25:51,314 |-ERROR in ch.qos.logback.core.joran.spi.Interpreter@6:22 - no applicable action for [Pattern], current ElementPath  is [[configuration][appender][layout][Pattern]]
11:25:51,314 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [ch.qos.logback.core.ConsoleAppender]
11:25:51,315 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [logstash]
11:25:51,476 |-INFO in ch.qos.logback.classic.joran.action.RootLoggerAction - Setting level of ROOT logger to INFO
11:25:51,476 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [STDOUT] to Logger[ROOT]
11:25:51,476 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [logstash] to Logger[ROOT]
11:25:51,476 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - End of configuration.
11:25:51,477 |-INFO in ch.qos.logback.classic.joran.JoranConfigurator@15e836b8 - Registering current configuration as safe fallback point

{"@timestamp":"2022-08-18T11:25:51.481+02:00","@version":"1","message":"Starting operation","logger_name":"zio.logging.backend.SLF4JParSpec","thread_name":"ZScheduler-Worker-2","level":"INFO","level_value":20000}
{"@timestamp":"2022-08-18T11:25:51.488+02:00","@version":"1","message":"Starting operation","logger_name":"zio.logging.backend.SLF4JParSpec","thread_name":"ZScheduler-Worker-2","level":"INFO","level_value":20000,"user":"aba324da-f1a7-4ea9-a5e1-96de76979c86","trace_id":"4a562fd8-607e-4633-bd00-a42be241ba4c"}
SLF4J: A number (1) of logging calls during the initialization phase have been intercepted and are
SLF4J: now being replayed. These are subject to the filtering rules of the underlying logging system.
SLF4J: See also http://www.slf4j.org/codes.html#replay
{"@timestamp":"2022-08-18T11:25:51.744+02:00","@version":"1","message":"Stopping operation","logger_name":"zio.logging.backend.SLF4JParSpec","thread_name":"zio-default-blocking-1","level":"INFO","level_value":20000,"user":"459245e4-e97a-403b-9775-2a1f757a2121","trace_id":"4a562fd8-607e-4633-bd00-a42be241ba4c"}
{"@timestamp":"2022-08-18T11:25:51.992+02:00","@version":"1","message":"Stopping operation","logger_name":"zio.logging.backend.SLF4JParSpec","thread_name":"zio-default-blocking-1","level":"INFO","level_value":20000,"user":"aba324da-f1a7-4ea9-a5e1-96de76979c86","trace_id":"4a562fd8-607e-4633-bd00-a42be241ba4c"}
{"@timestamp":"2022-08-18T11:25:51.995+02:00","@version":"1","message":"Done","logger_name":"zio.logging.backend.SLF4JParSpec","thread_name":"ZScheduler-Worker-1","level":"INFO","level_value":20000}
  - log all annotations into MDC with custom logger name
    ✗ Chunk(None, None, Some("4a562fd8-607e-4633-bd00-a42be241ba4c"), Some("4a562fd8-607e-4633-bd00-a42be241ba4c"), Some("4a562fd8-607e-4633-bd00-a42be241ba4c")) was not equal to Chunk(None, Some("4a562fd8-607e-4633-bd00-a42be241ba4c"), Some("4a562fd8-607e-4633-bd00-a42be241ba4c"), Some("4a562fd8-607e-4633-bd00-a42be241ba4c"), Some("4a562fd8-607e-4633-bd00-a42be241ba4c"))
    loggerOutput.map(_.mdc.get(LogAnnotation.TraceId.name)).sorted did not satisfy equalTo(
            (Chunk.fill(4)(Some(traceId.toString)) :+ None).sorted
          )
    loggerOutput.map(_.mdc.get(LogAnnotation.TraceId.name)).sorted = Chunk(None, None, Some("4a562fd8-607e-4633-bd00-a42be241ba4c"), Some("4a562fd8-607e-4633-bd00-a42be241ba4c"), Some("4a562fd8-607e-4633-bd00-a42be241ba4c"))
    at /Users/coon/workspace/git/zio-logging/slf4j/src/test/scala-2/zio/logging/backend/SLF4JParSpec.scala:43
    ✗ Chunk(None, None, Some("459245e4-e97a-403b-9775-2a1f757a2121"), Some("aba324da-f1a7-4ea9-a5e1-96de76979c86"), Some("aba324da-f1a7-4ea9-a5e1-96de76979c86")) was not equal to Chunk(None, Some("459245e4-e97a-403b-9775-2a1f757a2121"), Some("459245e4-e97a-403b-9775-2a1f757a2121"), Some("aba324da-f1a7-4ea9-a5e1-96de76979c86"), Some("aba324da-f1a7-4ea9-a5e1-96de76979c86"))
    loggerOutput.map(_.mdc.get("user")).sorted did not satisfy equalTo((users.flatMap(u => Chunk.fill(2)(Some(u.toString))) :+ None).sorted)
    loggerOutput.map(_.mdc.get("user")).sorted = Chunk(None, None, Some("459245e4-e97a-403b-9775-2a1f757a2121"), Some("aba324da-f1a7-4ea9-a5e1-96de76979c86"), Some("aba324da-f1a7-4ea9-a5e1-96de76979c86"))
    at /Users/coon/workspace/git/zio-logging/slf4j/src/test/scala-2/zio/logging/backend/SLF4JParSpec.scala:47

0 tests passed. 1 tests failed. 0 tests ignored.

  - SLF4JParSpec / log all annotations into MDC with custom logger name
    ✗ Chunk(None, None, Some("4a562fd8-607e-4633-bd00-a42be241ba4c"), Some("4a562fd8-607e-4633-bd00-a42be241ba4c"), Some("4a562fd8-607e-4633-bd00-a42be241ba4c")) was not equal to Chunk(None, Some("4a562fd8-607e-4633-bd00-a42be241ba4c"), Some("4a562fd8-607e-4633-bd00-a42be241ba4c"), Some("4a562fd8-607e-4633-bd00-a42be241ba4c"), Some("4a562fd8-607e-4633-bd00-a42be241ba4c"))
    loggerOutput.map(_.mdc.get(LogAnnotation.TraceId.name)).sorted did not satisfy equalTo(
            (Chunk.fill(4)(Some(traceId.toString)) :+ None).sorted
          )
    loggerOutput.map(_.mdc.get(LogAnnotation.TraceId.name)).sorted = Chunk(None, None, Some("4a562fd8-607e-4633-bd00-a42be241ba4c"), Some("4a562fd8-607e-4633-bd00-a42be241ba4c"), Some("4a562fd8-607e-4633-bd00-a42be241ba4c"))
    at /Users/coon/workspace/git/zio-logging/slf4j/src/test/scala-2/zio/logging/backend/SLF4JParSpec.scala:43
    ✗ Chunk(None, None, Some("459245e4-e97a-403b-9775-2a1f757a2121"), Some("aba324da-f1a7-4ea9-a5e1-96de76979c86"), Some("aba324da-f1a7-4ea9-a5e1-96de76979c86")) was not equal to Chunk(None, Some("459245e4-e97a-403b-9775-2a1f757a2121"), Some("459245e4-e97a-403b-9775-2a1f757a2121"), Some("aba324da-f1a7-4ea9-a5e1-96de76979c86"), Some("aba324da-f1a7-4ea9-a5e1-96de76979c86"))
    loggerOutput.map(_.mdc.get("user")).sorted did not satisfy equalTo((users.flatMap(u => Chunk.fill(2)(Some(u.toString))) :+ None).sorted)
    loggerOutput.map(_.mdc.get("user")).sorted = Chunk(None, None, Some("459245e4-e97a-403b-9775-2a1f757a2121"), Some("aba324da-f1a7-4ea9-a5e1-96de76979c86"), Some("aba324da-f1a7-4ea9-a5e1-96de76979c86"))
    at /Users/coon/workspace/git/zio-logging/slf4j/src/test/scala-2/zio/logging/backend/SLF4JParSpec.scala:47

this may be also related to implementation of: ch.qos.logback.classic.spi.LoggingEvent.getMDCPropertyMap

where MDC context is fetched in getter, and not "materialised" during log event creation