Add a new module to take care of logging

It is based on outr/scribe; mainly providing a json log format and
much easier configuration.

build.sbt

@@ -313,6 +313,19 @@ val common = project
         Dependencies.calevCirce
   )
 
+val logging = project
+  .in(file("modules/logging"))
+  .disablePlugins(RevolverPlugin)
+  .settings(sharedSettings)
+  .settings(testSettingsMUnit)
+  .settings(
+    name := "docspell-logging",
+    libraryDependencies ++=
+      Dependencies.scribe ++
+        Dependencies.catsEffect ++
+        Dependencies.circeCore
+  )
+
 val config = project
   .in(file("modules/config"))
   .disablePlugins(RevolverPlugin)
@@ -869,6 +882,7 @@ val root = project
   )
   .aggregate(
     common,
+    logging,
     config,
     extract,
     convert,

modules/logging/src/main/scala/docspell/logging/Level.scala

@@ -0,0 +1,57 @@
+/*
+ * Copyright 2020 Eike K. & Contributors
+ *
+ * SPDX-License-Identifier: AGPL-3.0-or-later
+ */
+
+package docspell.logging
+
+import cats.Order
+import cats.data.NonEmptyList
+
+import io.circe.{Decoder, Encoder}
+
+sealed trait Level { self: Product =>
+  val name: String =
+    productPrefix.toUpperCase
+
+  val value: Double
+}
+
+object Level {
+  case object Fatal extends Level {
+    val value = 600.0
+  }
+  case object Error extends Level {
+    val value = 500.0
+  }
+  case object Warn extends Level {
+    val value = 400.0
+  }
+  case object Info extends Level {
+    val value = 300.0
+  }
+  case object Debug extends Level {
+    val value = 200.0
+  }
+  case object Trace extends Level {
+    val value = 100.0
+  }
+
+  val all: NonEmptyList[Level] =
+    NonEmptyList.of(Fatal, Error, Warn, Info, Debug, Trace)
+
+  def fromString(str: String): Either[String, Level] = {
+    val s = str.toUpperCase
+    all.find(_.name == s).toRight(s"Invalid level name: $str")
+  }
+
+  implicit val order: Order[Level] =
+    Order.by(_.value)
+
+  implicit val jsonEncoder: Encoder[Level] =
+    Encoder.encodeString.contramap(_.name)
+
+  implicit val jsonDecoder: Decoder[Level] =
+    Decoder.decodeString.emap(fromString)
+}

modules/logging/src/main/scala/docspell/logging/LogConfig.scala

@@ -0,0 +1,45 @@
+/*
+ * Copyright 2020 Eike K. & Contributors
+ *
+ * SPDX-License-Identifier: AGPL-3.0-or-later
+ */
+
+package docspell.logging
+
+import cats.data.NonEmptyList
+
+import io.circe.{Decoder, Encoder}
+
+final case class LogConfig(minimumLevel: Level, format: LogConfig.Format) {}
+
+object LogConfig {
+
+  sealed trait Format { self: Product =>
+    def name: String =
+      productPrefix.toLowerCase
+  }
+  object Format {
+    case object Plain extends Format
+    case object Fancy extends Format
+    case object Json extends Format
+    case object Logfmt extends Format
+
+    val all: NonEmptyList[Format] =
+      NonEmptyList.of(Plain, Fancy, Json, Logfmt)
+
+    def fromString(str: String): Either[String, Format] =
+      all.find(_.name.equalsIgnoreCase(str)).toRight(s"Invalid format name: $str")
+
+    implicit val jsonDecoder: Decoder[Format] =
+      Decoder.decodeString.emap(fromString)
+
+    implicit val jsonEncoder: Encoder[Format] =
+      Encoder.encodeString.contramap(_.name)
+  }
+
+  implicit val jsonDecoder: Decoder[LogConfig] =
+    Decoder.forProduct2("minimumLevel", "format")(LogConfig.apply)
+
+  implicit val jsonEncoder: Encoder[LogConfig] =
+    Encoder.forProduct2("minimumLevel", "format")(r => (r.minimumLevel, r.format))
+}

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

@@ -0,0 +1,43 @@
+/*
+ * Copyright 2020 Eike K. & Contributors
+ *
+ * SPDX-License-Identifier: AGPL-3.0-or-later
+ */
+
+package docspell.logging
+
+import io.circe.{Encoder, Json}
+import sourcecode._
+
+final case class LogEvent(
+    level: Level,
+    msg: () => String,
+    additional: List[() => LogEvent.AdditionalMsg],
+    data: Map[String, () => Json],
+    pkg: Pkg,
+    fileName: FileName,
+    name: Name,
+    line: Line
+) {
+
+  def data[A: Encoder](key: String, value: => A): LogEvent =
+    copy(data = data.updated(key, () => Encoder[A].apply(value)))
+
+  def addMessage(msg: => String): LogEvent =
+    copy(additional = (() => Left(msg)) :: additional)
+
+  def addError(ex: Throwable): LogEvent =
+    copy(additional = (() => Right(ex)) :: additional)
+}
+
+object LogEvent {
+
+  type AdditionalMsg = Either[String, Throwable]
+
+  def of(l: Level, m: => String)(implicit
+      pkg: Pkg,
+      fileName: FileName,
+      name: Name,
+      line: Line
+  ): LogEvent = LogEvent(l, () => m, Nil, Map.empty, pkg, fileName, name, line)
+}

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

@@ -0,0 +1,128 @@
+/*
+ * Copyright 2020 Eike K. & Contributors
+ *
+ * SPDX-License-Identifier: AGPL-3.0-or-later
+ */
+
+package docspell.logging
+
+import cats.Id
+import cats.effect.Sync
+
+import docspell.logging.impl.LoggerWrapper
+
+import sourcecode._
+
+trait Logger[F[_]] {
+
+  def log(ev: LogEvent): F[Unit]
+
+  def asUnsafe: Logger[Id]
+
+  def trace(msg: => String)(implicit
+      pkg: Pkg,
+      fileName: FileName,
+      name: Name,
+      line: Line
+  ): F[Unit] =
+    log(LogEvent.of(Level.Trace, msg))
+
+  def traceWith(msg: => String)(modify: LogEvent => LogEvent)(implicit
+      pkg: Pkg,
+      fileName: FileName,
+      name: Name,
+      line: Line
+  ): F[Unit] =
+    log(modify(LogEvent.of(Level.Trace, msg)))
+
+  def debug(msg: => String)(implicit
+      pkg: Pkg,
+      fileName: FileName,
+      name: Name,
+      line: Line
+  ): F[Unit] =
+    log(LogEvent.of(Level.Debug, msg))
+
+  def debugWith(msg: => String)(modify: LogEvent => LogEvent)(implicit
+      pkg: Pkg,
+      fileName: FileName,
+      name: Name,
+      line: Line
+  ): F[Unit] =
+    log(modify(LogEvent.of(Level.Debug, msg)))
+
+  def info(msg: => String)(implicit
+      pkg: Pkg,
+      fileName: FileName,
+      name: Name,
+      line: Line
+  ): F[Unit] =
+    log(LogEvent.of(Level.Info, msg))
+
+  def infoWith(msg: => String)(modify: LogEvent => LogEvent)(implicit
+      pkg: Pkg,
+      fileName: FileName,
+      name: Name,
+      line: Line
+  ): F[Unit] =
+    log(modify(LogEvent.of(Level.Info, msg)))
+
+  def warn(msg: => String)(implicit
+      pkg: Pkg,
+      fileName: FileName,
+      name: Name,
+      line: Line
+  ): F[Unit] =
+    log(LogEvent.of(Level.Warn, msg))
+
+  def warnWith(msg: => String)(modify: LogEvent => LogEvent)(implicit
+      pkg: Pkg,
+      fileName: FileName,
+      name: Name,
+      line: Line
+  ): F[Unit] =
+    log(modify(LogEvent.of(Level.Warn, msg)))
+
+  def warn(ex: Throwable)(msg: => String)(implicit
+      pkg: Pkg,
+      fileName: FileName,
+      name: Name,
+      line: Line
+  ): F[Unit] =
+    log(LogEvent.of(Level.Warn, msg).addError(ex))
+
+  def error(msg: => String)(implicit
+      pkg: Pkg,
+      fileName: FileName,
+      name: Name,
+      line: Line
+  ): F[Unit] =
+    log(LogEvent.of(Level.Error, msg))
+
+  def errorWith(msg: => String)(modify: LogEvent => LogEvent)(implicit
+      pkg: Pkg,
+      fileName: FileName,
+      name: Name,
+      line: Line
+  ): F[Unit] =
+    log(modify(LogEvent.of(Level.Error, msg)))
+
+  def error(ex: Throwable)(msg: => String)(implicit
+      pkg: Pkg,
+      fileName: FileName,
+      name: Name,
+      line: Line
+  ): F[Unit] =
+    log(LogEvent.of(Level.Error, msg).addError(ex))
+}
+
+object Logger {
+  def unsafe(name: String): Logger[Id] =
+    new LoggerWrapper.ImplUnsafe(scribe.Logger(name))
+
+  def apply[F[_]: Sync](name: String): Logger[F] =
+    new LoggerWrapper.Impl[F](scribe.Logger(name))
+
+  def apply[F[_]: Sync](clazz: Class[_]): Logger[F] =
+    new LoggerWrapper.Impl[F](scribe.Logger(clazz.getName))
+}

modules/logging/src/main/scala/docspell/logging/impl/JsonWriter.scala

@@ -0,0 +1,26 @@
+/*
+ * Copyright 2020 Eike K. & Contributors
+ *
+ * SPDX-License-Identifier: AGPL-3.0-or-later
+ */
+
+package docspell.logging.impl
+
+import io.circe.syntax._
+import scribe.LogRecord
+import scribe.output.format.OutputFormat
+import scribe.output.{LogOutput, TextOutput}
+import scribe.writer.Writer
+
+final case class JsonWriter(writer: Writer, compact: Boolean = true) extends Writer {
+  override def write[M](
+      record: LogRecord[M],
+      output: LogOutput,
+      outputFormat: OutputFormat
+  ): Unit = {
+    val r = Record.fromLogRecord(record)
+    val json = r.asJson
+    val jsonString = if (compact) json.noSpaces else json.spaces2
+    writer.write(record, new TextOutput(jsonString), outputFormat)
+  }
+}

modules/logging/src/main/scala/docspell/logging/impl/LogfmtWriter.scala

@@ -0,0 +1,32 @@
+/*
+ * Copyright 2020 Eike K. & Contributors
+ *
+ * SPDX-License-Identifier: AGPL-3.0-or-later
+ */
+
+package docspell.logging.impl
+
+import io.circe.syntax._
+import scribe.LogRecord
+import scribe.output.format.OutputFormat
+import scribe.output.{LogOutput, TextOutput}
+import scribe.writer.Writer
+
+// https://brandur.org/logfmt
+final case class LogfmtWriter(writer: Writer) extends Writer {
+  override def write[M](
+      record: LogRecord[M],
+      output: LogOutput,
+      outputFormat: OutputFormat
+  ): Unit = {
+    val r = Record.fromLogRecord(record)
+    val data = r.data
+      .map { case (k, v) =>
+        s"$k=${v.noSpaces}"
+      }
+      .mkString(" ")
+    val logfmtStr =
+      s"""level=${r.level.asJson.noSpaces} levelValue=${r.levelValue} message=${r.message.asJson.noSpaces} fileName=${r.fileName.asJson.noSpaces} className=${r.className.asJson.noSpaces} methodName=${r.methodName.asJson.noSpaces} line=${r.line.asJson.noSpaces} column=${r.column.asJson.noSpaces} $data timestamp=${r.timeStamp} date=${r.date} time=${r.time}"""
+    writer.write(record, new TextOutput(logfmtStr), outputFormat)
+  }
+}

modules/logging/src/main/scala/docspell/logging/impl/LoggerWrapper.scala

@@ -0,0 +1,52 @@
+/*
+ * Copyright 2020 Eike K. & Contributors
+ *
+ * SPDX-License-Identifier: AGPL-3.0-or-later
+ */
+
+package docspell.logging.impl
+
+import cats.Id
+import cats.effect._
+
+import docspell.logging._
+
+import scribe.LoggerSupport
+import scribe.message.{LoggableMessage, Message}
+
+private[logging] object LoggerWrapper {
+  final class ImplUnsafe(log: scribe.Logger) extends Logger[Id] {
+    override def asUnsafe = this
+
+    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) =
+      Sync[F].delay(log.log(convert(ev)))
+  }
+
+  private[impl] def convertLevel(l: Level): scribe.Level =
+    l match {
+      case Level.Fatal => scribe.Level.Fatal
+      case Level.Error => scribe.Level.Error
+      case Level.Warn  => scribe.Level.Warn
+      case Level.Info  => scribe.Level.Info
+      case Level.Debug => scribe.Level.Debug
+      case Level.Trace => scribe.Level.Trace
+    }
+
+  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)
+      }
+    }
+    LoggerSupport(level, ev.msg(), additional, ev.pkg, ev.fileName, ev.name, ev.line)
+      .copy(data = ev.data)
+  }
+}

