slf4j2-bridge - key values as log annotations (#851)

README.md

@@ -28,7 +28,7 @@ In order to use this library, we need to add the following line in our `build.sb
 
 ```scala
 // ZIO Logging backends
-libraryDependencies += "dev.zio" %% "zio-logging" % "2.2.2"
+libraryDependencies += "dev.zio" %% "zio-logging" % "2.2.4"
 ```
 
 The main module contains the following features: 
@@ -43,10 +43,10 @@ Other modules:
 
     ```scala
     // SLF4j v1 integration
-    libraryDependencies += "dev.zio" %% "zio-logging-slf4j" % "2.2.2"
+    libraryDependencies += "dev.zio" %% "zio-logging-slf4j" % "2.2.4"
 
     // SLF4j v2 integration
-    libraryDependencies += "dev.zio" %% "zio-logging-slf4j2" % "2.2.2"
+    libraryDependencies += "dev.zio" %% "zio-logging-slf4j2" % "2.2.4"
     ```
    When to use this module: you are already using SLF4J logger in some other project, and you like to have same log outputs. 
    See SLF4J [v2](docs/slf4j2.md) or [v1](docs/slf4j1.md) section for more details.
@@ -56,10 +56,10 @@ Other modules:
 
     ```scala
     // Using ZIO Logging for SLF4j v1 loggers, usually third-party non-ZIO libraries
-    libraryDependencies += "dev.zio" %% "zio-logging-slf4j-bridge" % "2.2.2"
+    libraryDependencies += "dev.zio" %% "zio-logging-slf4j-bridge" % "2.2.4"
 
     // Using ZIO Logging for SLF4j v2 loggers, usually third-party non-ZIO libraries
-    libraryDependencies += "dev.zio" %% "zio-logging-slf4j2-bridge" % "2.2.2"
+    libraryDependencies += "dev.zio" %% "zio-logging-slf4j2-bridge" % "2.2.4"
     ```
 
     When to use this module: you want to use some zio-logger implementation, but also you are using some java library which using SLF4J interface for logging.
@@ -70,7 +70,7 @@ Other modules:
 
     ```scala
     // JPL integration
-    libraryDependencies += "dev.zio" %% "zio-logging-jpl" % "2.2.2"
+    libraryDependencies += "dev.zio" %% "zio-logging-jpl" % "2.2.4"
     ```
 
     When to use this module: you are already using Java Platform/System Logger in some other project, and you like to have same log outputs.
@@ -81,7 +81,7 @@ Other modules:
 
     ```scala
     // JUL bridge
-    libraryDependencies += "dev.zio" %% "zio-logging-jul-bridge" % "2.2.2"
+    libraryDependencies += "dev.zio" %% "zio-logging-jul-bridge" % "2.2.4"
     ```
 
     When to use this module: you are already using JUL logger in some other project, and you like to have same log outputs.
@@ -134,11 +134,11 @@ Learn more on the [zio-logging homepage](https://zio.dev/zio-logging)!
 
 ## Contributing
 
-For the general guidelines, see ZIO [contributor's guide](https://zio.dev/contributor-guidelines/).
+For the general guidelines, see ZIO [contributor's guide](https://zio.dev/contributor-guidelines).
 
 ## Code of Conduct
 
-See the [Code of Conduct](https://zio.dev/code-of-conduct/)
+See the [Code of Conduct](https://zio.dev/code-of-conduct)
 
 ## Support
 

docs/slf4j1-bridge.md

@@ -111,10 +111,10 @@ object Slf4jBridgeExampleApp extends ZIOAppDefault {
 
 Expected Console Output:
 ```
-{"name":"zio.logging.slf4j.bridge.Slf4jBridgeExampleApp","timestamp":"2024-02-16T08:10:45.373807+01:00","level":"INFO","thread":"zio-fiber-6","message":"Start"}
+{"name":"zio.logging.example.Slf4jBridgeExampleApp","timestamp":"2024-02-16T08:10:45.373807+01:00","level":"INFO","thread":"zio-fiber-6","message":"Start"}
 {"name":"SLF4J-LOGGER","user_id":"d13f90ad-6b0a-45fd-bf94-1db7a0d8c0b7","trace_id":"561300a9-e6f1-4f61-8dcc-dfef476dab20","timestamp":"2024-02-16T08:10:45.421448+01:00","level":"WARN","thread":"zio-fiber-10","message":"Test WARNING!"}
 {"name":"SLF4J-LOGGER","user_id":"0f28521f-ac8f-4d8e-beeb-13c85c90c041","trace_id":"561300a9-e6f1-4f61-8dcc-dfef476dab20","timestamp":"2024-02-16T08:10:45.421461+01:00","level":"WARN","thread":"zio-fiber-9","message":"Test WARNING!"}
-{"name":"zio.logging.slf4j.bridge.Slf4jBridgeExampleApp","timestamp":"2024-02-16T08:10:45.428162+01:00","level":"DEBUG","thread":"zio-fiber-6","message":"Done"}
+{"name":"zio.logging.example.Slf4jBridgeExampleApp","timestamp":"2024-02-16T08:10:45.428162+01:00","level":"DEBUG","thread":"zio-fiber-6","message":"Done"}
 ```
 
 ## Feature changes

docs/slf4j2-bridge.md

@@ -22,6 +22,8 @@ program.provideCustom(Slf4jBridge.init())
 * `Slf4jBridge.init(filter: LogFilter[Any])` - setup with given `LogFilter`
 * `Slf4jBridge.initialize` - setup without filtering
 
+SLF4J v2 [key-value pairs](https://www.slf4j.org/manual.html#fluent) are propagated like ZIO log annotations.
+
 Need for log filtering in slf4j bridge: libraries with slf4j loggers, may have conditional logic for logging,
 which using functions like [org.slf4j.Logger.isTraceEnabled()](https://github.com/qos-ch/slf4j/blob/master/slf4j-api/src/main/java/org/slf4j/Logger.java#L170).
 logging parts may contain message and log parameters construction, which may be expensive and degrade performance of application.
@@ -96,9 +98,7 @@ object Slf4jBridgeExampleApp extends ZIOAppDefault {
   private val logFormat = LogFormat.label(
     "name",
     LoggerNameExtractor.loggerNameAnnotationOrTrace.toLogFormat()
-  ) + LogFormat.logAnnotation(LogAnnotation.UserId) + LogFormat.logAnnotation(
-    LogAnnotation.TraceId
-  ) + LogFormat.default
+  ) + LogFormat.allAnnotations(Set(zio.logging.loggerNameAnnotationKey)) + LogFormat.default
 
   private val loggerConfig = ConsoleLoggerConfig(logFormat, logFilterConfig)
 
@@ -112,7 +112,7 @@ object Slf4jBridgeExampleApp extends ZIOAppDefault {
       _ <- ZIO.logInfo("Start")
       _ <- ZIO.foreachPar(uuids) { u =>
         ZIO.succeed(slf4jLogger.info("Test {}!", "INFO")) *> ZIO.succeed(
-          slf4jLogger.warn("Test {}!", "WARNING")
+          slf4jLogger.atWarn().addArgument("WARNING").log("Test {}!")
         ) @@ LogAnnotation.UserId(
           u.toString
         )
@@ -125,8 +125,8 @@ object Slf4jBridgeExampleApp extends ZIOAppDefault {
 
 Expected Console Output:
 ```
-{"name":"zio.logging.slf4j.bridge.Slf4jBridgeExampleApp","timestamp":"2024-02-16T08:10:45.373807+01:00","level":"INFO","thread":"zio-fiber-6","message":"Start"}
-{"name":"SLF4J-LOGGER","user_id":"d13f90ad-6b0a-45fd-bf94-1db7a0d8c0b7","trace_id":"561300a9-e6f1-4f61-8dcc-dfef476dab20","timestamp":"2024-02-16T08:10:45.421448+01:00","level":"WARN","thread":"zio-fiber-10","message":"Test WARNING!"}
-{"name":"SLF4J-LOGGER","user_id":"0f28521f-ac8f-4d8e-beeb-13c85c90c041","trace_id":"561300a9-e6f1-4f61-8dcc-dfef476dab20","timestamp":"2024-02-16T08:10:45.421461+01:00","level":"WARN","thread":"zio-fiber-9","message":"Test WARNING!"}
-{"name":"zio.logging.slf4j.bridge.Slf4jBridgeExampleApp","timestamp":"2024-02-16T08:10:45.428162+01:00","level":"DEBUG","thread":"zio-fiber-6","message":"Done"}
+{"name":"zio.logging.example.Slf4jBridgeExampleApp","timestamp":"2024-05-28T08:05:48.056029+02:00","level":"INFO","thread":"zio-fiber-735317063","message":"Start"}
+{"name":"SLF4J-LOGGER","trace_id":"416f3886-717c-4359-9f6e-c260e49fd158","user_id":"580376aa-f851-43a2-8b17-9456ce005e93","timestamp":"2024-05-28T08:05:48.065133+02:00","level":"WARN","thread":"zio-fiber-1749629949","message":"Test WARNING!"}
+{"name":"SLF4J-LOGGER","trace_id":"416f3886-717c-4359-9f6e-c260e49fd158","user_id":"76d49e0d-7c28-47fd-b5a1-d05afb487cfe","timestamp":"2024-05-28T08:05:48.065174+02:00","level":"WARN","thread":"zio-fiber-697454589","message":"Test WARNING!"}
+{"name":"zio.logging.example.Slf4jBridgeExampleApp","timestamp":"2024-05-28T08:05:48.068127+02:00","level":"DEBUG","thread":"zio-fiber-735317063","message":"Done"}
 ```

examples/slf4j2-bridge/src/main/scala/zio/logging/example/Slf4jBridgeExampleApp.scala

@@ -34,9 +34,7 @@ object Slf4jBridgeExampleApp extends ZIOAppDefault {
   private val logFormat = LogFormat.label(
     "name",
     LoggerNameExtractor.loggerNameAnnotationOrTrace.toLogFormat()
-  ) + LogFormat.logAnnotation(LogAnnotation.UserId) + LogFormat.logAnnotation(
-    LogAnnotation.TraceId
-  ) + LogFormat.default
+  ) + LogFormat.allAnnotations(Set(zio.logging.loggerNameAnnotationKey)) + LogFormat.default
 
   private val loggerConfig = ConsoleLoggerConfig(logFormat, logFilterConfig)
 
@@ -50,7 +48,7 @@ object Slf4jBridgeExampleApp extends ZIOAppDefault {
       _ <- ZIO.logInfo("Start")
       _ <- ZIO.foreachPar(uuids) { u =>
              ZIO.succeed(slf4jLogger.info("Test {}!", "INFO")) *> ZIO.succeed(
-               slf4jLogger.warn("Test {}!", "WARNING")
+               slf4jLogger.atWarn().addArgument("WARNING").log("Test {}!")
              ) @@ LogAnnotation.UserId(
                u.toString
              )

jul-bridge/src/main/scala/zio/logging/jul/bridge/ZioLoggerRuntime.scala

@@ -35,7 +35,7 @@ final class ZioLoggerRuntime(runtime: Runtime[Any], filter: LogFilter[Any]) exte
 
       val logLevel     = ZioLoggerRuntime.logLevelMapping(level)
       val trace        = Trace.empty
-      val fiberId      = FiberId.make(trace)
+      val fiberId      = FiberId.Gen.Live.make(trace)
       val currentFiber = Fiber._currentFiber.get()
 
       val currentFiberRefs = if (currentFiber eq null) {

slf4j-bridge/src/main/scala/zio/logging/slf4j/bridge/ZioLoggerRuntime.scala

@@ -35,7 +35,7 @@ final class ZioLoggerRuntime(runtime: Runtime[Any], filter: LogFilter[Any]) exte
     Unsafe.unsafe { implicit u =>
       val logLevel     = ZioLoggerRuntime.logLevelMapping(level)
       val trace        = Trace.empty
-      val fiberId      = FiberId.make(trace)
+      val fiberId      = FiberId.Gen.Live.make(trace)
       val currentFiber = Fiber._currentFiber.get()
 
       val currentFiberRefs = if (currentFiber eq null) {

slf4j2-bridge/src/main/java/zio/logging/slf4j/bridge/Logger.java

@@ -17,9 +17,13 @@
 
 import org.slf4j.Marker;
 import org.slf4j.event.Level;
+import org.slf4j.event.LoggingEvent;
 import org.slf4j.helpers.AbstractLogger;
+import org.slf4j.spi.LoggingEventAware;
 
-final class Logger extends AbstractLogger {
+import java.util.Collections;
+
+final class Logger extends AbstractLogger implements LoggingEventAware {
 
     private LoggerFactory factory;
 
@@ -35,7 +39,7 @@ protected String getFullyQualifiedCallerName() {
 
     @Override
     protected void handleNormalizedLoggingCall(Level level, Marker marker, String messagePattern, Object[] arguments, Throwable throwable) {
-        factory.log(name, level, marker, messagePattern, arguments, throwable);
+        factory.log(name, level, messagePattern, arguments, throwable, Collections.emptyList());
     }
 
     @Override
@@ -87,4 +91,11 @@ public boolean isErrorEnabled() {
     public boolean isErrorEnabled(Marker marker) {
         return isErrorEnabled();
     }
+
+    @Override
+    public void log(LoggingEvent event) {
+        if (factory.isEnabled(name, event.getLevel())) {
+            factory.log(name, event.getLevel(), event.getMessage(), event.getArgumentArray(), event.getThrowable(), event.getKeyValuePairs());
+        }
+    }
 }

slf4j2-bridge/src/main/java/zio/logging/slf4j/bridge/LoggerFactory.java

@@ -17,8 +17,10 @@
 
 import org.slf4j.ILoggerFactory;
 import org.slf4j.Marker;
+import org.slf4j.event.KeyValuePair;
 import org.slf4j.event.Level;
 
+import java.util.List;
 import java.util.Map;
 import java.util.concurrent.ConcurrentHashMap;
 
@@ -32,9 +34,9 @@ void attachRuntime(LoggerRuntime runtime) {
         this.runtime = runtime;
     }
 
-    void log(String name, Level level, Marker marker, String messagePattern, Object[] arguments, Throwable throwable) {
+    void log(String name, Level level, String messagePattern, Object[] arguments, Throwable throwable, List<KeyValuePair> keyValues) {
         if (runtime != null) {
-            runtime.log(name, level, marker, messagePattern, arguments, throwable);
+            runtime.log(name, level, messagePattern, arguments, throwable, keyValues);
         }
     }
 

slf4j2-bridge/src/main/java/zio/logging/slf4j/bridge/LoggerRuntime.java

@@ -15,11 +15,13 @@
  */
 package zio.logging.slf4j.bridge;
 
-import org.slf4j.Marker;
+import org.slf4j.event.KeyValuePair;
 import org.slf4j.event.Level;
 
+import java.util.List;
+
 interface LoggerRuntime {
-    void log(String name, Level level, Marker marker, String messagePattern, Object[] arguments, Throwable throwable);
+    void log(String name, Level level, String messagePattern, Object[] arguments, Throwable throwable, List<KeyValuePair> keyValues);
 
     boolean isEnabled(String name, Level level);
 }

slf4j2-bridge/src/main/scala/zio/logging/slf4j/bridge/ZioLoggerRuntime.scala

@@ -15,26 +15,27 @@
  */
 package zio.logging.slf4j.bridge
 
-import org.slf4j.Marker
-import org.slf4j.event.Level
+import org.slf4j.event.{ KeyValuePair, Level }
 import org.slf4j.helpers.MessageFormatter
 import zio.logging.LogFilter
 import zio.{ Cause, Fiber, FiberId, FiberRef, FiberRefs, LogLevel, Runtime, Trace, Unsafe }
 
+import scala.jdk.CollectionConverters._
+
 final class ZioLoggerRuntime(runtime: Runtime[Any], filter: LogFilter[Any]) extends LoggerRuntime {
 
   override def log(
     name: String,
     level: Level,
-    marker: Marker,
     messagePattern: String,
     arguments: Array[AnyRef],
-    throwable: Throwable
+    throwable: Throwable,
+    keyValues: java.util.List[KeyValuePair]
   ): Unit =
     Unsafe.unsafe { implicit u =>
       val logLevel     = ZioLoggerRuntime.logLevelMapping(level)
       val trace        = Trace.empty
-      val fiberId      = FiberId.make(trace)
+      val fiberId      = FiberId.Gen.Live.make(trace)
       val currentFiber = Fiber._currentFiber.get()
 
       val currentFiberRefs = if (currentFiber eq null) {
@@ -43,14 +44,19 @@ final class ZioLoggerRuntime(runtime: Runtime[Any], filter: LogFilter[Any]) exte
         runtime.fiberRefs.joinAs(fiberId)(currentFiber.unsafe.getFiberRefs())
       }
 
-      val logSpan    = zio.LogSpan(name, java.lang.System.currentTimeMillis())
-      val loggerName = (zio.logging.loggerNameAnnotationKey -> name)
+      val logSpan        = zio.LogSpan(name, java.lang.System.currentTimeMillis())
+      val loggerName     = (zio.logging.loggerNameAnnotationKey -> name)
+      val logAnnotations = if (keyValues != null) {
+        keyValues.asScala.map(kv => (kv.key, kv.value.toString)).toMap
+      } else {
+        Map.empty
+      }
 
       val fiberRefs = currentFiberRefs
         .updatedAs(fiberId)(FiberRef.currentLogSpan, logSpan :: currentFiberRefs.getOrDefault(FiberRef.currentLogSpan))
         .updatedAs(fiberId)(
           FiberRef.currentLogAnnotations,
-          currentFiberRefs.getOrDefault(FiberRef.currentLogAnnotations) + loggerName
+          currentFiberRefs.getOrDefault(FiberRef.currentLogAnnotations) ++ logAnnotations + loggerName
         )
 
       val fiberRuntime = zio.internal.FiberRuntime(fiberId, fiberRefs, runtime.runtimeFlags)

slf4j2-bridge/src/test/scala/zio/logging/slf4j/bridge/Slf4jBridgeExampleApp.scala

@@ -18,9 +18,7 @@ object Slf4jBridgeExampleApp extends ZIOAppDefault {
   private val logFormat = LogFormat.label(
     "name",
     LoggerNameExtractor.loggerNameAnnotationOrTrace.toLogFormat()
-  ) + LogFormat.logAnnotation(LogAnnotation.UserId) + LogFormat.logAnnotation(
-    LogAnnotation.TraceId
-  ) + LogFormat.default
+  ) + LogFormat.allAnnotations(Set(zio.logging.loggerNameAnnotationKey)) + LogFormat.default
 
   private val loggerConfig = ConsoleLoggerConfig(logFormat, logFilterConfig)
 
@@ -34,7 +32,7 @@ object Slf4jBridgeExampleApp extends ZIOAppDefault {
       _ <- ZIO.logInfo("Start")
       _ <- ZIO.foreachPar(uuids) { u =>
              ZIO.succeed(slf4jLogger.info("Test {}!", "INFO")) *> ZIO.succeed(
-               slf4jLogger.warn("Test {}!", "WARNING")
+               slf4jLogger.atWarn().addArgument("WARNING").log("Test {}!")
              ) @@ LogAnnotation.UserId(
                u.toString
              )

slf4j2-bridge/src/test/scala/zio/logging/slf4j/bridge/Slf4jBridgeSpec.scala

@@ -32,13 +32,15 @@ object Slf4jBridgeSpec extends ZIOSpecDefault {
           _      <-
             (for {
               logger <- ZIO.attempt(org.slf4j.LoggerFactory.getLogger("test.logger"))
-              _      <- ZIO.logSpan("span")(ZIO.attempt(logger.debug("test debug message"))) @@ ZIOAspect
+              _      <- ZIO.logSpan("span")(
+                          ZIO.attempt(logger.atDebug().addKeyValue("k", "v").addArgument("message").log("test debug {}"))
+                        ) @@ ZIOAspect
                           .annotated("trace_id", "tId")
               _      <- ZIO.attempt(logger.warn("hello {}", "world")) @@ ZIOAspect.annotated("user_id", "uId")
               _      <- ZIO.attempt(logger.warn("{}..{}..{} ... go!", "3", "2", "1"))
-              _      <- ZIO.attempt(logger.warn("warn cause", testFailure))
+              _      <- ZIO.attempt(logger.atWarn().setCause(testFailure).setMessage("warn cause").log())
               _      <- ZIO.attempt(logger.error("error", testFailure))
-              _      <- ZIO.attempt(logger.error("error", null))
+              _      <- ZIO.attempt(logger.atError().log("error"))
             } yield ()).exit
           output <- ZTestLogger.logOutput
           lines   = output.map { logEntry =>
@@ -55,7 +57,7 @@ object Slf4jBridgeSpec extends ZIOSpecDefault {
             LogEntry(
               List("test.logger", "span"),
               LogLevel.Debug,
-              Map(zio.logging.loggerNameAnnotationKey -> "test.logger", "trace_id" -> "tId"),
+              Map(zio.logging.loggerNameAnnotationKey -> "test.logger", "trace_id" -> "tId", "k" -> "v"),
               "test debug message",
               Cause.empty
             ),
@@ -174,7 +176,9 @@ object Slf4jBridgeSpec extends ZIOSpecDefault {
                   _       <- ZIO.attempt(logger1.debug("test debug message"))
                   _       <- ZIO.attempt(logger1.warn("test warn message"))
                   _       <- ZIO.attempt(logger2.debug("hello2 {} debug", "world"))
+                  _       <- ZIO.attempt(logger2.atDebug().log("hello2 {} debug", "world"))
                   _       <- ZIO.attempt(logger2.warn("hello2 {} warn", "world"))
+                  _       <- ZIO.attempt(logger3.atDebug().log("hello3 {} info", "world"))
                   _       <- ZIO.attempt(logger3.info("hello3 {} info", "world"))
                   _       <- ZIO.attempt(logger3.warn("hello3 {} warn", "world"))
                 } yield ()).exit