Merge pull request #1537 from eikek/logging-improvement2

Improve log events, adding new logger to capture data

modules/logging/api/src/main/scala/docspell/logging/AndThenLogger.scala

@@ -13,12 +13,12 @@ import cats.{Applicative, Id}
 final private[logging] class AndThenLogger[F[_]: Applicative](
     val loggers: NonEmptyList[Logger[F]]
 ) extends Logger[F] {
-  def log(ev: LogEvent): F[Unit] =
+  def log(ev: => LogEvent): F[Unit] =
     loggers.traverse(_.log(ev)).as(())
 
   def asUnsafe: Logger[Id] =
     new Logger[Id] { self =>
-      def log(ev: LogEvent): Unit =
+      def log(ev: => LogEvent): Unit =
         loggers.toList.foreach(_.asUnsafe.log(ev))
       def asUnsafe = self
     }

modules/logging/api/src/main/scala/docspell/logging/CapturedLogger.scala

@@ -0,0 +1,41 @@
+/*
+ * Copyright 2020 Eike K. & Contributors
+ *
+ * SPDX-License-Identifier: AGPL-3.0-or-later
+ */
+
+package docspell.logging
+
+import cats.Id
+
+import io.circe.Json
+
+final private class CapturedLogger[F[_]] private (
+    val data: LazyMap[String, Json],
+    val delegate: Logger[F]
+) extends Logger[F] {
+
+  def log(ev: => LogEvent) =
+    delegate.log(ev.copy(data = ev.data ++ data))
+
+  def asUnsafe: Logger[Id] = {
+    val self = delegate.asUnsafe
+    new Logger[Id] {
+      def log(ev: => LogEvent): Unit =
+        self.log(ev.copy(data = ev.data ++ data))
+
+      def asUnsafe = this
+    }
+  }
+}
+
+object CapturedLogger {
+
+  def apply[F[_]](logger: Logger[F], data: LazyMap[String, Json]): Logger[F] =
+    logger match {
+      case cl: CapturedLogger[F] =>
+        new CapturedLogger[F](cl.data ++ data, cl.delegate)
+      case _ =>
+        new CapturedLogger[F](data, logger)
+    }
+}

modules/logging/api/src/main/scala/docspell/logging/LazyMap.scala

@@ -0,0 +1,46 @@
+/*
+ * Copyright 2020 Eike K. & Contributors
+ *
+ * SPDX-License-Identifier: AGPL-3.0-or-later
+ */
+
+package docspell.logging
+
+import docspell.logging.LazyMap.Val
+
+final class LazyMap[A, B](
+    private val values: Map[A, Val[B]]
+) {
+  lazy val toMap: Map[A, B] = values.view.mapValues(_.value).toMap
+
+  def updated(key: A, value: => B): LazyMap[A, B] =
+    new LazyMap(values.updated(key, Val(value)))
+
+  def get(key: A): Option[() => B] =
+    values.get(key).map(e => () => e.value)
+
+  def ++(lm: LazyMap[A, B]): LazyMap[A, B] =
+    new LazyMap(values ++ lm.values)
+
+  def addMap(m: Map[A, B]): LazyMap[A, B] =
+    this ++ LazyMap.fromMap(m)
+
+  def toDeferred: Map[A, () => B] =
+    values.view.mapValues(e => () => e.value).toMap
+}
+
+object LazyMap {
+  private[this] val emptyMap = new LazyMap[Any, Any](Map.empty)
+
+  def empty[A, B]: LazyMap[A, B] = emptyMap.asInstanceOf[LazyMap[A, B]]
+
+  def fromMap[A, B](m: Map[A, B]): LazyMap[A, B] =
+    new LazyMap(m.view.mapValues(a => Val(a)).toMap)
+
+  final private class Val[B](v: => B) {
+    lazy val value = v
+  }
+  private object Val {
+    def apply[B](v: => B): Val[B] = new Val(v)
+  }
+}

modules/logging/api/src/main/scala/docspell/logging/LogEvent.scala

@@ -12,8 +12,8 @@ import sourcecode._
 final case class LogEvent(
     level: Level,
     msg: () => String,
-    additional: List[() => LogEvent.AdditionalMsg],
+    additional: LazyList[LogEvent.AdditionalMsg],
-    data: Map[String, () => Json],
+    data: LazyMap[String, Json],
     pkg: Pkg,
     fileName: FileName,
     name: Name,
@@ -24,21 +24,21 @@ final case class LogEvent(
     s"${level.name} ${name.value}/${fileName}:${line.value} - ${msg()}"
 
   def data[A: Encoder](key: String, value: => A): LogEvent =
-    copy(data = data.updated(key, () => Encoder[A].apply(value)))
+    copy(data = data.updated(key, Encoder[A].apply(value)))
 
   def addData(m: Map[String, Json]): LogEvent =
-    copy(data = data ++ m.view.mapValues(json => () => json).toMap)
+    copy(data = data.addMap(m))
 
   def addMessage(msg: => String): LogEvent =
-    copy(additional = (() => Left(msg)) :: additional)
+    copy(additional = Left(msg) #:: additional)
 
   def addError(ex: Throwable): LogEvent =
-    copy(additional = (() => Right(ex)) :: additional)
+    copy(additional = Right(ex) #:: additional)
 
   def findErrors: List[Throwable] =
-    additional.map(a => a()).collect { case Right(ex) =>
+    additional.collect { case Right(ex) =>
       ex
-    }
+    }.toList
 }
 
 object LogEvent {
@@ -50,5 +50,6 @@ object LogEvent {
       fileName: FileName,
       name: Name,
       line: Line
-  ): LogEvent = LogEvent(l, () => m, Nil, Map.empty, pkg, fileName, name, line)
+  ): LogEvent =
+    LogEvent(l, () => m, LazyList.empty, LazyMap.empty, pkg, fileName, name, line)
 }

modules/logging/api/src/main/scala/docspell/logging/Logger.scala

@@ -13,16 +13,28 @@ import cats.effect.{Ref, Sync}
 import cats.syntax.applicative._
 import cats.syntax.functor._
 import cats.syntax.order._
-import cats.{Applicative, Id}
+import cats.{Applicative, Functor, Id}
 
+import io.circe.{Encoder, Json}
 import sourcecode._
 
 trait Logger[F[_]] extends LoggerExtension[F] {
 
-  def log(ev: LogEvent): F[Unit]
+  def log(ev: => LogEvent): F[Unit]
 
   def asUnsafe: Logger[Id]
 
+  def captureAll(data: LazyMap[String, Json]): Logger[F] =
+    CapturedLogger(this, data)
+
+  def captureAll(data: Map[String, Json]): Logger[F] =
+    CapturedLogger(this, LazyMap.fromMap(data))
+
+  def capture[A: Encoder](key: String, value: => A): Logger[F] = {
+    val enc = Encoder[A]
+    CapturedLogger(this, LazyMap.empty[String, Json].updated(key, enc(value)))
+  }
+
   def trace(msg: => String)(implicit
       pkg: Pkg,
       fileName: FileName,
@@ -123,22 +135,22 @@ trait Logger[F[_]] extends LoggerExtension[F] {
 object Logger {
   def off: Logger[Id] =
     new Logger[Id] {
-      def log(ev: LogEvent): Unit = ()
+      def log(ev: => LogEvent): Unit = ()
       def asUnsafe = this
     }
 
   def offF[F[_]: Applicative]: Logger[F] =
     new Logger[F] {
-      def log(ev: LogEvent) = ().pure[F]
+      def log(ev: => LogEvent) = ().pure[F]
       def asUnsafe = off
     }
 
-  def buffer[F[_]: Sync](): F[(Ref[F, Vector[LogEvent]], Logger[F])] =
+  def buffer[F[_]: Ref.Make: Functor](): F[(Ref[F, Vector[LogEvent]], Logger[F])] =
     for {
       buffer <- Ref.of[F, Vector[LogEvent]](Vector.empty[LogEvent])
       logger =
         new Logger[F] {
-          def log(ev: LogEvent) =
+          def log(ev: => LogEvent) =
             buffer.update(_.appended(ev))
           def asUnsafe = off
         }
@@ -147,7 +159,7 @@ object Logger {
   /** Just prints to the given print stream. Useful for testing. */
   def simple(ps: PrintStream, minimumLevel: Level): Logger[Id] =
     new Logger[Id] {
-      def log(ev: LogEvent): Unit =
+      def log(ev: => LogEvent): Unit =
         if (ev.level >= minimumLevel)
           ps.println(s"${Instant.now()} [${Thread.currentThread()}] ${ev.asString}")
         else
@@ -158,7 +170,7 @@ object Logger {
 
   def simpleF[F[_]: Sync](ps: PrintStream, minimumLevel: Level): Logger[F] =
     new Logger[F] {
-      def log(ev: LogEvent) =
+      def log(ev: => LogEvent) =
         Sync[F].delay(asUnsafe.log(ev))
 
       val asUnsafe = simple(ps, minimumLevel)

modules/logging/api/src/main/scala/docspell/logging/LoggerExtension.scala

@@ -13,7 +13,7 @@ trait LoggerExtension[F[_]] { self: Logger[F] =>
 
   def stream: Logger[Stream[F, *]] =
     new Logger[Stream[F, *]] {
-      def log(ev: LogEvent) =
+      def log(ev: => LogEvent) =
         Stream.eval(self.log(ev))
 
       def asUnsafe = self.asUnsafe

modules/logging/api/src/test/scala/docspell/logging/CapturedLoggerTest.scala

@@ -0,0 +1,26 @@
+/*
+ * Copyright 2020 Eike K. & Contributors
+ *
+ * SPDX-License-Identifier: AGPL-3.0-or-later
+ */
+
+package docspell.logging
+
+import io.circe.{Encoder, Json}
+import munit.FunSuite
+
+class CapturedLoggerTest extends FunSuite {
+
+  test("capture data") {
+    val logger = TestLogger()
+    logger.capture("collective", "demo").capture("id", 1).info("hello")
+
+    assertEquals(
+      logger.getEvents.head.data.toMap,
+      Map(t("collective" -> "demo"), t("id" -> 1))
+    )
+  }
+
+  def t[A: Encoder](e: (String, A)): (String, Json) =
+    (e._1, Encoder[A].apply(e._2))
+}

modules/logging/api/src/test/scala/docspell/logging/LazyMapTest.scala

@@ -0,0 +1,51 @@
+/*
+ * Copyright 2020 Eike K. & Contributors
+ *
+ * SPDX-License-Identifier: AGPL-3.0-or-later
+ */
+
+package docspell.logging
+
+import java.util.concurrent.atomic.AtomicInteger
+
+import munit.FunSuite
+
+class LazyMapTest extends FunSuite {
+  test("updated value lazy") {
+    val counter = new AtomicInteger(0)
+    val lm = LazyMap
+      .empty[String, Int]
+      .updated("test", produce(counter, 1))
+
+    assertEquals(counter.get(), 0)
+    assertEquals(lm.toMap("test"), 1)
+    assertEquals(counter.get(), 1)
+
+    for (_ <- 1 to 10) {
+      assertEquals(lm.toMap("test"), 1)
+      assertEquals(counter.get(), 1)
+    }
+  }
+
+  test("get doesn't evaluate value") {
+    val counter = new AtomicInteger(0)
+    val lm = LazyMap
+      .empty[String, Int]
+      .updated("test", produce(counter, 1))
+
+    val v = lm.get("test")
+    assert(v.isDefined)
+    assertEquals(counter.get(), 0)
+
+    assertEquals(v.get(), 1)
+    assertEquals(counter.get(), 1)
+
+    assertEquals(v.get(), 1)
+    assertEquals(counter.get(), 1)
+  }
+
+  def produce(counter: AtomicInteger, n: Int): Int = {
+    counter.incrementAndGet()
+    n
+  }
+}

modules/logging/api/src/test/scala/docspell/logging/TestLogger.scala

@@ -0,0 +1,30 @@
+/*
+ * Copyright 2020 Eike K. & Contributors
+ *
+ * SPDX-License-Identifier: AGPL-3.0-or-later
+ */
+
+package docspell.logging
+
+import java.util.concurrent.atomic.AtomicReference
+
+import cats.Id
+
+class TestLogger extends Logger[Id] {
+
+  private[this] val events: AtomicReference[Vector[LogEvent]] =
+    new AtomicReference(Vector.empty)
+
+  def log(ev: => LogEvent): Id[Unit] = {
+    events.getAndUpdate(v => v :+ ev)
+    ()
+  }
+
+  def getEvents: Vector[LogEvent] = events.get()
+
+  def asUnsafe = this
+}
+
+object TestLogger {
+  def apply(): TestLogger = new TestLogger
+}

modules/logging/scribe/src/main/scala/docspell/logging/impl/ScribeWrapper.scala

@@ -18,13 +18,13 @@ private[logging] object ScribeWrapper {
   final class ImplUnsafe(log: scribe.Logger) extends Logger[Id] {
     override def asUnsafe = this
 
-    override def log(ev: LogEvent): Unit =
+    override def log(ev: => LogEvent): Unit =
       log.log(convert(ev))
   }
   final class Impl[F[_]: Sync](log: scribe.Logger) extends Logger[F] {
     override def asUnsafe = new ImplUnsafe(log)
 
-    override def log(ev: LogEvent) =
+    override def log(ev: => LogEvent) =
       Sync[F].delay(log.log(convert(ev)))
   }
 
@@ -40,13 +40,11 @@ private[logging] object ScribeWrapper {
 
   private[this] def convert(ev: LogEvent) = {
     val level = convertLevel(ev.level)
-    val additional: List[LoggableMessage] = ev.additional.map { x =>
+    val additional: List[LoggableMessage] = ev.additional.map {
-      x() match {
+      case Right(ex) => Message.static(ex)
-        case Right(ex) => Message.static(ex)
+      case Left(msg) => Message.static(msg)
-        case Left(msg) => Message.static(msg)
+    }.toList
-      }
-    }
     LoggerSupport(level, ev.msg(), additional, ev.pkg, ev.fileName, ev.name, ev.line)
-      .copy(data = ev.data)
+      .copy(data = ev.data.toDeferred)
   }
 }

modules/scheduler/impl/src/main/scala/docspell/scheduler/impl/LogSink.scala

@@ -11,7 +11,6 @@ import cats.implicits._
 import fs2.Pipe
 
 import docspell.common._
-import docspell.logging
 import docspell.store.Store
 import docspell.store.records.RJobLog
 
@@ -29,27 +28,26 @@ object LogSink {
     }
 
   def logInternal[F[_]: Sync](e: LogEvent): F[Unit] = {
-    val logger = docspell.logging.getLogger[F](e.taskName.id)
+    val logger = docspell.logging
-    val addData: logging.LogEvent => logging.LogEvent =
+      .getLogger[F]
-      _.data("jobId", e.jobId)
+      .capture("jobId", e.jobId)
-        .data("task", e.taskName)
+      .capture("task", e.taskName)
-        .data("group", e.group)
+      .capture("group", e.group)
-        .data("jobInfo", e.jobInfo)
+      .capture("jobInfo", e.jobInfo)
-        .addData(e.data)
 
     e.level match {
       case LogLevel.Info =>
-        logger.infoWith(e.logLine)(addData)
+        logger.info(e.logLine)
       case LogLevel.Debug =>
-        logger.debugWith(e.logLine)(addData)
+        logger.debug(e.logLine)
       case LogLevel.Warn =>
-        logger.warnWith(e.logLine)(addData)
+        logger.warn(e.logLine)
       case LogLevel.Error =>
         e.ex match {
           case Some(exc) =>
-            logger.errorWith(e.logLine)(addData.andThen(_.addError(exc)))
+            logger.error(exc)(e.logLine)
           case None =>
-            logger.errorWith(e.logLine)(addData)
+            logger.error(e.logLine)
         }
     }
   }

modules/scheduler/impl/src/main/scala/docspell/scheduler/impl/QueueLogger.scala

@@ -29,7 +29,7 @@ object QueueLogger {
   ): Logger[F] =
     new Logger[F] {
 
-      def log(logEvent: logging.LogEvent) =
+      def log(logEvent: => logging.LogEvent) =
         LogEvent
           .create[F](
             jobId,
@@ -38,7 +38,7 @@ object QueueLogger {
             jobInfo,
             level2Level(logEvent.level),
             logEvent.msg(),
-            logEvent.data.view.mapValues(f => f()).toMap
+            logEvent.data.toMap
           )
           .flatMap { ev =>
             val event =