Improve logging configuration

- Log levels of specific loggers can be defined in the config file (doesn't work with env variables) - Log events of background tasks carry now additional data
2025-06-22 02:18:26 +00:00 · 2022-04-30 18:26:19 +02:00
parent c4c5985a6e
commit 5bdf728eb3
12 changed files with 91 additions and 51 deletions
--- a/modules/fts-psql/src/test/scala/docspell/ftspsql/MigrationTest.scala
+++ b/modules/fts-psql/src/test/scala/docspell/ftspsql/MigrationTest.scala
@ -27,9 +27,7 @@ class MigrationTest
    PostgreSQLContainer.Def(DockerImageName.parse("postgres:14"))

  override def docspellLogConfig: LogConfig =
-    LogConfig(Level.Debug, LogConfig.Format.Fancy)
-
-  override def rootMinimumLevel = Level.Warn
+    super.docspellLogConfig.docspellLevel(Level.Debug)

  test("create schema") {
    withContainers { cnt =>
--- a/modules/fts-psql/src/test/scala/docspell/ftspsql/PsqlFtsClientTest.scala
+++ b/modules/fts-psql/src/test/scala/docspell/ftspsql/PsqlFtsClientTest.scala
@ -31,9 +31,7 @@ class PsqlFtsClientTest
  private val table = FtsRepository.table

  override def docspellLogConfig: LogConfig =
-    LogConfig(Level.Debug, LogConfig.Format.Fancy)
-
-  override def rootMinimumLevel = Level.Warn
+    super.docspellLogConfig.docspellLevel(Level.Debug)

  test("insert data into index") {
    withContainers { cnt =>
--- a/modules/joex/src/main/resources/reference.conf
+++ b/modules/joex/src/main/resources/reference.conf
@ -26,7 +26,15 @@ docspell.joex {

    # The minimum level to log. From lowest to highest:
    # Trace, Debug, Info, Warn, Error
-    minimum-level = "Info"
+    minimum-level = "Warn"
+
+    # Override the log level of specific loggers
+    levels = {
+      "docspell" = "Info"
+      "org.flywaydb" = "Info"
+      "binny" = "Info"
+      "org.http4s" = "Info"
+    }
  }

  # The database connection.
--- a/modules/logging/api/src/main/scala/docspell/logging/LogConfig.scala
+++ b/modules/logging/api/src/main/scala/docspell/logging/LogConfig.scala
@ -10,10 +10,26 @@ import cats.data.NonEmptyList

 import io.circe.{Decoder, Encoder}

-final case class LogConfig(minimumLevel: Level, format: LogConfig.Format) {}
+final case class LogConfig(
+    minimumLevel: Level,
+    format: LogConfig.Format,
+    levels: LogConfig.ExtraLevels
+) {
+
+  def clearLevels: LogConfig =
+    copy(levels = Map.empty)
+
+  def withLevel(logger: String, level: Level): LogConfig =
+    copy(levels = levels.updated(logger, level))
+
+  def docspellLevel(level: Level): LogConfig =
+    withLevel("docspell", level)
+}

 object LogConfig {

+  type ExtraLevels = Map[String, Level]
+
  sealed trait Format { self: Product =>
    def name: String =
      productPrefix.toLowerCase
@ -38,8 +54,10 @@ object LogConfig {
  }

  implicit val jsonDecoder: Decoder[LogConfig] =
-    Decoder.forProduct2("minimumLevel", "format")(LogConfig.apply)
+    Decoder.forProduct3("minimumLevel", "format", "levels")(LogConfig.apply)

  implicit val jsonEncoder: Encoder[LogConfig] =
-    Encoder.forProduct2("minimumLevel", "format")(r => (r.minimumLevel, r.format))
+    Encoder.forProduct3("minimumLevel", "format", "levels")(r =>
+      (r.minimumLevel, r.format, r.levels)
+    )
 }
--- a/modules/logging/api/src/main/scala/docspell/logging/LogEvent.scala
+++ b/modules/logging/api/src/main/scala/docspell/logging/LogEvent.scala
@ -26,6 +26,9 @@ final case class LogEvent(
  def data[A: Encoder](key: String, value: => A): LogEvent =
    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)
+
  def addMessage(msg: => String): LogEvent =
    copy(additional = (() => Left(msg)) :: additional)

--- a/modules/logging/scribe/src/main/scala/docspell/logging/impl/ScribeConfigure.scala
+++ b/modules/logging/scribe/src/main/scala/docspell/logging/impl/ScribeConfigure.scala
@ -16,40 +16,36 @@ import scribe.jul.JULHandler
 import scribe.writer.SystemOutWriter

 object ScribeConfigure {
-  private[this] val docspellRootVerbose = "DOCSPELL_ROOT_LOGGER_LEVEL"
-
  def configure[F[_]: Sync](cfg: LogConfig): F[Unit] =
    Sync[F].delay {
      replaceJUL()
-      val docspellLogger = scribe.Logger("docspell")
-
-      unsafeConfigure(scribe.Logger.root, cfg.copy(minimumLevel = getRootMinimumLevel))
-      unsafeConfigure(docspellLogger, cfg)
-      unsafeConfigure(scribe.Logger("org.flywaydb"), cfg)
-      unsafeConfigure(scribe.Logger("binny"), cfg)
-      unsafeConfigure(scribe.Logger("org.http4s"), cfg)
+      unsafeConfigure(cfg)
    }

-  private[this] def getRootMinimumLevel: Level =
-    Option(System.getenv(docspellRootVerbose))
-      .map(Level.fromString)
-      .flatMap {
-        case Right(level) => Some(level)
-        case Left(err) =>
-          scribe.warn(
-            s"Environment variable '$docspellRootVerbose' has invalid value: $err"
-          )
-          None
-      }
-      .getOrElse(Level.Error)
+  def unsafeConfigure(cfg: LogConfig): Unit = {
+    unsafeConfigure(scribe.Logger.root, cfg.format, cfg.minimumLevel)
+    cfg.levels.foreach { case (name, level) =>
+      unsafeConfigure(scribe.Logger(name), cfg.format, level)
+    }
+  }

-  def unsafeConfigure(logger: scribe.Logger, cfg: LogConfig): Unit = {
+  def unsafeConfigure(logger: String, cfg: LogConfig): Unit = {
+    val log = scribe.Logger(logger)
+    val level = cfg.levels.getOrElse(logger, cfg.minimumLevel)
+    unsafeConfigure(log, cfg.format, level)
+  }
+
+  def unsafeConfigure(
+      logger: scribe.Logger,
+      format: LogConfig.Format,
+      level: Level
+  ): Unit = {
    val mods = List[scribe.Logger => scribe.Logger](
      _.clearHandlers(),
-      _.withMinimumLevel(ScribeWrapper.convertLevel(cfg.minimumLevel)),
+      _.withMinimumLevel(ScribeWrapper.convertLevel(level)),
      l =>
        if (logger.id == scribe.Logger.RootId) {
-          cfg.format match {
+          format match {
            case Format.Fancy =>
              l.withHandler(formatter = Formatter.enhanced, writer = SystemOutWriter)
            case Format.Plain =>
--- a/modules/logging/scribe/src/test/scala/docspell/logging/TestLoggingConfig.scala
+++ b/modules/logging/scribe/src/test/scala/docspell/logging/TestLoggingConfig.scala
@ -11,16 +11,13 @@ import docspell.logging.impl.ScribeConfigure
 import munit.Suite

 trait TestLoggingConfig extends Suite {
-  def docspellLogConfig: LogConfig = LogConfig(Level.Warn, LogConfig.Format.Fancy)
+  def docspellLogConfig: LogConfig =
+    LogConfig(rootMinimumLevel, LogConfig.Format.Fancy, Map.empty)
+
  def rootMinimumLevel: Level = Level.Error

  override def beforeAll(): Unit = {
    super.beforeAll()
-    val docspellLogger = scribe.Logger("docspell")
-    ScribeConfigure.unsafeConfigure(docspellLogger, docspellLogConfig)
-    val rootCfg = docspellLogConfig.copy(minimumLevel = rootMinimumLevel)
-    ScribeConfigure.unsafeConfigure(scribe.Logger.root, rootCfg)
-    ()
+    ScribeConfigure.unsafeConfigure(docspellLogConfig)
  }
-
 }
--- a/modules/restserver/src/main/resources/reference.conf
+++ b/modules/restserver/src/main/resources/reference.conf
@ -29,7 +29,15 @@ docspell.server {

    # The minimum level to log. From lowest to highest:
    # Trace, Debug, Info, Warn, Error
-    minimum-level = "Info"
+    minimum-level = "Warn"
+
+    # Override the log level of specific loggers
+    levels = {
+      "docspell" = "Info"
+      "org.flywaydb" = "Info"
+      "binny" = "Info"
+      "org.http4s" = "Info"
+    }
  }

  # Where the server binds to.
--- a/modules/scheduler/impl/src/main/scala/docspell/scheduler/impl/LogEvent.scala
+++ b/modules/scheduler/impl/src/main/scala/docspell/scheduler/impl/LogEvent.scala
@ -11,6 +11,8 @@ import cats.implicits._

 import docspell.common._

+import io.circe.Json
+
 case class LogEvent(
    jobId: Ident,
    taskName: Ident,
@ -19,7 +21,8 @@ case class LogEvent(
    time: Timestamp,
    level: LogLevel,
    msg: String,
-    ex: Option[Throwable] = None
+    ex: Option[Throwable],
+    data: Map[String, Json]
 ) {

  def logLine: String =
@ -35,10 +38,11 @@ object LogEvent {
      group: Ident,
      jobInfo: String,
      level: LogLevel,
-      msg: String
+      msg: String,
+      data: Map[String, Json]
  ): F[LogEvent] =
    Timestamp
      .current[F]
-      .map(now => LogEvent(jobId, taskName, group, jobInfo, now, level, msg))
+      .map(now => LogEvent(jobId, taskName, group, jobInfo, now, level, msg, None, data))

 }
--- a/modules/scheduler/impl/src/main/scala/docspell/scheduler/impl/LogSink.scala
+++ b/modules/scheduler/impl/src/main/scala/docspell/scheduler/impl/LogSink.scala
@ -29,12 +29,13 @@ object LogSink {
    }

  def logInternal[F[_]: Sync](e: LogEvent): F[Unit] = {
-    val logger = docspell.logging.getLogger[F]
+    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)

    e.level match {
      case LogLevel.Info =>
--- a/modules/scheduler/impl/src/main/scala/docspell/scheduler/impl/QueueLogger.scala
+++ b/modules/scheduler/impl/src/main/scala/docspell/scheduler/impl/QueueLogger.scala
@ -15,6 +15,9 @@ import docspell.common.{Ident, LogLevel}
 import docspell.logging
 import docspell.logging.{Level, Logger}

+/** Background tasks use this logger to emit the log events to a queue. The consumer is
+  * [[LogSink]], which picks up log events in a separate thread.
+  */
 object QueueLogger {

  def create[F[_]: Sync](
@ -34,7 +37,8 @@ object QueueLogger {
            group,
            jobInfo,
            level2Level(logEvent.level),
-            logEvent.msg()
+            logEvent.msg(),
+            logEvent.data.view.mapValues(f => f()).toMap
          )
          .flatMap { ev =>
            val event =