From 506fbcbcb71eac1f74acdb41e89ddc089139dc0d Mon Sep 17 00:00:00 2001 From: eikek Date: Sun, 1 May 2022 12:15:42 +0200 Subject: [PATCH] Improve log events, adding new logger to capture data --- .../docspell/logging/AndThenLogger.scala | 4 +- .../docspell/logging/CapturedLogger.scala | 41 +++++++++++++++ .../main/scala/docspell/logging/LazyMap.scala | 46 +++++++++++++++++ .../scala/docspell/logging/LogEvent.scala | 19 +++---- .../main/scala/docspell/logging/Logger.scala | 28 +++++++--- .../docspell/logging/LoggerExtension.scala | 2 +- .../docspell/logging/CapturedLoggerTest.scala | 26 ++++++++++ .../scala/docspell/logging/LazyMapTest.scala | 51 +++++++++++++++++++ .../scala/docspell/logging/TestLogger.scala | 30 +++++++++++ .../docspell/logging/impl/ScribeWrapper.scala | 16 +++--- .../docspell/scheduler/impl/LogSink.scala | 24 ++++----- .../docspell/scheduler/impl/QueueLogger.scala | 4 +- 12 files changed, 247 insertions(+), 44 deletions(-) create mode 100644 modules/logging/api/src/main/scala/docspell/logging/CapturedLogger.scala create mode 100644 modules/logging/api/src/main/scala/docspell/logging/LazyMap.scala create mode 100644 modules/logging/api/src/test/scala/docspell/logging/CapturedLoggerTest.scala create mode 100644 modules/logging/api/src/test/scala/docspell/logging/LazyMapTest.scala create mode 100644 modules/logging/api/src/test/scala/docspell/logging/TestLogger.scala diff --git a/modules/logging/api/src/main/scala/docspell/logging/AndThenLogger.scala b/modules/logging/api/src/main/scala/docspell/logging/AndThenLogger.scala index e5109504..eead20db 100644 --- a/modules/logging/api/src/main/scala/docspell/logging/AndThenLogger.scala +++ b/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 } diff --git a/modules/logging/api/src/main/scala/docspell/logging/CapturedLogger.scala b/modules/logging/api/src/main/scala/docspell/logging/CapturedLogger.scala new file mode 100644 index 00000000..ac10569a --- /dev/null +++ b/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) + } +} diff --git a/modules/logging/api/src/main/scala/docspell/logging/LazyMap.scala b/modules/logging/api/src/main/scala/docspell/logging/LazyMap.scala new file mode 100644 index 00000000..76224cf5 --- /dev/null +++ b/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) + } +} diff --git a/modules/logging/api/src/main/scala/docspell/logging/LogEvent.scala b/modules/logging/api/src/main/scala/docspell/logging/LogEvent.scala index 0536285d..3ab122ea 100644 --- a/modules/logging/api/src/main/scala/docspell/logging/LogEvent.scala +++ b/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], - data: Map[String, () => Json], + additional: LazyList[LogEvent.AdditionalMsg], + 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) } diff --git a/modules/logging/api/src/main/scala/docspell/logging/Logger.scala b/modules/logging/api/src/main/scala/docspell/logging/Logger.scala index 18359294..0b8997e8 100644 --- a/modules/logging/api/src/main/scala/docspell/logging/Logger.scala +++ b/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) diff --git a/modules/logging/api/src/main/scala/docspell/logging/LoggerExtension.scala b/modules/logging/api/src/main/scala/docspell/logging/LoggerExtension.scala index 0e2597af..c3110032 100644 --- a/modules/logging/api/src/main/scala/docspell/logging/LoggerExtension.scala +++ b/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 diff --git a/modules/logging/api/src/test/scala/docspell/logging/CapturedLoggerTest.scala b/modules/logging/api/src/test/scala/docspell/logging/CapturedLoggerTest.scala new file mode 100644 index 00000000..c4e6aa86 --- /dev/null +++ b/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)) +} diff --git a/modules/logging/api/src/test/scala/docspell/logging/LazyMapTest.scala b/modules/logging/api/src/test/scala/docspell/logging/LazyMapTest.scala new file mode 100644 index 00000000..9ee95c64 --- /dev/null +++ b/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 + } +} diff --git a/modules/logging/api/src/test/scala/docspell/logging/TestLogger.scala b/modules/logging/api/src/test/scala/docspell/logging/TestLogger.scala new file mode 100644 index 00000000..9c83eb2f --- /dev/null +++ b/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 +} diff --git a/modules/logging/scribe/src/main/scala/docspell/logging/impl/ScribeWrapper.scala b/modules/logging/scribe/src/main/scala/docspell/logging/impl/ScribeWrapper.scala index 1eeadaed..d547225c 100644 --- a/modules/logging/scribe/src/main/scala/docspell/logging/impl/ScribeWrapper.scala +++ b/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 => - x() match { - case Right(ex) => Message.static(ex) - case Left(msg) => Message.static(msg) - } - } + val additional: List[LoggableMessage] = ev.additional.map { + case Right(ex) => Message.static(ex) + 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) } } diff --git a/modules/scheduler/impl/src/main/scala/docspell/scheduler/impl/LogSink.scala b/modules/scheduler/impl/src/main/scala/docspell/scheduler/impl/LogSink.scala index 7f3fec66..5ebfd665 100644 --- a/modules/scheduler/impl/src/main/scala/docspell/scheduler/impl/LogSink.scala +++ b/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 addData: logging.LogEvent => logging.LogEvent = - _.data("jobId", e.jobId) - .data("task", e.taskName) - .data("group", e.group) - .data("jobInfo", e.jobInfo) - .addData(e.data) + val logger = docspell.logging + .getLogger[F] + .capture("jobId", e.jobId) + .capture("task", e.taskName) + .capture("group", e.group) + .capture("jobInfo", e.jobInfo) 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) } } } diff --git a/modules/scheduler/impl/src/main/scala/docspell/scheduler/impl/QueueLogger.scala b/modules/scheduler/impl/src/main/scala/docspell/scheduler/impl/QueueLogger.scala index 23e03ba8..50410e65 100644 --- a/modules/scheduler/impl/src/main/scala/docspell/scheduler/impl/QueueLogger.scala +++ b/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 =