modules/logging/src/main/scala/docspell/logging/impl/Record.scala

@@ -0,0 +1,120 @@
+/*
+ * Copyright 2020 Eike K. & Contributors
+ *
+ * SPDX-License-Identifier: AGPL-3.0-or-later
+ */
+
+package docspell.logging.impl
+
+import docspell.logging.impl.Record._
+
+import io.circe.syntax._
+import io.circe.{Encoder, Json}
+import perfolation._
+import scribe.LogRecord
+import scribe.data.MDC
+import scribe.message.Message
+
+// From: https://github.com/outr/scribe/blob/8e99521e1ee1f0c421629764dd96e4eb193d84bd/json/shared/src/main/scala/scribe/json/JsonWriter.scala
+// which would introduce jackson and other dependencies. Modified to work with circe.
+// Original licensed under MIT.
+
+private[impl] case class Record(
+    level: String,
+    levelValue: Double,
+    message: String,
+    additionalMessages: List[String],
+    fileName: String,
+    className: String,
+    methodName: Option[String],
+    line: Option[Int],
+    column: Option[Int],
+    data: Map[String, Json],
+    traces: List[Trace],
+    timeStamp: Long,
+    date: String,
+    time: String
+)
+
+private[impl] object Record {
+
+  def fromLogRecord[M](record: LogRecord[M]): Record = {
+    val l = record.timeStamp
+    val traces = record.additionalMessages.collect {
+      case message: Message[_] if message.value.isInstanceOf[Throwable] =>
+        throwable2Trace(message.value.asInstanceOf[Throwable])
+    }
+    val additionalMessages = record.additionalMessages.map(_.logOutput.plainText)
+
+    Record(
+      level = record.level.name,
+      levelValue = record.levelValue,
+      message = record.logOutput.plainText,
+      additionalMessages = additionalMessages,
+      fileName = record.fileName,
+      className = record.className,
+      methodName = record.methodName,
+      line = record.line,
+      column = record.column,
+      data = (record.data ++ MDC.map).map { case (key, value) =>
+        value() match {
+          case value: Json   => key -> value
+          case value: Int    => key -> value.asJson
+          case value: Long   => key -> value.asJson
+          case value: Double => key -> value.asJson
+          case any           => key -> Json.fromString(any.toString)
+        }
+      },
+      traces = traces,
+      timeStamp = l,
+      date = l.t.F,
+      time = s"${l.t.T}.${l.t.L}${l.t.z}"
+    )
+  }
+
+  private def throwable2Trace(throwable: Throwable): Trace = {
+    val elements = throwable.getStackTrace.toList.map { e =>
+      TraceElement(e.getClassName, e.getMethodName, e.getLineNumber)
+    }
+    Trace(
+      throwable.getLocalizedMessage,
+      elements,
+      Option(throwable.getCause).map(throwable2Trace)
+    )
+  }
+
+  implicit val jsonEncoder: Encoder[Record] =
+    Encoder.forProduct14(
+      "level",
+      "levelValue",
+      "message",
+      "additionalMessages",
+      "fileName",
+      "className",
+      "methodName",
+      "line",
+      "column",
+      "data",
+      "traces",
+      "timestamp",
+      "date",
+      "time"
+    )(r => Record.unapply(r).get)
+
+  case class Trace(message: String, elements: List[TraceElement], cause: Option[Trace])
+
+  object Trace {
+    implicit def jsonEncoder: Encoder[Trace] =
+      Encoder.forProduct3("message", "elements", "cause")(r => Trace.unapply(r).get)
+
+    implicit def openEncoder: Encoder[Option[Trace]] =
+      Encoder.instance(opt => opt.map(jsonEncoder.apply).getOrElse(Json.Null))
+  }
+
+  case class TraceElement(`class`: String, method: String, line: Int)
+
+  object TraceElement {
+    implicit val jsonEncoder: Encoder[TraceElement] =
+      Encoder.forProduct3("class", "method", "line")(r => TraceElement.unapply(r).get)
+  }
+}

