Merge pull request #1535 from eikek/logging-improvements

Improve logging configuration

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)
+    super.docspellLogConfig.docspellLevel(Level.Debug)
-
-  override def rootMinimumLevel = Level.Warn
 
   test("create schema") {
     withContainers { cnt =>

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)
+    super.docspellLogConfig.docspellLevel(Level.Debug)
-
-  override def rootMinimumLevel = Level.Warn
 
   test("insert data into index") {
     withContainers { cnt =>

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.

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)
+    )
 }

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)
 

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

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(docspellLogConfig)
-    ScribeConfigure.unsafeConfigure(docspellLogger, docspellLogConfig)
-    val rootCfg = docspellLogConfig.copy(minimumLevel = rootMinimumLevel)
-    ScribeConfigure.unsafeConfigure(scribe.Logger.root, rootCfg)
-    ()
   }
-
 }

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.

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))
 
 }

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 =>

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 =

website/site/content/docs/configure/main.md

@@ -158,9 +158,9 @@ Please have a look at the corresponding
 
 # Logging
 
-By default, docspell logs to stdout. This works well, when managed by
+Docspell logs to stdout. This works well, when managed by systemd or
-systemd or other inits. Logging can be configured in the configuration
+similar tools. Logging can be configured in the configuration file or
-file or via environment variables. There are only two settings:
+via environment variables. There are these settings:
 
 - `minimum-level` specifies the log level to control the verbosity.
   Levels are ordered from: *Trace*, *Debug*, *Info*, *Warn* and
@@ -169,8 +169,13 @@ file or via environment variables. There are only two settings:
   formats for humans: *Plain* and *Fancy*. And two more suited for
   machine consumption: *Json* and *Logfmt*. The *Json* format contains
   all details, while the others may omit some for readability
+- `levels` optional _logger name_ to _level_ mappings to override the
+  log level for specific loggers. If not mentioned here, everything is
+  logged with `minimum-level`.
 
-These settings are the same for joex and the restserver component.
+The default settings for joex and restserver are the same and
+configure a minimum level of `Warn` and override some loggers with
+`Info`.
 
 # Default Config
 ## Rest Server