zio-logging improvements (#1154)

* Invoke slf4j initialisation * Add scoped log annotations * Review fixes: init slf4j with default logger name and revert logger name in doc * Fix compilation
tofu-tf · Jul 20, 2023 · 09f10df · 09f10df
1 parent 38c9446
commit 09f10df
Show file tree

Hide file tree

Showing 5 changed files with 75 additions and 12 deletions.
diff --git a/docs/tofu.logging.recipes.zio2.md b/docs/tofu.logging.recipes.zio2.md
@@ -90,6 +90,26 @@ will produce:
 
 You can change the logger name via `ZLogAnnotation.loggerName`.
 
+Also you can create scoped annotations via `ZLogAnnotation.scoped`
+
+```scala
+import tofu.logging.zlogs.ZLogAnnotation._
+
+val httpCode: ZLogAnnotation[Int] = make("httpCode")
+
+override def run = {
+  ZIO.scoped {
+    for {
+      _    <- httpCode.scoped(code)
+      _    <- program
+    } yield ()
+  }
+}.provide(
+  Runtime.removeDefaultLoggers,
+  TofuZLogger.addToRuntime
+)
+```
+
 `ZLogAnnotation.make[A]` implicitly requires a `Loggable[A]` instance, see more
 in [Loggable](./tofu.logging.loggable.md) section.
 

diff --git a/examples/zio2/src/main/scala-2/tofu/example/logging/ZioLoggingNativeExample.scala b/examples/zio2/src/main/scala-2/tofu/example/logging/ZioLoggingNativeExample.scala
@@ -15,6 +15,8 @@ object ZioLoggingNativeExample extends ZIOAppDefault {
                          _ <- ZIO.log("Start request")
                          // {"zSpans":{"backend_2":10,"full_app":35}}
                          _ <- ZIO.sleep(i.seconds)
+                         // every log in scope will contain: "user":{"login":"Vasya","accessLevel":1}
+                         _ <- LogKey.user.scoped(TestUser("Vasya", "12345"))
                          _ <- ZIO.fail(new IllegalStateException(s"$i divided by 3")).when(i % 3 == 0)
                          _ <- ZIO.logInfo("Request completed") // + i seconds:
                          // {"zSpans":{"backend_2":2032,"full_app":2063}}
@@ -40,15 +42,17 @@ object ZioLoggingNativeExample extends ZIOAppDefault {
       ZIO.logSpan("full_app") {
         // logs will contain {"zSpans":{"full_app":6}}: this is
         // the time (milliseconds) spent from the span started
-        for {
-          // adds object with zioAnnotations: {"zSpans":{"full_app":6},"zAnnotations":{"detail":"Good day!"}}
-          _ <- ZIO.logWarning("Hello everybody") @@ ZIOAspect.annotated("detail" -> "Good day!")
-          // adds tofu-anotation for every parallel task:
-          // {"user":{"login":"Vasya","accessLevel":1}}
-          _ <- ZIO.collectAllParDiscard(tasks) @@ LogKey.user(TestUser("Vasya", "12345"))
-          // {"message":"Application shut down","zSpans":{"full_app":3064}}
-          _ <- ZIO.log("Application shut down")
-        } yield ()
+        ZIO.scoped[Any] {
+          for {
+            // adds object with zioAnnotations: {"zSpans":{"full_app":6},"zAnnotations":{"detail":"Good day!"}}
+            _ <- ZIO.logWarning("Hello everybody") @@ ZIOAspect.annotated("detail" -> "Good day!")
+            // adds tofu-anotation for every parallel task:
+            // {"user":{"login":"Vasya","accessLevel":1}}
+            _ <- ZIO.collectAllParDiscard(tasks) @@ LogKey.user(TestUser("Vasya", "12345"))
+            // {"message":"Application shut down","zSpans":{"full_app":3064}}
+            _ <- ZIO.log("Application shut down")
+          } yield ()
+        }
       }
   }
     .provide(

diff --git a/modules/interop/zio2/logging/src/main/scala-2/tofu/logging/zlogs/TofuZLogger.scala b/modules/interop/zio2/logging/src/main/scala-2/tofu/logging/zlogs/TofuZLogger.scala
@@ -9,7 +9,7 @@ import zio._
 
 import java.time.{Clock => JClock}
 
-class TofuZLogger(jc: JClock) extends ZLogger[String, Unit] {
+class TofuZLogger private (jc: JClock) extends ZLogger[String, Unit] {
 
   protected val zioLevel2TofuLevel: LogLevel => Logging.Level = {
     case LogLevel.All     => Logging.Trace
@@ -64,9 +64,18 @@ object TofuZLogger {
     *   }}}
     */
   val addToRuntime: ULayer[Unit] = ZLayer(
-    Clock.javaClock.map(jc => Runtime.addLogger(new TofuZLogger(jc)))
+    Clock.javaClock.map(jc => Runtime.addLogger(TofuZLogger(jc)))
   ).flatten
 
+  def apply(jc: JClock): TofuZLogger = {
+    // get some slf4j logger to invoke slf4j initialisation
+    // as in some program failure cases it may happen, that program exit sooner then log message will be logged
+    // @see https://github.com/zio/zio-logging/issues/616
+    LoggerFactory.getLogger(DefaultLoggerName)
+
+    new TofuZLogger(jc)
+  }
+
   /** Parses logger name from [[Trace]]
     *
     * Trace value ''tofu.example.logging.ZioLoggingNativeExample$.run(ZioLoggingNativeExample.scala:15)'' will be parsed

diff --git a/modules/interop/zio2/logging/src/main/scala-2/tofu/logging/zlogs/ZLogAnnotation.scala b/modules/interop/zio2/logging/src/main/scala-2/tofu/logging/zlogs/ZLogAnnotation.scala
@@ -1,7 +1,7 @@
 package tofu.logging.zlogs
 
 import tofu.logging.{LogAnnotation, Loggable}
-import zio.{Trace, ZIO, ZIOAspect}
+import zio.{Scope, Trace, URIO, ZIO, ZIOAspect}
 
 /** The [[LogAnnotation]] extension allows you add structured log annotations into the default log context. The stored
   * values are accessible via [[TofuDefaultContext]] and would be logged by [[TofuZLogger]].
@@ -26,6 +26,13 @@ class ZLogAnnotation[V](name: String, valueLoggable: Loggable[V]) extends LogAnn
       case None    => ZLogAnnotation.NoopAspect
     }
 
+  def scoped(value: V): URIO[Scope, Unit] =
+    TofuDefaultContext.AnnotatedContextRef
+      .locallyScopedWith(_ + ((this, value)))
+
+  def scoped(value: Option[V]): URIO[Scope, Unit] =
+    value.fold[URIO[Scope, Unit]](ZIO.unit)(scoped)
+
 }
 
 object ZLogAnnotation {

diff --git a/...les/interop/zio2/logging/src/test/scala-2/tofu/logging/zlogs/TofuDefaultContextSpec.scala b/...les/interop/zio2/logging/src/test/scala-2/tofu/logging/zlogs/TofuDefaultContextSpec.scala
@@ -25,6 +25,21 @@ object TofuDefaultContextSpec extends ZIOSpecDefault {
           }
         } @@ LogKey.user(testUser) @@ LogKey.count(testCount) @@ LogKey.status(testStatus)
       }.provide(TofuDefaultContext.layerZioContextOff),
+      test("extracts all values added via ZLogAnnotation.scoped") {
+        ZIO.scoped {
+          for {
+            _      <- scopedTestProg
+            ctx    <- ZIO.service[TofuDefaultContext]
+            status <- ctx.getValue(LogKey.status)
+            user   <- ctx.getValue(LogKey.user)
+            count  <- ctx.getValue(LogKey.count)
+          } yield {
+            assertTrue(status.get == testStatus) &&
+            assertTrue(user.get == testUser) &&
+            assertTrue(count.get == testCount)
+          }
+        }
+      }.provide(TofuDefaultContext.layerZioContextOff),
       test("layerZioContextOffLayer logs only tofu context") {
         testProg.map { ctx =>
           assertTrue(LogTree(ctx) == expectedJsonOnlyTofuContext)
@@ -48,6 +63,14 @@ object TofuDefaultContextSpec extends ZIOSpecDefault {
       ZIO.serviceWithZIO[ContextProvider](_.getCtx)
   ) @@ ZIOAspect.annotated("foo", "bar") @@ LogKey.status(testStatus) @@ LogKey.count(testCount)
 
+  val scopedTestProg: ZIO[Scope, Nothing, Unit] =
+    for {
+      _ <- LogKey.user.scoped(testUser)
+      _ <- LogKey.count.scoped(testCount)
+      _ <- LogKey.status.scoped(Some(testStatus))
+      _ <- TestClock.adjust(adjustDuration)
+    } yield ()
+
   val expectedJsonOnlyTofuContext: Json = JsonObject(
     LogKey.count.name  -> Json.fromInt(testCount),
     LogKey.status.name -> testStatus.asJson