modules/logging/src/main/scala/docspell/logging/impl/ScribeConfigure.scala

@@ -0,0 +1,54 @@
+/*
+ * Copyright 2020 Eike K. & Contributors
+ *
+ * SPDX-License-Identifier: AGPL-3.0-or-later
+ */
+
+package docspell.logging.impl
+
+import cats.effect._
+
+import docspell.logging.LogConfig
+import docspell.logging.LogConfig.Format
+
+import scribe.format.Formatter
+import scribe.jul.JULHandler
+import scribe.writer.ConsoleWriter
+
+object ScribeConfigure {
+
+  def configure[F[_]: Sync](cfg: LogConfig): F[Unit] =
+    Sync[F].delay {
+      replaceJUL()
+      unsafeConfigure(scribe.Logger.root, cfg)
+    }
+
+  def unsafeConfigure(logger: scribe.Logger, cfg: LogConfig): Unit = {
+    val mods = List[scribe.Logger => scribe.Logger](
+      _.clearHandlers(),
+      _.withMinimumLevel(LoggerWrapper.convertLevel(cfg.minimumLevel)),
+      l =>
+        cfg.format match {
+          case Format.Fancy =>
+            l.withHandler(formatter = Formatter.enhanced)
+          case Format.Plain =>
+            l.withHandler(formatter = Formatter.classic)
+          case Format.Json =>
+            l.withHandler(writer = JsonWriter(ConsoleWriter))
+          case Format.Logfmt =>
+            l.withHandler(writer = LogfmtWriter(ConsoleWriter))
+        },
+      _.replace()
+    )
+
+    mods.foldLeft(logger)((l, mod) => mod(l))
+    ()
+  }
+
+  def replaceJUL(): Unit = {
+    scribe.Logger.system // just to load effects in Logger singleton
+    val julRoot = java.util.logging.LogManager.getLogManager.getLogger("")
+    julRoot.getHandlers.foreach(julRoot.removeHandler)
+    julRoot.addHandler(JULHandler)
+  }
+}

project/Dependencies.scala

@@ -9,6 +9,8 @@ object Dependencies {
   val BetterMonadicForVersion = "0.3.1"
   val BinnyVersion = "0.3.0"
   val CalevVersion = "0.6.1"
+  val CatsVersion = "2.7.0"
+  val CatsEffectVersion = "3.3.5"
   val CatsParseVersion = "0.3.6"
   val CirceVersion = "0.14.1"
   val ClipboardJsVersion = "2.0.6"
@@ -40,6 +42,7 @@ object Dependencies {
   val PureConfigVersion = "0.17.1"
   val ScalaJavaTimeVersion = "2.3.0"
   val ScodecBitsVersion = "1.1.30"
+  val ScribeVersion = "3.7.0"
   val Slf4jVersion = "1.7.36"
   val StanfordNlpVersion = "4.4.0"
   val TikaVersion = "2.3.0"
@@ -49,6 +52,11 @@ object Dependencies {
   val TwelveMonkeysVersion = "3.8.1"
   val JQueryVersion = "3.5.1"
 
+  val scribe = Seq(
+    "com.outr" %% "scribe" % ScribeVersion,
+    "com.outr" %% "scribe-slf4j" % ScribeVersion
+  )
+
   val jwtScala = Seq(
     "com.github.jwt-scala" %% "jwt-circe" % JwtScalaVersion
   )
@@ -67,6 +75,14 @@ object Dependencies {
     "com.dimafeng" %% "testcontainers-scala-postgresql" % TestContainerVersion
   )
 
+  val cats = Seq(
+    "org.typelevel" %% "cats-core" % CatsVersion
+  )
+
+  val catsEffect = Seq(
+    "org.typelevel" %% "cats-effect" % CatsEffectVersion
+  )
+
   val catsParse = Seq(
     "org.typelevel" %% "cats-parse" % CatsParseVersion
   )