From feab227bb133d3f825c3af1f98c77a157576f038 Mon Sep 17 00:00:00 2001 From: Ondra Pelech Date: Mon, 18 Nov 2019 10:29:49 +0100 Subject: [PATCH 01/35] move to sub-project --- build.sbt | 34 ++++++++++++++----- .../src}/main/resources/logback.xml | 0 .../loggingexperiment/logbackzio}/Main.scala | 2 +- 3 files changed, 26 insertions(+), 10 deletions(-) rename {src => logback-zio/src}/main/resources/logback.xml (100%) rename {src/main/scala/loggingexperiment => logback-zio/src/main/scala/loggingexperiment/logbackzio}/Main.scala (99%) diff --git a/build.sbt b/build.sbt index 58d12a5..4b82b91 100644 --- a/build.sbt +++ b/build.sbt @@ -6,12 +6,28 @@ scalaVersion := "2.12.10" val circeVersion = "0.11.1" -libraryDependencies ++= Seq( - "org.slf4j" % "slf4j-api" % "1.7.29", - "ch.qos.logback" % "logback-classic" % "1.2.3", - "net.logstash.logback" % "logstash-logback-encoder" % "6.2", - "io.circe" %% "circe-core" % circeVersion, - "io.circe" %% "circe-generic" % circeVersion, -// "org.typelevel" %% "cats-effect" % "2.0.0", - "dev.zio" %% "zio" % "1.0.0-RC16", -) + +lazy val root = project + .in(file(".")) + .settings( + name := "loggingexperiment", + publish / skip := true, // doesn't publish ivy XML files, in contrast to "publishArtifact := false" + ) + .aggregate( + logbackZio, + ) + +lazy val logbackZio = project + .in(file("logback-zio")) + .settings( + name := "logback-zio", + libraryDependencies ++= Seq( + "org.slf4j" % "slf4j-api" % "1.7.29", + "ch.qos.logback" % "logback-classic" % "1.2.3", + "net.logstash.logback" % "logstash-logback-encoder" % "6.2", + "io.circe" %% "circe-core" % circeVersion, + "io.circe" %% "circe-generic" % circeVersion, + // "org.typelevel" %% "cats-effect" % "2.0.0", + "dev.zio" %% "zio" % "1.0.0-RC16", + ) + ) diff --git a/src/main/resources/logback.xml b/logback-zio/src/main/resources/logback.xml similarity index 100% rename from src/main/resources/logback.xml rename to logback-zio/src/main/resources/logback.xml diff --git a/src/main/scala/loggingexperiment/Main.scala b/logback-zio/src/main/scala/loggingexperiment/logbackzio/Main.scala similarity index 99% rename from src/main/scala/loggingexperiment/Main.scala rename to logback-zio/src/main/scala/loggingexperiment/logbackzio/Main.scala index 9e04cf7..40f4f97 100644 --- a/src/main/scala/loggingexperiment/Main.scala +++ b/logback-zio/src/main/scala/loggingexperiment/logbackzio/Main.scala @@ -1,4 +1,4 @@ -package loggingexperiment +package loggingexperiment.logbackzio //import cats.effect.{ExitCode, IO, IOApp, Sync} import io.circe.Encoder From d3f4c1343631492a2df7c3195319b9a850e9a150 Mon Sep 17 00:00:00 2001 From: Ondra Pelech Date: Mon, 18 Nov 2019 11:47:40 +0100 Subject: [PATCH 02/35] monix --- build.sbt | 37 +++-- logback-monix/src/main/resources/logback.xml | 10 ++ .../loggingexperiment/logbackzio/Main.scala | 142 ++++++++++++++++++ 3 files changed, 180 insertions(+), 9 deletions(-) create mode 100644 logback-monix/src/main/resources/logback.xml create mode 100644 logback-monix/src/main/scala/loggingexperiment/logbackzio/Main.scala diff --git a/build.sbt b/build.sbt index 4b82b91..039e958 100644 --- a/build.sbt +++ b/build.sbt @@ -4,8 +4,14 @@ version := "0.1" scalaVersion := "2.12.10" -val circeVersion = "0.11.1" - +lazy val Version = new { + val circe = "0.11.1" + val slf4j = "1.7.29" + val logback = "1.2.3" + val logstashLogback = "6.2" + val zio = "1.0.0-RC16" + val monix = "3.1.0" +} lazy val root = project .in(file(".")) @@ -22,12 +28,25 @@ lazy val logbackZio = project .settings( name := "logback-zio", libraryDependencies ++= Seq( - "org.slf4j" % "slf4j-api" % "1.7.29", - "ch.qos.logback" % "logback-classic" % "1.2.3", - "net.logstash.logback" % "logstash-logback-encoder" % "6.2", - "io.circe" %% "circe-core" % circeVersion, - "io.circe" %% "circe-generic" % circeVersion, - // "org.typelevel" %% "cats-effect" % "2.0.0", - "dev.zio" %% "zio" % "1.0.0-RC16", + "org.slf4j" % "slf4j-api" % Version.slf4j, + "ch.qos.logback" % "logback-classic" % Version.logback, + "net.logstash.logback" % "logstash-logback-encoder" % Version.logstashLogback, + "io.circe" %% "circe-core" % Version.circe, + "io.circe" %% "circe-generic" % Version.circe, + "dev.zio" %% "zio" % Version.zio, + ) + ) + +lazy val logbackMonix = project + .in(file("logback-monix")) + .settings( + name := "logback-monix", + libraryDependencies ++= Seq( + "org.slf4j" % "slf4j-api" % Version.slf4j, + "ch.qos.logback" % "logback-classic" % Version.logback, + "net.logstash.logback" % "logstash-logback-encoder" % Version.logstashLogback, + "io.circe" %% "circe-core" % Version.circe, + "io.circe" %% "circe-generic" % Version.circe, + "io.monix" %% "monix" % Version.monix, ) ) diff --git a/logback-monix/src/main/resources/logback.xml b/logback-monix/src/main/resources/logback.xml new file mode 100644 index 0000000..396c5a5 --- /dev/null +++ b/logback-monix/src/main/resources/logback.xml @@ -0,0 +1,10 @@ + + + + log/loggingexperiment.log + + {"application":"loggingexperiment"} + + + + diff --git a/logback-monix/src/main/scala/loggingexperiment/logbackzio/Main.scala b/logback-monix/src/main/scala/loggingexperiment/logbackzio/Main.scala new file mode 100644 index 0000000..4f6d61a --- /dev/null +++ b/logback-monix/src/main/scala/loggingexperiment/logbackzio/Main.scala @@ -0,0 +1,142 @@ +package loggingexperiment.logbackzio + +import cats.effect._ +import io.circe.Encoder +import io.circe.generic.auto._ +import io.circe.syntax._ +import monix.eval._ +import monix.execution.Scheduler +import net.logstash.logback.argument.StructuredArguments +import net.logstash.logback.marker.{LogstashMarker, Markers} +import org.slf4j.{Logger, LoggerFactory} + +final case class A(x: Int, y: String) +final case class B(a: A, b: Boolean) + +trait Log { + def info[A](format: String, xName: String, x: A)( + implicit e: Encoder[A] + ): Task[Unit] + def info[A, B](format: String, xName: String, x: A, yName: String, y: B)( + implicit ex: Encoder[A], + ey: Encoder[B] + ): Task[Unit] + def addContext[A](format: String, xName: String, x: A)( + implicit e: Encoder[A], + sch: Scheduler + ): Resource[Task, Unit] +} + +object Log { + private class LogImpl(logger: Logger, + mdc: TaskLocal[Map[String, List[(Any, Encoder[Any])]]]) + extends Log { + + private def log(body: LogstashMarker => Unit): Task[Unit] = + for { + mdc <- mdc.read + mdcNormalized = mdc.toList.map { + case (k, v) => (k, v.head match { case (v, e) => e(v).spaces2 }) + } + markers = mdcNormalized.map { case (k, v) => Markers.appendRaw(k, v) } + _ <- Task.delay { + body(Markers.aggregate(markers: _*)) + } + } yield () + + override def addContext[A](format: String, xName: String, x: A)( + implicit e: Encoder[A], + sch: Scheduler + ): Resource[Task, Unit] = { + Resource.make { + for { + ctx <- mdc.read + ctxNew = ctx.get(xName) match { + case Some(list) => + ctx + ((xName, (x, e.asInstanceOf[Encoder[Any]]) :: list)) + case None => + ctx + ((xName, (x, e.asInstanceOf[Encoder[Any]]) :: Nil)) + } + _ <- mdc.write(ctxNew) + } yield () + } { _: Unit => + for { + ctx <- mdc.read + ctxNew = ctx.get(xName) match { + case Some(_ :: Nil) => + ctx - xName + case Some(_ :: tail) => + ctx + ((xName, tail)) + } + _ <- mdc.write(ctxNew) + } yield () + } + } + + override def info[A](format: String, xName: String, x: A)( + implicit e: Encoder[A] + ): Task[Unit] = + log { mdc => + logger.info( + mdc, + format, + StructuredArguments.raw(xName, x.asJson.spaces2), + ) + } + + override def info[A, B]( + format: String, + xName: String, + x: A, + yName: String, + y: B + )(implicit ex: Encoder[A], ey: Encoder[B]): Task[Unit] = + log { mdc => + logger.info( + mdc, + format, + StructuredArguments.raw(xName, x.asJson.spaces2), + StructuredArguments.raw(yName, y.asJson.spaces2): Any, + ) + } + } + + def make(logger: Logger): Task[Log] = { + for { + mdc <- TaskLocal(Map.empty[String, List[(Any, Encoder[Any])]]) + logImpl = new LogImpl(logger, mdc) + } yield logImpl + } + +} + +object Main extends TaskApp { + + val logger: Logger = LoggerFactory.getLogger(Main.getClass) + val o = B(A(123, "Hello"), b = true) + + override def run(args: List[String]): Task[ExitCode] = + init(scheduler) + .map(_ => ExitCode.Success) + .executeWithOptions(_.enableLocalContextPropagation) + + def init(implicit sch: Scheduler): Task[Unit] = + for { + log <- Log.make(logger) + result <- program(log) + } yield result + + def program(logger: Log)(implicit sch: Scheduler): Task[Unit] = { + for { + _ <- logger.addContext("XXXXXXX {} ", "yyy", A(567, "YYYYYYYYYYYY")).use { + _: Unit => + for { + _ <- logger.info("Hello {}", "o", o) + } yield () + } + _ <- logger.info("Hello {}", "o", o) + _ <- logger.info("Hello2 {} and {}", "x", 123, "o", o) + } yield () + } + +} From 94992760f1cc3af8b95e9f34bc69c2a9d93ec146 Mon Sep 17 00:00:00 2001 From: Ondra Pelech Date: Mon, 18 Nov 2019 11:51:02 +0100 Subject: [PATCH 03/35] clean up ZIO --- .../loggingexperiment/logbackzio/Main.scala | 2 +- logback-zio/src/main/resources/logback.xml | 2 +- .../loggingexperiment/logbackzio/Main.scala | 60 ++----------------- 3 files changed, 7 insertions(+), 57 deletions(-) diff --git a/logback-monix/src/main/scala/loggingexperiment/logbackzio/Main.scala b/logback-monix/src/main/scala/loggingexperiment/logbackzio/Main.scala index 4f6d61a..8120ee0 100644 --- a/logback-monix/src/main/scala/loggingexperiment/logbackzio/Main.scala +++ b/logback-monix/src/main/scala/loggingexperiment/logbackzio/Main.scala @@ -112,7 +112,7 @@ object Log { object Main extends TaskApp { - val logger: Logger = LoggerFactory.getLogger(Main.getClass) + val logger: Logger = LoggerFactory.getLogger(getClass) val o = B(A(123, "Hello"), b = true) override def run(args: List[String]): Task[ExitCode] = diff --git a/logback-zio/src/main/resources/logback.xml b/logback-zio/src/main/resources/logback.xml index a31f728..396c5a5 100644 --- a/logback-zio/src/main/resources/logback.xml +++ b/logback-zio/src/main/resources/logback.xml @@ -3,7 +3,7 @@ log/loggingexperiment.log - + {"application":"loggingexperiment"} diff --git a/logback-zio/src/main/scala/loggingexperiment/logbackzio/Main.scala b/logback-zio/src/main/scala/loggingexperiment/logbackzio/Main.scala index 40f4f97..1723bbf 100644 --- a/logback-zio/src/main/scala/loggingexperiment/logbackzio/Main.scala +++ b/logback-zio/src/main/scala/loggingexperiment/logbackzio/Main.scala @@ -1,15 +1,12 @@ package loggingexperiment.logbackzio -//import cats.effect.{ExitCode, IO, IOApp, Sync} import io.circe.Encoder -import org.slf4j.{Logger, LoggerFactory, MDC} -import net.logstash.logback.argument.StructuredArguments -import net.logstash.logback.marker.{LogstashMarker, Markers} import io.circe.generic.auto._ import io.circe.syntax._ -import zio.{UManaged, _} - -import collection.JavaConverters._ +import net.logstash.logback.argument.StructuredArguments +import net.logstash.logback.marker.{LogstashMarker, Markers} +import org.slf4j.{Logger, LoggerFactory} +import zio._ final case class A(x: Int, y: String) final case class B(a: A, b: Boolean) @@ -49,15 +46,6 @@ object Log { markers = mdcNormalized.map { case (k, v) => Markers.appendRaw(k, v) } _ <- UIO.effectTotal { body(Markers.aggregate(markers: _*)) -// val context = mdc.map { -// case (k, v) => -// MDC.putCloseable(k, v.head match { case (v, e) => e(v).toString }) -// } -// try { -// body(mdc.map{ case (n, l)}) -// } finally { -// context.foreach(_.close) -// } } } yield () @@ -131,29 +119,7 @@ object Log { object Main extends App { -// implicit final class LoggerOps(val logger: Logger) extends AnyVal { -// def info_[A](format: String, xName: String, x: A)( -// implicit e: Encoder[A] -// ): UIO[Unit] = { -// UIO.effectTotal( -// logger.info(format, StructuredArguments.raw(xName, x.asJson.toString)) -// ) -// } -// def info_[A, B](format: String, xName: String, x: A, yName: String, y: B)( -// implicit ex: Encoder[A], -// ey: Encoder[B] -// ): UIO[Unit] = { -// UIO.effectTotal( -// logger.info( -// format, -// StructuredArguments.raw(xName, x.asJson.toString), -// StructuredArguments.raw(yName, y.asJson.toString): Any -// ) -// ) -// } -// } - - val logger: Logger = LoggerFactory.getLogger(Main.getClass) + val logger: Logger = LoggerFactory.getLogger(getClass) val o = B(A(123, "Hello"), b = true) override def run(args: List[String]): ZIO[ZEnv, Nothing, Int] = @@ -179,20 +145,4 @@ object Main extends App { } yield () } -// def run(args: Array[String]): Unit = { -// -// println(s"Hello $o") -// logger.info(s"Hello $o") -// logger.info("Hello {}", o) -// logger.info("Hello o={}", o) -// logger.info("Hello array {}", StructuredArguments.array("o", o)) -// logger.info( -// "Hello entries {}", -// StructuredArguments.entries(o.asJsonObject.toMap.asJava) -// ) -// logger.info("Hello fields {}", StructuredArguments.fields("o", o)) -// logger.info("Hello keyValue {}", StructuredArguments.keyValue("o", o)) -// logger.info("Hello raw {}", StructuredArguments.raw("o", o.asJson.toString)) -// logger.info("Hello value {}", StructuredArguments.value("o", o)) -// } } From f57b49c515d21f0b00c86bad5aaf16415922514b Mon Sep 17 00:00:00 2001 From: Ondra Pelech Date: Mon, 18 Nov 2019 17:04:17 +0100 Subject: [PATCH 04/35] logstage --- build.sbt | 19 ++++++++ .../{logbackzio => logbackmonix}/Main.scala | 25 +++++------ .../loggingexperiment/logbackzio/Main.scala | 16 +++---- logstage-monix/src/main/resources/logback.xml | 19 ++++++++ .../logstagemonix/Main.scala | 43 +++++++++++++++++++ 5 files changed, 99 insertions(+), 23 deletions(-) rename logback-monix/src/main/scala/loggingexperiment/{logbackzio => logbackmonix}/Main.scala (87%) create mode 100644 logstage-monix/src/main/resources/logback.xml create mode 100644 logstage-monix/src/main/scala/loggingexperiment/logstagemonix/Main.scala diff --git a/build.sbt b/build.sbt index 039e958..da11d37 100644 --- a/build.sbt +++ b/build.sbt @@ -11,6 +11,7 @@ lazy val Version = new { val logstashLogback = "6.2" val zio = "1.0.0-RC16" val monix = "3.1.0" + val izumi = "0.9.12" } lazy val root = project @@ -21,6 +22,7 @@ lazy val root = project ) .aggregate( logbackZio, + logbackMonix, ) lazy val logbackZio = project @@ -50,3 +52,20 @@ lazy val logbackMonix = project "io.monix" %% "monix" % Version.monix, ) ) + +lazy val logstageMonix = project + .in(file("logstage-monix")) + .settings( + name := "logstage-monix", + libraryDependencies ++= Seq( + "org.slf4j" % "slf4j-api" % Version.slf4j, + "ch.qos.logback" % "logback-classic" % Version.logback, + "net.logstash.logback" % "logstash-logback-encoder" % Version.logstashLogback, + "io.circe" %% "circe-core" % Version.circe, + "io.circe" %% "circe-generic" % Version.circe, + "io.monix" %% "monix" % Version.monix, + "io.7mind.izumi" %% "logstage-core" % Version.izumi, + "io.7mind.izumi" %% "logstage-rendering-circe" % Version.izumi, + "io.7mind.izumi" %% "logstage-sink-slf4j" % Version.izumi, + ) + ) diff --git a/logback-monix/src/main/scala/loggingexperiment/logbackzio/Main.scala b/logback-monix/src/main/scala/loggingexperiment/logbackmonix/Main.scala similarity index 87% rename from logback-monix/src/main/scala/loggingexperiment/logbackzio/Main.scala rename to logback-monix/src/main/scala/loggingexperiment/logbackmonix/Main.scala index 8120ee0..84ec91d 100644 --- a/logback-monix/src/main/scala/loggingexperiment/logbackzio/Main.scala +++ b/logback-monix/src/main/scala/loggingexperiment/logbackmonix/Main.scala @@ -1,4 +1,4 @@ -package loggingexperiment.logbackzio +package loggingexperiment.logbackmonix import cats.effect._ import io.circe.Encoder @@ -21,10 +21,8 @@ trait Log { implicit ex: Encoder[A], ey: Encoder[B] ): Task[Unit] - def addContext[A](format: String, xName: String, x: A)( - implicit e: Encoder[A], - sch: Scheduler - ): Resource[Task, Unit] + def addContext[A](xName: String, x: A)(implicit e: Encoder[A], + sch: Scheduler): Resource[Task, Unit] } object Log { @@ -44,10 +42,10 @@ object Log { } } yield () - override def addContext[A](format: String, xName: String, x: A)( - implicit e: Encoder[A], - sch: Scheduler - ): Resource[Task, Unit] = { + override def addContext[A]( + xName: String, + x: A + )(implicit e: Encoder[A], sch: Scheduler): Resource[Task, Unit] = { Resource.make { for { ctx <- mdc.read @@ -128,11 +126,10 @@ object Main extends TaskApp { def program(logger: Log)(implicit sch: Scheduler): Task[Unit] = { for { - _ <- logger.addContext("XXXXXXX {} ", "yyy", A(567, "YYYYYYYYYYYY")).use { - _: Unit => - for { - _ <- logger.info("Hello {}", "o", o) - } yield () + _ <- logger.addContext("yyy", A(567, "YYYYYYYYYYYY")).use { _: Unit => + for { + _ <- logger.info("Hello {}", "o", o) + } yield () } _ <- logger.info("Hello {}", "o", o) _ <- logger.info("Hello2 {} and {}", "x", 123, "o", o) diff --git a/logback-zio/src/main/scala/loggingexperiment/logbackzio/Main.scala b/logback-zio/src/main/scala/loggingexperiment/logbackzio/Main.scala index 1723bbf..acc6ce5 100644 --- a/logback-zio/src/main/scala/loggingexperiment/logbackzio/Main.scala +++ b/logback-zio/src/main/scala/loggingexperiment/logbackzio/Main.scala @@ -25,7 +25,7 @@ object Log { implicit ex: Encoder[A], ey: Encoder[B] ): UIO[Unit] - def addContext[A](format: String, xName: String, x: A)( + def addContext[A](xName: String, x: A)( implicit e: Encoder[A] ): UManaged[Unit] } @@ -49,9 +49,8 @@ object Log { } } yield () - override def addContext[A](format: String, xName: String, x: A)( - implicit e: Encoder[A] - ): UManaged[Unit] = { + override def addContext[A](xName: String, + x: A)(implicit e: Encoder[A]): UManaged[Unit] = { Managed.make { for { _ <- mdc.update { mdc => @@ -134,11 +133,10 @@ object Main extends App { def program: RIO[Log, Unit] = { for { logger <- Log.log - _ <- logger.addContext("XXXXXXX {} ", "yyy", A(567, "YYYYYYYYYYYY")).use { - _: Unit => - for { - _ <- logger.info("Hello {}", "o", o) - } yield () + _ <- logger.addContext("yyy", A(567, "YYYYYYYYYYYY")).use { _: Unit => + for { + _ <- logger.info("Hello {}", "o", o) + } yield () } _ <- logger.info("Hello {}", "o", o) _ <- logger.info("Hello2 {} and {}", "x", 123, "o", o) diff --git a/logstage-monix/src/main/resources/logback.xml b/logstage-monix/src/main/resources/logback.xml new file mode 100644 index 0000000..c2e2933 --- /dev/null +++ b/logstage-monix/src/main/resources/logback.xml @@ -0,0 +1,19 @@ + + + + log/loggingexperiment.log + + + + + + + + { "message": "#asJson{%message}" } + + + + + + + diff --git a/logstage-monix/src/main/scala/loggingexperiment/logstagemonix/Main.scala b/logstage-monix/src/main/scala/loggingexperiment/logstagemonix/Main.scala new file mode 100644 index 0000000..efe15d0 --- /dev/null +++ b/logstage-monix/src/main/scala/loggingexperiment/logstagemonix/Main.scala @@ -0,0 +1,43 @@ +package loggingexperiment.logstagemonix + +import cats.effect._ +import io.circe.generic.auto._ +import izumi.logstage.api.rendering.json.LogstageCirceRenderingPolicy +import izumi.logstage.sink.slf4j.LogSinkLegacySlf4jImpl +import logstage._ +import logstage.circe._ +import monix.eval._ +import monix.execution.Scheduler + +final case class A(x: Int, y: String) +final case class B(a: A, b: Boolean) + +object Main extends TaskApp { + + val sink = new LogSinkLegacySlf4jImpl(new LogstageCirceRenderingPolicy(true)) + val jsonSink: ConsoleSink = ConsoleSink.json(prettyPrint = true) + val logger = IzLogger(Trace, List(sink, jsonSink)) + val loggerTask: LogIO[Task] = LogIO.fromLogger[Task](logger) + + val o = B(A(123, "Hel\nlo"), b = true) + + override def run(args: List[String]): Task[ExitCode] = + init(scheduler) + .map(_ => ExitCode.Success) + .executeWithOptions(_.enableLocalContextPropagation) + + def init(implicit sch: Scheduler): Task[Unit] = + for { + result <- program(loggerTask) + } yield result + + def program(logger: LogIO[Task])(implicit sch: Scheduler): Task[Unit] = { + val logger_ = logger("yyy" -> A(567, "YYYYYYYYYYYY")) + for { + _ <- logger_.info(s"Hello $o") + _ <- logger.info(s"Hello $o") + _ <- logger.info(s"Hello2 ${123} and $o") + } yield () + } + +} From 0ade317d0163989d89c74829050b7ab9a4b45dae Mon Sep 17 00:00:00 2001 From: Ondra Pelech Date: Mon, 18 Nov 2019 17:24:05 +0100 Subject: [PATCH 05/35] gson --- build.sbt | 6 +- .../loggingexperiment/logbackmonix/Main.scala | 64 +++++++++---------- 2 files changed, 33 insertions(+), 37 deletions(-) diff --git a/build.sbt b/build.sbt index da11d37..d3516e2 100644 --- a/build.sbt +++ b/build.sbt @@ -12,6 +12,7 @@ lazy val Version = new { val zio = "1.0.0-RC16" val monix = "3.1.0" val izumi = "0.9.12" + val gson = "2.8.6" } lazy val root = project @@ -47,8 +48,9 @@ lazy val logbackMonix = project "org.slf4j" % "slf4j-api" % Version.slf4j, "ch.qos.logback" % "logback-classic" % Version.logback, "net.logstash.logback" % "logstash-logback-encoder" % Version.logstashLogback, - "io.circe" %% "circe-core" % Version.circe, - "io.circe" %% "circe-generic" % Version.circe, + "com.google.code.gson" % "gson" % Version.gson, +// "io.circe" %% "circe-core" % Version.circe, +// "io.circe" %% "circe-generic" % Version.circe, "io.monix" %% "monix" % Version.monix, ) ) diff --git a/logback-monix/src/main/scala/loggingexperiment/logbackmonix/Main.scala b/logback-monix/src/main/scala/loggingexperiment/logbackmonix/Main.scala index 84ec91d..7bb2453 100644 --- a/logback-monix/src/main/scala/loggingexperiment/logbackmonix/Main.scala +++ b/logback-monix/src/main/scala/loggingexperiment/logbackmonix/Main.scala @@ -1,9 +1,7 @@ package loggingexperiment.logbackmonix import cats.effect._ -import io.circe.Encoder -import io.circe.generic.auto._ -import io.circe.syntax._ +import com.google.gson.Gson import monix.eval._ import monix.execution.Scheduler import net.logstash.logback.argument.StructuredArguments @@ -14,27 +12,28 @@ final case class A(x: Int, y: String) final case class B(a: A, b: Boolean) trait Log { - def info[A](format: String, xName: String, x: A)( - implicit e: Encoder[A] - ): Task[Unit] - def info[A, B](format: String, xName: String, x: A, yName: String, y: B)( - implicit ex: Encoder[A], - ey: Encoder[B] - ): Task[Unit] - def addContext[A](xName: String, x: A)(implicit e: Encoder[A], - sch: Scheduler): Resource[Task, Unit] + def info(format: String, xName: String, x: Any): Task[Unit] + def info(format: String, + xName: String, + x: Any, + yName: String, + y: Any): Task[Unit] + def addContext(xName: String, x: Any)( + implicit sch: Scheduler + ): Resource[Task, Unit] } object Log { - private class LogImpl(logger: Logger, - mdc: TaskLocal[Map[String, List[(Any, Encoder[Any])]]]) + private class LogImpl(logger: Logger, mdc: TaskLocal[Map[String, List[Any]]]) extends Log { + private val gson = new Gson() + private def log(body: LogstashMarker => Unit): Task[Unit] = for { mdc <- mdc.read mdcNormalized = mdc.toList.map { - case (k, v) => (k, v.head match { case (v, e) => e(v).spaces2 }) + case (k, v :: _) => (k, gson.toJson(v)) } markers = mdcNormalized.map { case (k, v) => Markers.appendRaw(k, v) } _ <- Task.delay { @@ -42,18 +41,17 @@ object Log { } } yield () - override def addContext[A]( - xName: String, - x: A - )(implicit e: Encoder[A], sch: Scheduler): Resource[Task, Unit] = { + override def addContext(xName: String, x: Any)( + implicit sch: Scheduler + ): Resource[Task, Unit] = { Resource.make { for { ctx <- mdc.read ctxNew = ctx.get(xName) match { case Some(list) => - ctx + ((xName, (x, e.asInstanceOf[Encoder[Any]]) :: list)) + ctx + ((xName, x :: list)) case None => - ctx + ((xName, (x, e.asInstanceOf[Encoder[Any]]) :: Nil)) + ctx + ((xName, x :: Nil)) } _ <- mdc.write(ctxNew) } yield () @@ -71,37 +69,33 @@ object Log { } } - override def info[A](format: String, xName: String, x: A)( - implicit e: Encoder[A] - ): Task[Unit] = + override def info(format: String, xName: String, x: Any): Task[Unit] = log { mdc => logger.info( mdc, format, - StructuredArguments.raw(xName, x.asJson.spaces2), + StructuredArguments.raw(xName, gson.toJson(x)), ) } - override def info[A, B]( - format: String, - xName: String, - x: A, - yName: String, - y: B - )(implicit ex: Encoder[A], ey: Encoder[B]): Task[Unit] = + override def info(format: String, + xName: String, + x: Any, + yName: String, + y: Any): Task[Unit] = log { mdc => logger.info( mdc, format, - StructuredArguments.raw(xName, x.asJson.spaces2), - StructuredArguments.raw(yName, y.asJson.spaces2): Any, + StructuredArguments.raw(xName, gson.toJson(x)), + StructuredArguments.raw(yName, gson.toJson(y)): Any, ) } } def make(logger: Logger): Task[Log] = { for { - mdc <- TaskLocal(Map.empty[String, List[(Any, Encoder[Any])]]) + mdc <- TaskLocal(Map.empty[String, List[Any]]) logImpl = new LogImpl(logger, mdc) } yield logImpl } From 6ac8d8c2caf5956f6b74383b6d048398ae180908 Mon Sep 17 00:00:00 2001 From: Ondra Pelech Date: Mon, 18 Nov 2019 17:34:15 +0100 Subject: [PATCH 06/35] jackson --- build.sbt | 26 +++- .../src/main/resources/logback.xml | 0 .../loggingexperiment/logbackmonix/Main.scala | 0 .../src/main/resources/logback.xml | 10 ++ .../loggingexperiment/logbackmonix/Main.scala | 147 ++++++++++++++++++ 5 files changed, 177 insertions(+), 6 deletions(-) rename {logback-monix => logback-monix-gson}/src/main/resources/logback.xml (100%) rename {logback-monix => logback-monix-gson}/src/main/scala/loggingexperiment/logbackmonix/Main.scala (100%) create mode 100644 logback-monix-jackson/src/main/resources/logback.xml create mode 100644 logback-monix-jackson/src/main/scala/loggingexperiment/logbackmonix/Main.scala diff --git a/build.sbt b/build.sbt index d3516e2..8e5fcb2 100644 --- a/build.sbt +++ b/build.sbt @@ -13,6 +13,7 @@ lazy val Version = new { val monix = "3.1.0" val izumi = "0.9.12" val gson = "2.8.6" + val jackson = "2.9.8" } lazy val root = project @@ -23,7 +24,9 @@ lazy val root = project ) .aggregate( logbackZio, - logbackMonix, + logbackMonixGson, + logbackMonixJackson, + logstageMonix, ) lazy val logbackZio = project @@ -40,17 +43,28 @@ lazy val logbackZio = project ) ) -lazy val logbackMonix = project - .in(file("logback-monix")) +lazy val logbackMonixGson = project + .in(file("logback-monix-gson")) .settings( - name := "logback-monix", + name := "logback-monix-gson", libraryDependencies ++= Seq( "org.slf4j" % "slf4j-api" % Version.slf4j, "ch.qos.logback" % "logback-classic" % Version.logback, "net.logstash.logback" % "logstash-logback-encoder" % Version.logstashLogback, "com.google.code.gson" % "gson" % Version.gson, -// "io.circe" %% "circe-core" % Version.circe, -// "io.circe" %% "circe-generic" % Version.circe, + "io.monix" %% "monix" % Version.monix, + ) + ) + +lazy val logbackMonixJackson = project + .in(file("logback-monix-jackson")) + .settings( + name := "logback-monix-jackson", + libraryDependencies ++= Seq( + "org.slf4j" % "slf4j-api" % Version.slf4j, + "ch.qos.logback" % "logback-classic" % Version.logback, + "net.logstash.logback" % "logstash-logback-encoder" % Version.logstashLogback, + "com.fasterxml.jackson.core" % "jackson-databind" % Version.jackson, "io.monix" %% "monix" % Version.monix, ) ) diff --git a/logback-monix/src/main/resources/logback.xml b/logback-monix-gson/src/main/resources/logback.xml similarity index 100% rename from logback-monix/src/main/resources/logback.xml rename to logback-monix-gson/src/main/resources/logback.xml diff --git a/logback-monix/src/main/scala/loggingexperiment/logbackmonix/Main.scala b/logback-monix-gson/src/main/scala/loggingexperiment/logbackmonix/Main.scala similarity index 100% rename from logback-monix/src/main/scala/loggingexperiment/logbackmonix/Main.scala rename to logback-monix-gson/src/main/scala/loggingexperiment/logbackmonix/Main.scala diff --git a/logback-monix-jackson/src/main/resources/logback.xml b/logback-monix-jackson/src/main/resources/logback.xml new file mode 100644 index 0000000..396c5a5 --- /dev/null +++ b/logback-monix-jackson/src/main/resources/logback.xml @@ -0,0 +1,10 @@ + + + + log/loggingexperiment.log + + {"application":"loggingexperiment"} + + + + diff --git a/logback-monix-jackson/src/main/scala/loggingexperiment/logbackmonix/Main.scala b/logback-monix-jackson/src/main/scala/loggingexperiment/logbackmonix/Main.scala new file mode 100644 index 0000000..2108b7b --- /dev/null +++ b/logback-monix-jackson/src/main/scala/loggingexperiment/logbackmonix/Main.scala @@ -0,0 +1,147 @@ +package loggingexperiment.logbackmonix + +import cats.effect._ +import com.fasterxml.jackson.annotation.JsonAutoDetect.Visibility +import com.fasterxml.jackson.annotation.PropertyAccessor +import com.fasterxml.jackson.databind.ObjectMapper +import monix.eval._ +import monix.execution.Scheduler +import net.logstash.logback.argument.StructuredArguments +import net.logstash.logback.marker.{LogstashMarker, Markers} +import org.slf4j.{Logger, LoggerFactory} + +final case class A(x: Int, y: String) +final case class B(a: A, b: Boolean) + +trait Log { + def info(format: String, xName: String, x: Any): Task[Unit] + def info(format: String, + xName: String, + x: Any, + yName: String, + y: Any): Task[Unit] + def addContext(xName: String, x: Any)( + implicit sch: Scheduler + ): Resource[Task, Unit] +} + +object Log { + private class LogImpl(logger: Logger, mdc: TaskLocal[Map[String, List[Any]]]) + extends Log { + + private val jackson = new ObjectMapper() + + jackson.setVisibility(PropertyAccessor.ALL, Visibility.NONE) + jackson.setVisibility(PropertyAccessor.FIELD, Visibility.ANY) +// jackson.setVisibility( +// jackson +// .getSerializationConfig() +// .getDefaultVisibilityChecker() +// .withFieldVisibility(JsonAutoDetect.Visibility.ANY) +// .withGetterVisibility(JsonAutoDetect.Visibility.NONE) +// .withSetterVisibility(JsonAutoDetect.Visibility.NONE) +// .withCreatorVisibility(JsonAutoDetect.Visibility.NONE) +// ) + + private def log(body: LogstashMarker => Unit): Task[Unit] = + for { + mdc <- mdc.read + mdcNormalized = mdc.toList.map { + case (k, v :: _) => (k, jackson.writeValueAsString(v)) + } + markers = mdcNormalized.map { case (k, v) => Markers.appendRaw(k, v) } + _ <- Task.delay { + body(Markers.aggregate(markers: _*)) + } + } yield () + + override def addContext(xName: String, x: Any)( + implicit sch: Scheduler + ): Resource[Task, Unit] = { + Resource.make { + for { + ctx <- mdc.read + ctxNew = ctx.get(xName) match { + case Some(list) => + ctx + ((xName, x :: list)) + case None => + ctx + ((xName, x :: Nil)) + } + _ <- mdc.write(ctxNew) + } yield () + } { _: Unit => + for { + ctx <- mdc.read + ctxNew = ctx.get(xName) match { + case Some(_ :: Nil) => + ctx - xName + case Some(_ :: tail) => + ctx + ((xName, tail)) + } + _ <- mdc.write(ctxNew) + } yield () + } + } + + override def info(format: String, xName: String, x: Any): Task[Unit] = + log { mdc => + logger.info( + mdc, + format, + StructuredArguments.raw(xName, jackson.writeValueAsString(x)), + ) + } + + override def info(format: String, + xName: String, + x: Any, + yName: String, + y: Any): Task[Unit] = + log { mdc => + logger.info( + mdc, + format, + StructuredArguments.raw(xName, jackson.writeValueAsString(x)), + StructuredArguments.raw(yName, jackson.writeValueAsString(y)): Any, + ) + } + } + + def make(logger: Logger): Task[Log] = { + for { + mdc <- TaskLocal(Map.empty[String, List[Any]]) + logImpl = new LogImpl(logger, mdc) + } yield logImpl + } + +} + +object Main extends TaskApp { + + val logger: Logger = LoggerFactory.getLogger(getClass) + val o = B(A(123, "Hello"), b = true) + + override def run(args: List[String]): Task[ExitCode] = + init(scheduler) + .map(_ => ExitCode.Success) + .executeWithOptions(_.enableLocalContextPropagation) + + def init(implicit sch: Scheduler): Task[Unit] = + for { + log <- Log.make(logger) + result <- program(log) + } yield result + + def program(logger: Log)(implicit sch: Scheduler): Task[Unit] = { + for { + _ <- logger.addContext("yyy", A(567, "YYYYYYYYYYYY")).use { _: Unit => + for { + _ <- logger.info("Hello {}", "o", o) + } yield () + } + _ <- logger.info("Hello {}", "o", o) + _ <- logger.info("Hello2 {} and {}", "x", 123, "o", o) + } yield () + } + +} From 04a4c036ac1d745d793aa9a34cd157613a855ff7 Mon Sep 17 00:00:00 2001 From: Ondra Pelech Date: Wed, 27 Nov 2019 15:36:10 +0100 Subject: [PATCH 07/35] cats-mtl ApplicativeLocal based solution --- build.sbt | 19 ++ logback-mtl/src/main/resources/logback.xml | 16 ++ .../loggingexperiment/logbackmtl/Main.scala | 176 ++++++++++++++++++ .../logstagemonix/Main.scala | 2 + 4 files changed, 213 insertions(+) create mode 100644 logback-mtl/src/main/resources/logback.xml create mode 100644 logback-mtl/src/main/scala/loggingexperiment/logbackmtl/Main.scala diff --git a/build.sbt b/build.sbt index 8e5fcb2..e415470 100644 --- a/build.sbt +++ b/build.sbt @@ -14,6 +14,8 @@ lazy val Version = new { val izumi = "0.9.12" val gson = "2.8.6" val jackson = "2.9.8" + val catsMtl = "0.7.0" + val meowMtl = "0.4.0" } lazy val root = project @@ -27,6 +29,7 @@ lazy val root = project logbackMonixGson, logbackMonixJackson, logstageMonix, + logbackMtl, ) lazy val logbackZio = project @@ -85,3 +88,19 @@ lazy val logstageMonix = project "io.7mind.izumi" %% "logstage-sink-slf4j" % Version.izumi, ) ) + +lazy val logbackMtl = project + .in(file("logback-mtl")) + .settings( + name := "logback-mtl", + libraryDependencies ++= Seq( + "org.slf4j" % "slf4j-api" % Version.slf4j, + "ch.qos.logback" % "logback-classic" % Version.logback, + "net.logstash.logback" % "logstash-logback-encoder" % Version.logstashLogback, + "io.circe" %% "circe-core" % Version.circe, + "io.circe" %% "circe-generic" % Version.circe, + "io.monix" %% "monix" % Version.monix, + "org.typelevel" %% "cats-mtl-core" % Version.catsMtl, + "com.olegpy" %% "meow-mtl-monix" % Version.meowMtl, + ) + ) diff --git a/logback-mtl/src/main/resources/logback.xml b/logback-mtl/src/main/resources/logback.xml new file mode 100644 index 0000000..1e6feb6 --- /dev/null +++ b/logback-mtl/src/main/resources/logback.xml @@ -0,0 +1,16 @@ + + + + log/loggingexperiment.json + + {"application":"loggingexperiment"} + + + + log/loggingexperiment.log + + %d{HH:mm:ss.SSS} [%thread] %-5level %logger{36} - %msg - %marker%n + + + + diff --git a/logback-mtl/src/main/scala/loggingexperiment/logbackmtl/Main.scala b/logback-mtl/src/main/scala/loggingexperiment/logbackmtl/Main.scala new file mode 100644 index 0000000..e8ebed8 --- /dev/null +++ b/logback-mtl/src/main/scala/loggingexperiment/logbackmtl/Main.scala @@ -0,0 +1,176 @@ +package loggingexperiment.logbackmtl + +import java.security.InvalidParameterException + +import cats.effect._ +import cats.implicits._ +import cats.mtl._ +import com.olegpy.meow.monix._ +import io.circe.Encoder +import io.circe.generic.auto._ +import monix.eval._ +import monix.execution.Scheduler +import net.logstash.logback.marker.{LogstashMarker, Markers} +import org.slf4j.{Logger, LoggerFactory} + +import scala.language.higherKinds + +final case class A(x: Int, y: String) +final case class B(a: A, b: Boolean) + +trait Log[F[_]] { + def info[A](message: String): F[Unit] + def info[A](message: String, name: String, value: A)( + implicit e: Encoder[A] + ): F[Unit] + def info[A](message: String, ex: Throwable): F[Unit] + def info[A](message: String, name: String, value: A, ex: Throwable)( + implicit e: Encoder[A] + ): F[Unit] + def withContext[A, B](name: String, value: A)(inner: F[B])( + implicit e: Encoder[A] + ): F[B] + def withContext[A, B, C](name1: String, value1: A, name2: String, value2: B)( + inner: F[C] + )(implicit e1: Encoder[A], e2: Encoder[B]): F[C] +} + +object Log { + private class LogImpl[F[_]](logger: Logger)( + implicit FApplicativeLocal: ApplicativeLocal[F, Map[String, String]], + FSync: Sync[F] + ) extends Log[F] { + + private def log(body: LogstashMarker => Unit): F[Unit] = + for { + mdc <- FApplicativeLocal.ask + markers = mdc.toList.map { case (k, v) => Markers.appendRaw(k, v) } + _ <- FSync.delay { + body(Markers.aggregate(markers: _*)) + } + } yield () + + override def withContext[A, B](name: String, value: A)( + inner: F[B] + )(implicit e: Encoder[A]): F[B] = { + if (logger.isTraceEnabled || logger.isDebugEnabled || logger.isInfoEnabled || logger.isWarnEnabled || logger.isErrorEnabled) { + FApplicativeLocal.local(_ + ((name, e(value).spaces2)))(inner) + } else { + inner + } + } + + def withContext[A, B, C]( + name1: String, + value1: A, + name2: String, + value2: B + )(inner: F[C])(implicit e1: Encoder[A], e2: Encoder[B]): F[C] = { + if (logger.isTraceEnabled || logger.isDebugEnabled || logger.isInfoEnabled || logger.isWarnEnabled || logger.isErrorEnabled) { + FApplicativeLocal.local( + _ + ((name1, e1(value1).spaces2)) + ((name2, e2(value2).spaces2)) + )(inner) + } else { + inner + } + } + + override def info[A](message: String): F[Unit] = + if (logger.isInfoEnabled) { + log { mdc => + logger.info(mdc, message) + } + } else { + FSync.unit + } + + override def info[A](message: String, name: String, value: A)( + implicit e: Encoder[A] + ): F[Unit] = + if (logger.isInfoEnabled) { + withContext(name, value) { + log { mdc => + logger.info(mdc, message) + } + } + } else { + FSync.unit + } + + // only for Throwables for which you don't want to create Encoder, otherwise use `withContext` + override def info[A](message: String, ex: Throwable): F[Unit] = + if (logger.isInfoEnabled) { + log { mdc => + logger.info(mdc, message, ex) + } + } else { + FSync.unit + } + + // only for Throwables for which you don't want to create Encoder, otherwise use `withContext` + override def info[A](message: String, + name: String, + value: A, + ex: Throwable)(implicit e: Encoder[A]): F[Unit] = + if (logger.isInfoEnabled) { + withContext(name, value) { + log { mdc => + logger.info(mdc, message, ex) + } + } + } else { + FSync.unit + } + } + + def make[F[_]](logger: Logger)( + implicit FApplicativeLocal: ApplicativeLocal[F, Map[String, String]], + FSync: Sync[F] + ): Log[F] = { + new LogImpl(logger) + } +} + +object MonixLog { + def make(logger: Logger): Task[Log[Task]] = { + for { + mdc <- TaskLocal(Map.empty[String, String]) + result = mdc.runLocal { implicit ev => + Log.make(logger) + } + } yield result + } +} + +object Main extends TaskApp { + + val logger: Logger = LoggerFactory.getLogger(getClass) + val o = B(A(123, "Hello"), b = true) + + override def run(args: List[String]): Task[ExitCode] = + init(scheduler) + .map(_ => ExitCode.Success) + .executeWithOptions(_.enableLocalContextPropagation) + + def init(implicit sch: Scheduler): Task[Unit] = + for { + log <- MonixLog.make(logger) + result <- program(log) + } yield result + + def program(logger: Log[Task])(implicit sch: Scheduler): Task[Unit] = { + val ex = new InvalidParameterException("BOOOOOM") + for { + _ <- logger.withContext("yyy", A(567, "YYYYYYYYYYYY")) { + logger.withContext("o", o) { + logger.info("Hello Monix") + } + } + _ <- logger.info("Hello MTL", "o", o, ex) + _ <- logger.withContext("x", 123, "o", o) { + logger.info("Hello2 meow") + } + } yield () + } + +} diff --git a/logstage-monix/src/main/scala/loggingexperiment/logstagemonix/Main.scala b/logstage-monix/src/main/scala/loggingexperiment/logstagemonix/Main.scala index efe15d0..eb8ce05 100644 --- a/logstage-monix/src/main/scala/loggingexperiment/logstagemonix/Main.scala +++ b/logstage-monix/src/main/scala/loggingexperiment/logstagemonix/Main.scala @@ -33,10 +33,12 @@ object Main extends TaskApp { def program(logger: LogIO[Task])(implicit sch: Scheduler): Task[Unit] = { val logger_ = logger("yyy" -> A(567, "YYYYYYYYYYYY")) + val justAList = List[Any](10, "green", "bottles") for { _ <- logger_.info(s"Hello $o") _ <- logger.info(s"Hello $o") _ <- logger.info(s"Hello2 ${123} and $o") + _ <- logger.info(s"Argument: $justAList") } yield () } From 7302efd507a6815d0ddb9027d387aabe79f37142 Mon Sep 17 00:00:00 2001 From: Ondra Pelech Date: Thu, 28 Nov 2019 16:09:48 +0100 Subject: [PATCH 08/35] add README.md --- README.md | 138 ++++++++++++++++++ .../loggingexperiment/logbackmtl/Main.scala | 4 +- 2 files changed, 140 insertions(+), 2 deletions(-) create mode 100644 README.md diff --git a/README.md b/README.md new file mode 100644 index 0000000..eff197a --- /dev/null +++ b/README.md @@ -0,0 +1,138 @@ +# Structured logging framework 4 Cats + +This repo contains experiments with possible implementations of structured logging with `cats-effect`. + +## Goals + + * log commands are side-effecting programs, based on `cats-effect` + * objects provided to log commands should appear as JSON in logs + * they're searchable in Kibana + * we won't duplicate the objects in message itself to reduce size + * logs will contain appropriate context + * the context can be programmatically augmented + * works in a stack-like manner, including shadowing + * works well with `cats-effect` and related libraries (is not bound to `ThreadLocal`/fat JVM thread like slf4j's MDC) + +## Implementation considerations + + * use Circe for the encoding + * mimic `slf4j`'s `Logger` API + +## Interface + +```scala +trait Log[F[_]] { + // excerpt for `info` logging + def info[A](message: String): F[Unit] + def info[A](message: String, name: String, value: A)(implicit e: Encoder[A]): F[Unit] + def info[A](message: String, ex: Throwable): F[Unit] + def info[A](message: String, name: String, value: A, ex: Throwable)(implicit e: Encoder[A]): F[Unit] + + // excerpt for augmenting the log context + def withContext[A, B](name: String, value: A)(inner: F[B])(implicit e: Encoder[A]): F[B] + def withContext[A, B, C](name1: String, value1: A, name2: String, value2: B)(inner: F[C])(implicit e1: Encoder[A], e2: Encoder[B]): F[C] +} +``` + +## Usage + +```scala +def program(logger: Log[Task])(implicit sch: Scheduler): Task[Unit] = { + val ex = new InvalidParameterException("BOOOOOM") + for { + _ <- logger.withContext("a", A(1, "x")) { + logger.withContext("o", o) { + logger.info("Hello Monix") + } + } + _ <- logger.info("Hello MTL", "o", o, ex) + _ <- logger.withContext("x", 123, "o", o) { + logger.info("Hello2 meow", "x", 9) + } + } yield () +} +``` + +### Nested contexts +```scala +_ <- logger.withContext("a", A(1, "x")) { + logger.withContext("o", o) { + logger.info("Hello Monix") + } +} +``` +```json +{ + "@timestamp": "2019-11-28T15:59:24.843+01:00", + "@version": "1", + "message": "Hello Monix", + "logger_name": "loggingexperiment.logbackmtl.Main$", + "thread_name": "scala-execution-context-global-12", + "level": "INFO", + "level_value": 20000, + "a": { + "x": 1, + "y": "x" + }, + "o": { + "a": { + "x": 123, + "y": "Hello" + }, + "b": true + }, + "application": "loggingexperiment" +} +``` + +### Logging exception +```scala +_ <- logger.info("Hello MTL", "o", o, ex) +``` +```json +{ + "@timestamp": "2019-11-28T15:59:24.864+01:00", + "@version": "1", + "message": "Hello MTL", + "logger_name": "loggingexperiment.logbackmtl.Main$", + "thread_name": "scala-execution-context-global-12", + "level": "INFO", + "level_value": 20000, + "stack_trace": "java.security.InvalidParameterException: BOOOOOM\n\tat loggingexperiment.logbackmtl.Main$.program(Main.scala:162)\n\tat loggingexperiment.logbackmtl.Main$.$anonfun$init$1(Main.scala:158)\n\t...", + "o": { + "a": { + "x": 123, + "y": "Hello" + }, + "b": true + }, + "application": "loggingexperiment" +} +``` + +### Context overriding +```scala +_ <- logger.withContext("x", 123, "o", o) { + logger.info("Hello2 meow", "x", 9) +} +``` +```json +{ + "@timestamp": "2019-11-28T15:59:24.876+01:00", + "@version": "1", + "message": "Hello2 meow", + "logger_name": "loggingexperiment.logbackmtl.Main$", + "thread_name": "scala-execution-context-global-12", + "level": "INFO", + "level_value": 20000, + "x": 9, + "o": { + "a": { + "x": 123, + "y": "Hello" + }, + "b": true + }, + "application": "loggingexperiment" +} +``` diff --git a/logback-mtl/src/main/scala/loggingexperiment/logbackmtl/Main.scala b/logback-mtl/src/main/scala/loggingexperiment/logbackmtl/Main.scala index e8ebed8..1cb627a 100644 --- a/logback-mtl/src/main/scala/loggingexperiment/logbackmtl/Main.scala +++ b/logback-mtl/src/main/scala/loggingexperiment/logbackmtl/Main.scala @@ -161,14 +161,14 @@ object Main extends TaskApp { def program(logger: Log[Task])(implicit sch: Scheduler): Task[Unit] = { val ex = new InvalidParameterException("BOOOOOM") for { - _ <- logger.withContext("yyy", A(567, "YYYYYYYYYYYY")) { + _ <- logger.withContext("a", A(1, "x")) { logger.withContext("o", o) { logger.info("Hello Monix") } } _ <- logger.info("Hello MTL", "o", o, ex) _ <- logger.withContext("x", 123, "o", o) { - logger.info("Hello2 meow") + logger.info("Hello2 meow", "x", 9) } } yield () } From fdf33a352396ec718ed92347471765ea28613d5f Mon Sep 17 00:00:00 2001 From: Ondra Pelech Date: Thu, 28 Nov 2019 21:44:16 +0100 Subject: [PATCH 09/35] README.md: other useful metadata in logs --- README.md | 6 ++++++ 1 file changed, 6 insertions(+) diff --git a/README.md b/README.md index eff197a..50e8b2e 100644 --- a/README.md +++ b/README.md @@ -12,6 +12,12 @@ This repo contains experiments with possible implementations of structured loggi * the context can be programmatically augmented * works in a stack-like manner, including shadowing * works well with `cats-effect` and related libraries (is not bound to `ThreadLocal`/fat JVM thread like slf4j's MDC) + * other useful metadata in logs + * timestamp + * file name + * line number + * loglevel as both string and number + * ... to be specified ## Implementation considerations From b1cf19d0c00480b410ecd5b517673b86b5773ad9 Mon Sep 17 00:00:00 2001 From: Ondra Pelech Date: Mon, 2 Dec 2019 20:45:10 +0100 Subject: [PATCH 10/35] keys --- README.md | 5 ++ .../loggingexperiment/logbackmtl/Main.scala | 55 +++++++++++++++++++ 2 files changed, 60 insertions(+) diff --git a/README.md b/README.md index 50e8b2e..a8a0a75 100644 --- a/README.md +++ b/README.md @@ -18,6 +18,11 @@ This repo contains experiments with possible implementations of structured loggi * line number * loglevel as both string and number * ... to be specified + * JSON keys, possibilities: + * always as free-form strings -- simplest solution + * library of standardized JSON keys + * JSON keys via extendable type + * JSON keys via typeclass ## Implementation considerations diff --git a/logback-mtl/src/main/scala/loggingexperiment/logbackmtl/Main.scala b/logback-mtl/src/main/scala/loggingexperiment/logbackmtl/Main.scala index 1cb627a..2a9a8e7 100644 --- a/logback-mtl/src/main/scala/loggingexperiment/logbackmtl/Main.scala +++ b/logback-mtl/src/main/scala/loggingexperiment/logbackmtl/Main.scala @@ -18,11 +18,24 @@ import scala.language.higherKinds final case class A(x: Int, y: String) final case class B(a: A, b: Boolean) +trait KeySub { + def toString: String +} + +trait KeyTC[A] { + def toString(a: A): String +} + trait Log[F[_]] { def info[A](message: String): F[Unit] def info[A](message: String, name: String, value: A)( implicit e: Encoder[A] ): F[Unit] + def info[A](message: String, name: KeySub, value: A)( + implicit e: Encoder[A] + ): F[Unit] + def info[A, K](message: String, name: K, value: A)(implicit e: Encoder[A], + k: KeyTC[K]): F[Unit] def info[A](message: String, ex: Throwable): F[Unit] def info[A](message: String, name: String, value: A, ex: Throwable)( implicit e: Encoder[A] @@ -30,6 +43,9 @@ trait Log[F[_]] { def withContext[A, B](name: String, value: A)(inner: F[B])( implicit e: Encoder[A] ): F[B] + def withContext[A, B](map: Map[String, A])(inner: F[B])( + implicit e: Encoder[A] + ): F[B] def withContext[A, B, C](name1: String, value1: A, name2: String, value2: B)( inner: F[C] )(implicit e1: Encoder[A], e2: Encoder[B]): F[C] @@ -60,6 +76,18 @@ object Log { } } + override def withContext[A, B]( + map: Map[String, A] + )(inner: F[B])(implicit e: Encoder[A]): F[B] = { + if (logger.isTraceEnabled || logger.isDebugEnabled || logger.isInfoEnabled || logger.isWarnEnabled || logger.isErrorEnabled) { + FApplicativeLocal.local(map.foldLeft(_) { + case (m, (k, v)) => m + ((k, e(v).spaces2)) + })(inner) + } else { + inner + } + } + def withContext[A, B, C]( name1: String, value1: A, @@ -97,6 +125,33 @@ object Log { FSync.unit } + override def info[A](message: String, name: KeySub, value: A)( + implicit e: Encoder[A] + ): F[Unit] = + if (logger.isInfoEnabled) { + withContext(name.toString, value) { + log { mdc => + logger.info(mdc, message) + } + } + } else { + FSync.unit + } + + override def info[A, K](message: String, name: K, value: A)( + implicit e: Encoder[A], + k: KeyTC[K] + ): F[Unit] = + if (logger.isInfoEnabled) { + withContext(k.toString(name), value) { + log { mdc => + logger.info(mdc, message) + } + } + } else { + FSync.unit + } + // only for Throwables for which you don't want to create Encoder, otherwise use `withContext` override def info[A](message: String, ex: Throwable): F[Unit] = if (logger.isInfoEnabled) { From 2e92b3ce08c48a54f360d82493b8ff2c3e93dc95 Mon Sep 17 00:00:00 2001 From: Ondra Pelech Date: Fri, 6 Dec 2019 21:43:44 +0100 Subject: [PATCH 11/35] MTL builder, basic macro working --- build.sbt | 23 ++ .../src/main/resources/logback.xml | 17 + .../loggingexperiment/logbackmtl/Main.scala | 46 +++ .../loggingexperiment/logbackmtl/Lib.scala | 336 ++++++++++++++++++ logback-mtl/src/main/resources/logback.xml | 1 + 5 files changed, 423 insertions(+) create mode 100644 logback-mtl-builder-app/src/main/resources/logback.xml create mode 100644 logback-mtl-builder-app/src/main/scala/loggingexperiment/logbackmtl/Main.scala create mode 100644 logback-mtl-builder/src/main/scala/loggingexperiment/logbackmtl/Lib.scala diff --git a/build.sbt b/build.sbt index e415470..ca809c5 100644 --- a/build.sbt +++ b/build.sbt @@ -104,3 +104,26 @@ lazy val logbackMtl = project "com.olegpy" %% "meow-mtl-monix" % Version.meowMtl, ) ) + +lazy val logbackMtlBuilder = project + .in(file("logback-mtl-builder")) + .settings( + name := "logback-mtl-builder", + libraryDependencies ++= Seq( + "org.slf4j" % "slf4j-api" % Version.slf4j, + "ch.qos.logback" % "logback-classic" % Version.logback, + "net.logstash.logback" % "logstash-logback-encoder" % Version.logstashLogback, + "io.circe" %% "circe-core" % Version.circe, + "io.circe" %% "circe-generic" % Version.circe, + "io.monix" %% "monix" % Version.monix, + "org.typelevel" %% "cats-mtl-core" % Version.catsMtl, + "com.olegpy" %% "meow-mtl-monix" % Version.meowMtl, + ) + ) + +lazy val logbackMtlBuilderApp = project + .in(file("logback-mtl-builder-app")) + .settings( + name := "logback-mtl-builder-app", + ) + .dependsOn(logbackMtlBuilder) diff --git a/logback-mtl-builder-app/src/main/resources/logback.xml b/logback-mtl-builder-app/src/main/resources/logback.xml new file mode 100644 index 0000000..4156d2c --- /dev/null +++ b/logback-mtl-builder-app/src/main/resources/logback.xml @@ -0,0 +1,17 @@ + + + + log/loggingexperiment.json + + {"application":"loggingexperiment"} + true + + + + log/loggingexperiment.log + + %d{HH:mm:ss.SSS} [%thread] %-5level %logger{36} - %msg - %marker%n + + + + diff --git a/logback-mtl-builder-app/src/main/scala/loggingexperiment/logbackmtl/Main.scala b/logback-mtl-builder-app/src/main/scala/loggingexperiment/logbackmtl/Main.scala new file mode 100644 index 0000000..f03c211 --- /dev/null +++ b/logback-mtl-builder-app/src/main/scala/loggingexperiment/logbackmtl/Main.scala @@ -0,0 +1,46 @@ +package loggingexperiment.logbackmtl + +import java.security.InvalidParameterException + +import cats.effect._ +import io.circe.generic.auto._ +import monix.eval._ +import monix.execution.Scheduler + +import scala.language.higherKinds + +object Main extends TaskApp { + + final case class A(x: Int, y: String) + final case class B(a: A, b: Boolean) + + private val o = B(A(123, "Hello"), b = true) + + override def run(args: List[String]): Task[ExitCode] = + init(scheduler) + .map(_ => ExitCode.Success) + .executeWithOptions(_.enableLocalContextPropagation) + + def init(implicit sch: Scheduler): Task[Unit] = + for { + mdc <- TaskLocal(Logger.Context.empty) + logger = MonixLog.make(mdc) + result <- program(logger) + } yield result + + def program(logger: Logger[Task])(implicit sch: Scheduler): Task[Unit] = { + val ex = new InvalidParameterException("BOOOOOM") + for { + _ <- logger + .context("a", A(1, "x")) + .context("o", o) + .apply + .info("Hello Monix") + _ <- logger.apply.info("Hello MTL", ex) + _ <- logger.context("x", 123).context("o", o).use { + logger.context("x", 9).apply.info("Hello2 meow") + } + } yield () + } + +} diff --git a/logback-mtl-builder/src/main/scala/loggingexperiment/logbackmtl/Lib.scala b/logback-mtl-builder/src/main/scala/loggingexperiment/logbackmtl/Lib.scala new file mode 100644 index 0000000..4d913bf --- /dev/null +++ b/logback-mtl-builder/src/main/scala/loggingexperiment/logbackmtl/Lib.scala @@ -0,0 +1,336 @@ +package loggingexperiment.logbackmtl + +import cats.effect._ +import cats.implicits._ +import cats.mtl._ +import com.olegpy.meow.monix._ +import io.circe.Encoder +import io.circe.generic.auto._ +import monix.eval._ +import net.logstash.logback.marker.Markers +import org.slf4j.{LoggerFactory, Marker} + +import scala.language.higherKinds +import scala.reflect.ClassTag + +trait Logger[F[_]] { +// def info: LoggerBuilder2[F] + def FSync: Sync[F] + def isInfoEnabled: F[Boolean] + def underlying: org.slf4j.Logger +// def info(message: String): F[Unit] +// def info(message: String, ex: Throwable): F[Unit] + def apply: Logger.LoggerImpl[F] + def context[A](name: String, value: A)(implicit e: Encoder[A]): Logger[F] + def context[A](map: Map[String, A])(implicit e: Encoder[A]): Logger[F] + def use[A](inner: F[A]): F[A] +} + +//trait LoggerBuilder2[F[_]] { +// def msg(message: String): F[Unit] +// def msg(ex: Throwable)(message: String): F[Unit] +//} + +object Logger { + + class JsonInString private (private[Logger] val raw: String) extends AnyVal + object JsonInString { + def make[A](x: A)(implicit e: Encoder[A]): JsonInString = { + new JsonInString(e(x).spaces2) + } + } + + type Context = Map[String, JsonInString] + object Context { + def empty: Context = Map.empty + } + + private object Macros { + import scala.reflect.macros.blackbox + type Context[F[_]] = blackbox.Context { type PrefixType = LoggerImpl[F] } + def info[F[_]](c: Context[F])(message: c.Expr[String]): c.Expr[F[Unit]] = { + import c.universe._ + val tree = q""" + ${c.prefix}.log2(self => (self.isInfoEnabled, marker => self.FSync.delay { self.underlying.info(marker, $message) })) + """ + c.Expr[F[Unit]](tree) + } + } + + class LoggerImpl[F[_]](val underlying: org.slf4j.Logger, context: Context)( + implicit FApplicativeLocal: ApplicativeLocal[F, Context], + val FSync: Sync[F] + ) extends Logger[F] { + + override def apply: LoggerImpl[F] = this + + private val marker: F[Marker] = FApplicativeLocal.ask.map { mdc => + val markers = mdc.toList.map { + case (k, v) => + Markers.appendRaw(k, v.raw) + } + Markers.aggregate(markers: _*) + } + + val isInfoEnabled: F[Boolean] = FSync.delay { + underlying.isInfoEnabled + } + + def log(isEnabled: F[Boolean], body: Marker => F[Unit]): F[Unit] = + isEnabled.flatMap { isEnabled => + if (isEnabled) { + use { + marker.flatMap { marker => + body(marker) + } + } + } else { + FSync.unit + } + } + + def log2(f: LoggerImpl[F] => (F[Boolean], Marker => F[Unit])): F[Unit] = { + val (isEnabled, body) = f(this) + log(isEnabled, body) + } + + import scala.language.experimental.macros + + def info(message: String): F[Unit] = macro Macros.info[F] +// log(this, +// isInfoEnabled, +// marker => FSync.delay { underlying.info(marker, message) } +// ) + + def info(message: String, ex: Throwable): F[Unit] = + log( + isInfoEnabled, + marker => FSync.delay { underlying.info(marker, message, ex) } + ) + + override def context[A](name: String, + value: A)(implicit e: Encoder[A]): Logger[F] = + new LoggerImpl[F]( + underlying, + context + ((name, JsonInString.make(value))) + ) + + override def context[A]( + map: Map[String, A] + )(implicit e: Encoder[A]): Logger[F] = + new LoggerImpl[F]( + underlying, + context ++ map.mapValues(JsonInString.make(_)) + ) + + override def use[A](inner: F[A]): F[A] = + FApplicativeLocal.local(_ ++ context)(inner) + } + +// private class LoggerBuilder2Impl[F[_]]( +// logger: Logger, +// context: Map[String, String] +// )(implicit FApplicativeLocal: ApplicativeLocal[F, Map[String, String]], +// FSync: Sync[F]) +// extends LoggerBuilder2[F] { +// +// private def log(body: LogstashMarker => Unit): F[Unit] = +// for { +// mdc <- FApplicativeLocal.ask +// markers = mdc.toList.map { case (k, v) => Markers.appendRaw(k, v) } +// _ <- FSync.delay { +// body(Markers.aggregate(markers: _*)) +// } +// } yield () +// +// override def msg(message: String): F[Unit] = +// if (logger.isInfoEnabled) { +// log { mdc => +// logger.info(mdc, message) +// } +// } else { +// FSync.unit +// } +// +// override def msg(ex: Throwable)(message: String): F[Unit] = ??? +// } + + def make[F[_]](logger: org.slf4j.Logger)( + implicit FApplicativeLocal: ApplicativeLocal[F, Context], + FSync: Sync[F] + ): Logger[F] = { + new LoggerImpl(logger, Map()) + } + + def make[F[_]](name: String)( + implicit FApplicativeLocal: ApplicativeLocal[F, Context], + FSync: Sync[F] + ): Logger[F] = { + make(LoggerFactory.getLogger(name)) + } + + def make[F[_], T](implicit classTag: ClassTag[T], + FApplicativeLocal: ApplicativeLocal[F, Context], + FSync: Sync[F]): Logger[F] = { + make(LoggerFactory.getLogger(classTag.runtimeClass)) + } +} + +//trait Log[F[_]] { +// +// def info[A](message: String): F[Unit] +// def info[A](message: String, name: String, value: A)( +// implicit e: Encoder[A] +// ): F[Unit] +// def info[A](message: String, m: Map[String, A])( +// implicit e: Encoder[A] +// ): F[Unit] +// def info[A](message: String, ex: Throwable): F[Unit] +// def info[A](message: String, name: String, value: A, ex: Throwable)( +// implicit e: Encoder[A] +// ): F[Unit] +// def info[A](message: String, m: Map[String, A], ex: Throwable)( +// implicit e: Encoder[A] +// ): F[Unit] +// +// def context[A, B](name: String, value: A)(inner: F[B])( +// implicit e: Encoder[A] +// ): F[B] +// def context[A, B](map: Map[String, A])(inner: F[B])( +// implicit e: Encoder[A] +// ): F[B] +//} +// +//object Log { +// private class LogImpl[F[_]](logger: Logger)( +// implicit FApplicativeLocal: ApplicativeLocal[F, Map[String, String]], +// FSync: Sync[F] +// ) extends Log[F] { +// +// private def log(body: LogstashMarker => Unit): F[Unit] = +// for { +// mdc <- FApplicativeLocal.ask +// markers = mdc.toList.map { case (k, v) => Markers.appendRaw(k, v) } +// _ <- FSync.delay { +// body(Markers.aggregate(markers: _*)) +// } +// } yield () +// +// override def context[A, B](name: String, value: A)( +// inner: F[B] +// )(implicit e: Encoder[A]): F[B] = { +// if (logger.isTraceEnabled || logger.isDebugEnabled || logger.isInfoEnabled || logger.isWarnEnabled || logger.isErrorEnabled) { +// FApplicativeLocal.local(_ + ((name, e(value).spaces2)))(inner) +// } else { +// inner +// } +// } +// +// override def context[A, B]( +// map: Map[String, A] +// )(inner: F[B])(implicit e: Encoder[A]): F[B] = { +// if (logger.isTraceEnabled || logger.isDebugEnabled || logger.isInfoEnabled || logger.isWarnEnabled || logger.isErrorEnabled) { +// FApplicativeLocal.local(map.foldLeft(_) { +// case (m, (k, v)) => m + ((k, e(v).spaces2)) +// })(inner) +// } else { +// inner +// } +// } +// +// def withContext[A, B, C]( +// name1: String, +// value1: A, +// name2: String, +// value2: B +// )(inner: F[C])(implicit e1: Encoder[A], e2: Encoder[B]): F[C] = { +// if (logger.isTraceEnabled || logger.isDebugEnabled || logger.isInfoEnabled || logger.isWarnEnabled || logger.isErrorEnabled) { +// FApplicativeLocal.local( +// _ + ((name1, e1(value1).spaces2)) + ((name2, e2(value2).spaces2)) +// )(inner) +// } else { +// inner +// } +// } +// +// override def info[A](message: String): F[Unit] = +// if (logger.isInfoEnabled) { +// log { mdc => +// logger.info(mdc, message) +// } +// } else { +// FSync.unit +// } +// +// override def info[A](message: String, name: String, value: A)( +// implicit e: Encoder[A] +// ): F[Unit] = +// if (logger.isInfoEnabled) { +// withContext(name, value) { +// log { mdc => +// logger.info(mdc, message) +// } +// } +// } else { +// FSync.unit +// } +// +// // only for Throwables for which you don't want to create Encoder, otherwise use `withContext` +// override def info[A](message: String, ex: Throwable): F[Unit] = +// if (logger.isInfoEnabled) { +// log { mdc => +// logger.info(mdc, message, ex) +// } +// } else { +// FSync.unit +// } +// +// // only for Throwables for which you don't want to create Encoder, otherwise use `withContext` +// override def info[A](message: String, +// name: String, +// value: A, +// ex: Throwable)(implicit e: Encoder[A]): F[Unit] = +// if (logger.isInfoEnabled) { +// withContext(name, value) { +// log { mdc => +// logger.info(mdc, message, ex) +// } +// } +// } else { +// FSync.unit +// } +// } +// +// def make[F[_]](logger: Logger)( +// implicit FApplicativeLocal: ApplicativeLocal[F, Map[String, String]], +// FSync: Sync[F] +// ): Log[F] = { +// new LogImpl(logger) +// } +//} + +object MonixLog { + def make( + logger: org.slf4j.Logger + )(taskLocalContext: TaskLocal[Logger.Context]): Logger[Task] = { + taskLocalContext.runLocal { implicit ev => + Logger.make(logger) + } + } + + def make( + name: String + )(taskLocalContext: TaskLocal[Logger.Context]): Logger[Task] = { + taskLocalContext.runLocal { implicit ev => + Logger.make(name) + } + } + + def make[T]( + taskLocalContext: TaskLocal[Logger.Context] + )(implicit classTag: ClassTag[T]): Logger[Task] = { + taskLocalContext.runLocal { implicit ev => + Logger.make + } + } +} diff --git a/logback-mtl/src/main/resources/logback.xml b/logback-mtl/src/main/resources/logback.xml index 1e6feb6..4156d2c 100644 --- a/logback-mtl/src/main/resources/logback.xml +++ b/logback-mtl/src/main/resources/logback.xml @@ -4,6 +4,7 @@ log/loggingexperiment.json {"application":"loggingexperiment"} + true From a9a3d55fe5308ddba9e80b8a37b1e1b45488f0bb Mon Sep 17 00:00:00 2001 From: Ondra Pelech Date: Fri, 6 Dec 2019 23:58:50 +0100 Subject: [PATCH 12/35] MTL builder, LoggerInfo implemented --- README.md | 92 ++--- build.sbt | 9 +- .../loggingexperiment/logbackmtl/Main.scala | 37 +- .../loggingexperiment/logbackmtl/Lib.scala | 336 ------------------ .../src/main/scala/slf4cats/slf4cats.scala | 166 +++++++++ 5 files changed, 254 insertions(+), 386 deletions(-) delete mode 100644 logback-mtl-builder/src/main/scala/loggingexperiment/logbackmtl/Lib.scala create mode 100644 logback-mtl-builder/src/main/scala/slf4cats/slf4cats.scala diff --git a/README.md b/README.md index a8a0a75..aa4d50f 100644 --- a/README.md +++ b/README.md @@ -32,53 +32,52 @@ This repo contains experiments with possible implementations of structured loggi ## Interface ```scala -trait Log[F[_]] { +trait Logger[F[_]] { // excerpt for `info` logging - def info[A](message: String): F[Unit] - def info[A](message: String, name: String, value: A)(implicit e: Encoder[A]): F[Unit] - def info[A](message: String, ex: Throwable): F[Unit] - def info[A](message: String, name: String, value: A, ex: Throwable)(implicit e: Encoder[A]): F[Unit] - - // excerpt for augmenting the log context - def withContext[A, B](name: String, value: A)(inner: F[B])(implicit e: Encoder[A]): F[B] - def withContext[A, B, C](name1: String, value1: A, name2: String, value2: B)(inner: F[C])(implicit e1: Encoder[A], e2: Encoder[B]): F[C] + def info: LoggerInfo[F] + //... + def context[A](name: String, value: A)(implicit e: Encoder[A]): Logger[F] + def context[A](map: Map[String, A])(implicit e: Encoder[A]): Logger[F] + def use[A](inner: F[A]): F[A] +} +class LoggerInfo[F[_]] (...) { + def apply(message: String): F[Unit] = macro ??? + def apply(message: String, throwable: Throwable): F[Unit] = macro ??? } ``` ## Usage ```scala -def program(logger: Log[Task])(implicit sch: Scheduler): Task[Unit] = { +def program(logger: Logger[Task])(implicit sch: Scheduler): Task[Unit] = { val ex = new InvalidParameterException("BOOOOOM") for { - _ <- logger.withContext("a", A(1, "x")) { - logger.withContext("o", o) { - logger.info("Hello Monix") - } - } - _ <- logger.info("Hello MTL", "o", o, ex) - _ <- logger.withContext("x", 123, "o", o) { - logger.info("Hello2 meow", "x", 9) + _ <- logger + .context("a", A(1, "x")) + .context("o", o) + .info("Hello Monix") + _ <- logger.info("Hello MTL", ex) + _ <- logger.context("x", 123).context("o", o).use { + logger.context("x", 9).info("Hello2 meow") } } yield () } ``` -### Nested contexts +### Multiple contexts ```scala -_ <- logger.withContext("a", A(1, "x")) { - logger.withContext("o", o) { - logger.info("Hello Monix") - } -} +_ <- logger + .context("a", A(1, "x")) + .context("o", o) + .info("Hello Monix") ``` ```json { - "@timestamp": "2019-11-28T15:59:24.843+01:00", + "@timestamp": "2019-12-06T23:20:55.237+01:00", "@version": "1", "message": "Hello Monix", "logger_name": "loggingexperiment.logbackmtl.Main$", - "thread_name": "scala-execution-context-global-12", + "thread_name": "scala-execution-context-global-11", "level": "INFO", "level_value": 20000, "a": { @@ -92,48 +91,49 @@ _ <- logger.withContext("a", A(1, "x")) { }, "b": true }, - "application": "loggingexperiment" + "application": "loggingexperiment", + "caller_class_name": "loggingexperiment.logbackmtl.Main$", + "caller_method_name": "$anonfun$program$6", + "caller_file_name": "Main.scala", + "caller_line_number": 66 } ``` ### Logging exception ```scala -_ <- logger.info("Hello MTL", "o", o, ex) +_ <- logger.info("Hello MTL", ex) ``` ```json { - "@timestamp": "2019-11-28T15:59:24.864+01:00", + "@timestamp": "2019-12-06T23:20:55.254+01:00", "@version": "1", "message": "Hello MTL", "logger_name": "loggingexperiment.logbackmtl.Main$", - "thread_name": "scala-execution-context-global-12", + "thread_name": "scala-execution-context-global-11", "level": "INFO", "level_value": 20000, - "stack_trace": "java.security.InvalidParameterException: BOOOOOM\n\tat loggingexperiment.logbackmtl.Main$.program(Main.scala:162)\n\tat loggingexperiment.logbackmtl.Main$.$anonfun$init$1(Main.scala:158)\n\t...", - "o": { - "a": { - "x": 123, - "y": "Hello" - }, - "b": true - }, - "application": "loggingexperiment" + "stack_trace": "java.security.InvalidParameterException: BOOOOOM\n\tat loggingexperiment.logbackmtl.Main$.program(Main.scala:61)\n...", + "application": "loggingexperiment", + "caller_class_name": "loggingexperiment.logbackmtl.Main$", + "caller_method_name": "$anonfun$program$11", + "caller_file_name": "Main.scala", + "caller_line_number": 67 } ``` ### Context overriding ```scala -_ <- logger.withContext("x", 123, "o", o) { - logger.info("Hello2 meow", "x", 9) +_ <- logger.context("x", 123).context("o", o).use { + logger.context("x", 9).info("Hello2 meow") } ``` ```json { - "@timestamp": "2019-11-28T15:59:24.876+01:00", + "@timestamp": "2019-12-06T23:20:55.263+01:00", "@version": "1", "message": "Hello2 meow", "logger_name": "loggingexperiment.logbackmtl.Main$", - "thread_name": "scala-execution-context-global-12", + "thread_name": "scala-execution-context-global-11", "level": "INFO", "level_value": 20000, "x": 9, @@ -144,6 +144,10 @@ _ <- logger.withContext("x", 123, "o", o) { }, "b": true }, - "application": "loggingexperiment" + "application": "loggingexperiment", + "caller_class_name": "loggingexperiment.logbackmtl.Main$", + "caller_method_name": "$anonfun$program$17", + "caller_file_name": "Main.scala", + "caller_line_number": 69 } ``` diff --git a/build.sbt b/build.sbt index ca809c5..a1b5ac4 100644 --- a/build.sbt +++ b/build.sbt @@ -15,6 +15,7 @@ lazy val Version = new { val gson = "2.8.6" val jackson = "2.9.8" val catsMtl = "0.7.0" + val catsEffect = "2.0.0" val meowMtl = "0.4.0" } @@ -115,9 +116,9 @@ lazy val logbackMtlBuilder = project "net.logstash.logback" % "logstash-logback-encoder" % Version.logstashLogback, "io.circe" %% "circe-core" % Version.circe, "io.circe" %% "circe-generic" % Version.circe, - "io.monix" %% "monix" % Version.monix, "org.typelevel" %% "cats-mtl-core" % Version.catsMtl, - "com.olegpy" %% "meow-mtl-monix" % Version.meowMtl, + "org.typelevel" %% "cats-effect" % Version.catsEffect, + "org.scala-lang" % "scala-reflect" % scalaVersion.value, ) ) @@ -125,5 +126,9 @@ lazy val logbackMtlBuilderApp = project .in(file("logback-mtl-builder-app")) .settings( name := "logback-mtl-builder-app", + libraryDependencies ++= Seq( + "io.monix" %% "monix" % Version.monix, + "com.olegpy" %% "meow-mtl-monix" % Version.meowMtl, + ) ) .dependsOn(logbackMtlBuilder) diff --git a/logback-mtl-builder-app/src/main/scala/loggingexperiment/logbackmtl/Main.scala b/logback-mtl-builder-app/src/main/scala/loggingexperiment/logbackmtl/Main.scala index f03c211..67da8fc 100644 --- a/logback-mtl-builder-app/src/main/scala/loggingexperiment/logbackmtl/Main.scala +++ b/logback-mtl-builder-app/src/main/scala/loggingexperiment/logbackmtl/Main.scala @@ -3,15 +3,45 @@ package loggingexperiment.logbackmtl import java.security.InvalidParameterException import cats.effect._ +import com.olegpy.meow.monix._ import io.circe.generic.auto._ import monix.eval._ import monix.execution.Scheduler +import slf4cats._ import scala.language.higherKinds +import scala.reflect.ClassTag + +object MonixLog { + def make( + logger: org.slf4j.Logger + )(taskLocalContext: TaskLocal[Logger.Context]): Logger[Task] = { + taskLocalContext.runLocal { implicit ev => + Logger.make(logger) + } + } + + def make( + name: String + )(taskLocalContext: TaskLocal[Logger.Context]): Logger[Task] = { + taskLocalContext.runLocal { implicit ev => + Logger.make(name) + } + } + + def make[T]( + taskLocalContext: TaskLocal[Logger.Context] + )(implicit classTag: ClassTag[T]): Logger[Task] = { + taskLocalContext.runLocal { implicit ev => + Logger.make + } + } +} object Main extends TaskApp { final case class A(x: Int, y: String) + final case class B(a: A, b: Boolean) private val o = B(A(123, "Hello"), b = true) @@ -24,7 +54,7 @@ object Main extends TaskApp { def init(implicit sch: Scheduler): Task[Unit] = for { mdc <- TaskLocal(Logger.Context.empty) - logger = MonixLog.make(mdc) + logger = MonixLog.make[Main.type](mdc) result <- program(logger) } yield result @@ -34,11 +64,10 @@ object Main extends TaskApp { _ <- logger .context("a", A(1, "x")) .context("o", o) - .apply .info("Hello Monix") - _ <- logger.apply.info("Hello MTL", ex) + _ <- logger.info("Hello MTL", ex) _ <- logger.context("x", 123).context("o", o).use { - logger.context("x", 9).apply.info("Hello2 meow") + logger.context("x", 9).info("Hello2 meow") } } yield () } diff --git a/logback-mtl-builder/src/main/scala/loggingexperiment/logbackmtl/Lib.scala b/logback-mtl-builder/src/main/scala/loggingexperiment/logbackmtl/Lib.scala deleted file mode 100644 index 4d913bf..0000000 --- a/logback-mtl-builder/src/main/scala/loggingexperiment/logbackmtl/Lib.scala +++ /dev/null @@ -1,336 +0,0 @@ -package loggingexperiment.logbackmtl - -import cats.effect._ -import cats.implicits._ -import cats.mtl._ -import com.olegpy.meow.monix._ -import io.circe.Encoder -import io.circe.generic.auto._ -import monix.eval._ -import net.logstash.logback.marker.Markers -import org.slf4j.{LoggerFactory, Marker} - -import scala.language.higherKinds -import scala.reflect.ClassTag - -trait Logger[F[_]] { -// def info: LoggerBuilder2[F] - def FSync: Sync[F] - def isInfoEnabled: F[Boolean] - def underlying: org.slf4j.Logger -// def info(message: String): F[Unit] -// def info(message: String, ex: Throwable): F[Unit] - def apply: Logger.LoggerImpl[F] - def context[A](name: String, value: A)(implicit e: Encoder[A]): Logger[F] - def context[A](map: Map[String, A])(implicit e: Encoder[A]): Logger[F] - def use[A](inner: F[A]): F[A] -} - -//trait LoggerBuilder2[F[_]] { -// def msg(message: String): F[Unit] -// def msg(ex: Throwable)(message: String): F[Unit] -//} - -object Logger { - - class JsonInString private (private[Logger] val raw: String) extends AnyVal - object JsonInString { - def make[A](x: A)(implicit e: Encoder[A]): JsonInString = { - new JsonInString(e(x).spaces2) - } - } - - type Context = Map[String, JsonInString] - object Context { - def empty: Context = Map.empty - } - - private object Macros { - import scala.reflect.macros.blackbox - type Context[F[_]] = blackbox.Context { type PrefixType = LoggerImpl[F] } - def info[F[_]](c: Context[F])(message: c.Expr[String]): c.Expr[F[Unit]] = { - import c.universe._ - val tree = q""" - ${c.prefix}.log2(self => (self.isInfoEnabled, marker => self.FSync.delay { self.underlying.info(marker, $message) })) - """ - c.Expr[F[Unit]](tree) - } - } - - class LoggerImpl[F[_]](val underlying: org.slf4j.Logger, context: Context)( - implicit FApplicativeLocal: ApplicativeLocal[F, Context], - val FSync: Sync[F] - ) extends Logger[F] { - - override def apply: LoggerImpl[F] = this - - private val marker: F[Marker] = FApplicativeLocal.ask.map { mdc => - val markers = mdc.toList.map { - case (k, v) => - Markers.appendRaw(k, v.raw) - } - Markers.aggregate(markers: _*) - } - - val isInfoEnabled: F[Boolean] = FSync.delay { - underlying.isInfoEnabled - } - - def log(isEnabled: F[Boolean], body: Marker => F[Unit]): F[Unit] = - isEnabled.flatMap { isEnabled => - if (isEnabled) { - use { - marker.flatMap { marker => - body(marker) - } - } - } else { - FSync.unit - } - } - - def log2(f: LoggerImpl[F] => (F[Boolean], Marker => F[Unit])): F[Unit] = { - val (isEnabled, body) = f(this) - log(isEnabled, body) - } - - import scala.language.experimental.macros - - def info(message: String): F[Unit] = macro Macros.info[F] -// log(this, -// isInfoEnabled, -// marker => FSync.delay { underlying.info(marker, message) } -// ) - - def info(message: String, ex: Throwable): F[Unit] = - log( - isInfoEnabled, - marker => FSync.delay { underlying.info(marker, message, ex) } - ) - - override def context[A](name: String, - value: A)(implicit e: Encoder[A]): Logger[F] = - new LoggerImpl[F]( - underlying, - context + ((name, JsonInString.make(value))) - ) - - override def context[A]( - map: Map[String, A] - )(implicit e: Encoder[A]): Logger[F] = - new LoggerImpl[F]( - underlying, - context ++ map.mapValues(JsonInString.make(_)) - ) - - override def use[A](inner: F[A]): F[A] = - FApplicativeLocal.local(_ ++ context)(inner) - } - -// private class LoggerBuilder2Impl[F[_]]( -// logger: Logger, -// context: Map[String, String] -// )(implicit FApplicativeLocal: ApplicativeLocal[F, Map[String, String]], -// FSync: Sync[F]) -// extends LoggerBuilder2[F] { -// -// private def log(body: LogstashMarker => Unit): F[Unit] = -// for { -// mdc <- FApplicativeLocal.ask -// markers = mdc.toList.map { case (k, v) => Markers.appendRaw(k, v) } -// _ <- FSync.delay { -// body(Markers.aggregate(markers: _*)) -// } -// } yield () -// -// override def msg(message: String): F[Unit] = -// if (logger.isInfoEnabled) { -// log { mdc => -// logger.info(mdc, message) -// } -// } else { -// FSync.unit -// } -// -// override def msg(ex: Throwable)(message: String): F[Unit] = ??? -// } - - def make[F[_]](logger: org.slf4j.Logger)( - implicit FApplicativeLocal: ApplicativeLocal[F, Context], - FSync: Sync[F] - ): Logger[F] = { - new LoggerImpl(logger, Map()) - } - - def make[F[_]](name: String)( - implicit FApplicativeLocal: ApplicativeLocal[F, Context], - FSync: Sync[F] - ): Logger[F] = { - make(LoggerFactory.getLogger(name)) - } - - def make[F[_], T](implicit classTag: ClassTag[T], - FApplicativeLocal: ApplicativeLocal[F, Context], - FSync: Sync[F]): Logger[F] = { - make(LoggerFactory.getLogger(classTag.runtimeClass)) - } -} - -//trait Log[F[_]] { -// -// def info[A](message: String): F[Unit] -// def info[A](message: String, name: String, value: A)( -// implicit e: Encoder[A] -// ): F[Unit] -// def info[A](message: String, m: Map[String, A])( -// implicit e: Encoder[A] -// ): F[Unit] -// def info[A](message: String, ex: Throwable): F[Unit] -// def info[A](message: String, name: String, value: A, ex: Throwable)( -// implicit e: Encoder[A] -// ): F[Unit] -// def info[A](message: String, m: Map[String, A], ex: Throwable)( -// implicit e: Encoder[A] -// ): F[Unit] -// -// def context[A, B](name: String, value: A)(inner: F[B])( -// implicit e: Encoder[A] -// ): F[B] -// def context[A, B](map: Map[String, A])(inner: F[B])( -// implicit e: Encoder[A] -// ): F[B] -//} -// -//object Log { -// private class LogImpl[F[_]](logger: Logger)( -// implicit FApplicativeLocal: ApplicativeLocal[F, Map[String, String]], -// FSync: Sync[F] -// ) extends Log[F] { -// -// private def log(body: LogstashMarker => Unit): F[Unit] = -// for { -// mdc <- FApplicativeLocal.ask -// markers = mdc.toList.map { case (k, v) => Markers.appendRaw(k, v) } -// _ <- FSync.delay { -// body(Markers.aggregate(markers: _*)) -// } -// } yield () -// -// override def context[A, B](name: String, value: A)( -// inner: F[B] -// )(implicit e: Encoder[A]): F[B] = { -// if (logger.isTraceEnabled || logger.isDebugEnabled || logger.isInfoEnabled || logger.isWarnEnabled || logger.isErrorEnabled) { -// FApplicativeLocal.local(_ + ((name, e(value).spaces2)))(inner) -// } else { -// inner -// } -// } -// -// override def context[A, B]( -// map: Map[String, A] -// )(inner: F[B])(implicit e: Encoder[A]): F[B] = { -// if (logger.isTraceEnabled || logger.isDebugEnabled || logger.isInfoEnabled || logger.isWarnEnabled || logger.isErrorEnabled) { -// FApplicativeLocal.local(map.foldLeft(_) { -// case (m, (k, v)) => m + ((k, e(v).spaces2)) -// })(inner) -// } else { -// inner -// } -// } -// -// def withContext[A, B, C]( -// name1: String, -// value1: A, -// name2: String, -// value2: B -// )(inner: F[C])(implicit e1: Encoder[A], e2: Encoder[B]): F[C] = { -// if (logger.isTraceEnabled || logger.isDebugEnabled || logger.isInfoEnabled || logger.isWarnEnabled || logger.isErrorEnabled) { -// FApplicativeLocal.local( -// _ + ((name1, e1(value1).spaces2)) + ((name2, e2(value2).spaces2)) -// )(inner) -// } else { -// inner -// } -// } -// -// override def info[A](message: String): F[Unit] = -// if (logger.isInfoEnabled) { -// log { mdc => -// logger.info(mdc, message) -// } -// } else { -// FSync.unit -// } -// -// override def info[A](message: String, name: String, value: A)( -// implicit e: Encoder[A] -// ): F[Unit] = -// if (logger.isInfoEnabled) { -// withContext(name, value) { -// log { mdc => -// logger.info(mdc, message) -// } -// } -// } else { -// FSync.unit -// } -// -// // only for Throwables for which you don't want to create Encoder, otherwise use `withContext` -// override def info[A](message: String, ex: Throwable): F[Unit] = -// if (logger.isInfoEnabled) { -// log { mdc => -// logger.info(mdc, message, ex) -// } -// } else { -// FSync.unit -// } -// -// // only for Throwables for which you don't want to create Encoder, otherwise use `withContext` -// override def info[A](message: String, -// name: String, -// value: A, -// ex: Throwable)(implicit e: Encoder[A]): F[Unit] = -// if (logger.isInfoEnabled) { -// withContext(name, value) { -// log { mdc => -// logger.info(mdc, message, ex) -// } -// } -// } else { -// FSync.unit -// } -// } -// -// def make[F[_]](logger: Logger)( -// implicit FApplicativeLocal: ApplicativeLocal[F, Map[String, String]], -// FSync: Sync[F] -// ): Log[F] = { -// new LogImpl(logger) -// } -//} - -object MonixLog { - def make( - logger: org.slf4j.Logger - )(taskLocalContext: TaskLocal[Logger.Context]): Logger[Task] = { - taskLocalContext.runLocal { implicit ev => - Logger.make(logger) - } - } - - def make( - name: String - )(taskLocalContext: TaskLocal[Logger.Context]): Logger[Task] = { - taskLocalContext.runLocal { implicit ev => - Logger.make(name) - } - } - - def make[T]( - taskLocalContext: TaskLocal[Logger.Context] - )(implicit classTag: ClassTag[T]): Logger[Task] = { - taskLocalContext.runLocal { implicit ev => - Logger.make - } - } -} diff --git a/logback-mtl-builder/src/main/scala/slf4cats/slf4cats.scala b/logback-mtl-builder/src/main/scala/slf4cats/slf4cats.scala new file mode 100644 index 0000000..7972c4b --- /dev/null +++ b/logback-mtl-builder/src/main/scala/slf4cats/slf4cats.scala @@ -0,0 +1,166 @@ +package slf4cats + +import cats.effect._ +import cats.implicits._ +import cats.mtl._ +import io.circe.Encoder +import io.circe.generic.auto._ +import net.logstash.logback.marker.Markers +import org.slf4j.{LoggerFactory, Marker} + +import scala.language.higherKinds +import scala.reflect.ClassTag + +trait Logger[F[_]] { + def info: LoggerInfo[F] + def context[A](name: String, value: A)(implicit e: Encoder[A]): Logger[F] + def context[A](map: Map[String, A])(implicit e: Encoder[A]): Logger[F] + def use[A](inner: F[A]): F[A] +} + +object Logger { + + class JsonInString private (private[slf4cats] val raw: String) extends AnyVal + object JsonInString { + def make[A](x: A)(implicit e: Encoder[A]): JsonInString = { + new JsonInString(e(x).spaces2) + } + } + + type Context = Map[String, JsonInString] + object Context { + def empty: Context = Map.empty + } + + private class LoggerImpl[F[_]]( + underlying: org.slf4j.Logger, + context: Map[String, (Encoder[Any], Any)] + )(implicit FApplicativeLocal: ApplicativeLocal[F, Context], + val FSync: Sync[F]) + extends Logger[F] { + + override def info: LoggerInfo[F] = + new LoggerInfo[F](this, underlying, context) + + override def context[A](name: String, + value: A)(implicit e: Encoder[A]): Logger[F] = + new LoggerImpl[F]( + underlying, + context + ((name, (e.asInstanceOf[Encoder[Any]], value))) + ) + + override def context[A]( + map: Map[String, A] + )(implicit e: Encoder[A]): Logger[F] = + new LoggerImpl[F]( + underlying, + context ++ map.mapValues((e.asInstanceOf[Encoder[Any]], _)) + ) + + override def use[A](inner: F[A]): F[A] = + FApplicativeLocal.local(_ ++ context.mapValues { + case (e, v) => JsonInString.make(v)(e) + })(inner) + } + + def make[F[_]](logger: org.slf4j.Logger)( + implicit FApplicativeLocal: ApplicativeLocal[F, Context], + FSync: Sync[F] + ): Logger[F] = { + new LoggerImpl(logger, Map()) + } + + def make[F[_]](name: String)( + implicit FApplicativeLocal: ApplicativeLocal[F, Context], + FSync: Sync[F] + ): Logger[F] = { + make(LoggerFactory.getLogger(name)) + } + + def make[F[_], T](implicit classTag: ClassTag[T], + FApplicativeLocal: ApplicativeLocal[F, Context], + FSync: Sync[F]): Logger[F] = { + make(LoggerFactory.getLogger(classTag.runtimeClass)) + } +} + +sealed class LoggerCommand[F[_]] private[slf4cats] ( + logger: Logger[F], + underlying: org.slf4j.Logger, + context: Map[String, (Encoder[Any], Any)] +)(implicit FApplicativeLocal: ApplicativeLocal[F, Logger.Context], + FSync: Sync[F]) { + + protected val marker: F[Marker] = FApplicativeLocal.ask.map { mdc => + val markers = mdc.toList.map { + case (k, v) => + Markers.appendRaw(k, v.raw) + } + Markers.aggregate(markers: _*) + } + + /** only to be used used by macro */ + def withUnderlying( + macroCallback: (Sync[F], org.slf4j.Logger) => (F[Boolean], + Marker => F[Unit]) + ): F[Unit] = { + val (isEnabled, body) = macroCallback(FSync, underlying) + isEnabled.flatMap { isEnabled => + if (isEnabled) { + logger.use { + marker.flatMap { marker => + body(marker) + } + } + } else { + FSync.unit + } + } + } + +} + +object LoggerCommand { + private[slf4cats] object Macros { + import scala.reflect.macros.blackbox + type Context[F[_]] = blackbox.Context { type PrefixType = LoggerCommand[F] } + } +} + +class LoggerInfo[F[_]] private[slf4cats] ( + logger: Logger[F], + underlying: org.slf4j.Logger, + context: Map[String, (Encoder[Any], Any)] +)(implicit FApplicativeLocal: ApplicativeLocal[F, Logger.Context], + FSync: Sync[F]) + extends LoggerCommand(logger, underlying, context) { + import scala.language.experimental.macros + def apply(message: String): F[Unit] = macro LoggerInfo.Macros.info[F] + def apply(message: String, throwable: Throwable): F[Unit] = + macro LoggerInfo.Macros.infoThrowable[F] +} + +object LoggerInfo { + + private[LoggerInfo] object Macros { + import LoggerCommand.Macros._ + + def info[F[_]](c: Context[F])(message: c.Expr[String]): c.Expr[F[Unit]] = { + import c.universe._ + val tree = + q"${c.prefix}.withUnderlying { case (fsync, underlying) => (fsync.delay { underlying.isInfoEnabled }, marker => fsync.delay { underlying.info(marker, $message) }) }" + c.Expr[F[Unit]](tree) + } + + def infoThrowable[F[_]](c: Context[F])( + message: c.Expr[String], + throwable: c.Expr[Throwable] + ): c.Expr[F[Unit]] = { + import c.universe._ + val tree = + q"${c.prefix}.withUnderlying { case (fsync, underlying) => (fsync.delay { underlying.isInfoEnabled }, marker => fsync.delay { underlying.info(marker, $message, $throwable) }) }" + c.Expr[F[Unit]](tree) + } + } + +} From 4b05bd82e78e705344a0491a9aeed41b16bb206f Mon Sep 17 00:00:00 2001 From: Ondra Pelech Date: Sat, 7 Dec 2019 00:30:50 +0100 Subject: [PATCH 13/35] purge, leave only MTL builder --- build.sbt | 84 +------ .../src/main/resources/logback.xml | 10 - .../loggingexperiment/logbackmonix/Main.scala | 133 ---------- .../src/main/resources/logback.xml | 10 - .../loggingexperiment/logbackmonix/Main.scala | 147 ----------- logback-mtl/src/main/resources/logback.xml | 17 -- .../loggingexperiment/logbackmtl/Main.scala | 231 ------------------ logback-zio/src/main/resources/logback.xml | 10 - .../loggingexperiment/logbackzio/Main.scala | 146 ----------- logstage-monix/src/main/resources/logback.xml | 19 -- .../logstagemonix/Main.scala | 45 ---- 11 files changed, 2 insertions(+), 850 deletions(-) delete mode 100644 logback-monix-gson/src/main/resources/logback.xml delete mode 100644 logback-monix-gson/src/main/scala/loggingexperiment/logbackmonix/Main.scala delete mode 100644 logback-monix-jackson/src/main/resources/logback.xml delete mode 100644 logback-monix-jackson/src/main/scala/loggingexperiment/logbackmonix/Main.scala delete mode 100644 logback-mtl/src/main/resources/logback.xml delete mode 100644 logback-mtl/src/main/scala/loggingexperiment/logbackmtl/Main.scala delete mode 100644 logback-zio/src/main/resources/logback.xml delete mode 100644 logback-zio/src/main/scala/loggingexperiment/logbackzio/Main.scala delete mode 100644 logstage-monix/src/main/resources/logback.xml delete mode 100644 logstage-monix/src/main/scala/loggingexperiment/logstagemonix/Main.scala diff --git a/build.sbt b/build.sbt index a1b5ac4..55418b2 100644 --- a/build.sbt +++ b/build.sbt @@ -9,11 +9,7 @@ lazy val Version = new { val slf4j = "1.7.29" val logback = "1.2.3" val logstashLogback = "6.2" - val zio = "1.0.0-RC16" val monix = "3.1.0" - val izumi = "0.9.12" - val gson = "2.8.6" - val jackson = "2.9.8" val catsMtl = "0.7.0" val catsEffect = "2.0.0" val meowMtl = "0.4.0" @@ -26,84 +22,8 @@ lazy val root = project publish / skip := true, // doesn't publish ivy XML files, in contrast to "publishArtifact := false" ) .aggregate( - logbackZio, - logbackMonixGson, - logbackMonixJackson, - logstageMonix, - logbackMtl, - ) - -lazy val logbackZio = project - .in(file("logback-zio")) - .settings( - name := "logback-zio", - libraryDependencies ++= Seq( - "org.slf4j" % "slf4j-api" % Version.slf4j, - "ch.qos.logback" % "logback-classic" % Version.logback, - "net.logstash.logback" % "logstash-logback-encoder" % Version.logstashLogback, - "io.circe" %% "circe-core" % Version.circe, - "io.circe" %% "circe-generic" % Version.circe, - "dev.zio" %% "zio" % Version.zio, - ) - ) - -lazy val logbackMonixGson = project - .in(file("logback-monix-gson")) - .settings( - name := "logback-monix-gson", - libraryDependencies ++= Seq( - "org.slf4j" % "slf4j-api" % Version.slf4j, - "ch.qos.logback" % "logback-classic" % Version.logback, - "net.logstash.logback" % "logstash-logback-encoder" % Version.logstashLogback, - "com.google.code.gson" % "gson" % Version.gson, - "io.monix" %% "monix" % Version.monix, - ) - ) - -lazy val logbackMonixJackson = project - .in(file("logback-monix-jackson")) - .settings( - name := "logback-monix-jackson", - libraryDependencies ++= Seq( - "org.slf4j" % "slf4j-api" % Version.slf4j, - "ch.qos.logback" % "logback-classic" % Version.logback, - "net.logstash.logback" % "logstash-logback-encoder" % Version.logstashLogback, - "com.fasterxml.jackson.core" % "jackson-databind" % Version.jackson, - "io.monix" %% "monix" % Version.monix, - ) - ) - -lazy val logstageMonix = project - .in(file("logstage-monix")) - .settings( - name := "logstage-monix", - libraryDependencies ++= Seq( - "org.slf4j" % "slf4j-api" % Version.slf4j, - "ch.qos.logback" % "logback-classic" % Version.logback, - "net.logstash.logback" % "logstash-logback-encoder" % Version.logstashLogback, - "io.circe" %% "circe-core" % Version.circe, - "io.circe" %% "circe-generic" % Version.circe, - "io.monix" %% "monix" % Version.monix, - "io.7mind.izumi" %% "logstage-core" % Version.izumi, - "io.7mind.izumi" %% "logstage-rendering-circe" % Version.izumi, - "io.7mind.izumi" %% "logstage-sink-slf4j" % Version.izumi, - ) - ) - -lazy val logbackMtl = project - .in(file("logback-mtl")) - .settings( - name := "logback-mtl", - libraryDependencies ++= Seq( - "org.slf4j" % "slf4j-api" % Version.slf4j, - "ch.qos.logback" % "logback-classic" % Version.logback, - "net.logstash.logback" % "logstash-logback-encoder" % Version.logstashLogback, - "io.circe" %% "circe-core" % Version.circe, - "io.circe" %% "circe-generic" % Version.circe, - "io.monix" %% "monix" % Version.monix, - "org.typelevel" %% "cats-mtl-core" % Version.catsMtl, - "com.olegpy" %% "meow-mtl-monix" % Version.meowMtl, - ) + logbackMtlBuilder, + logbackMtlBuilderApp, ) lazy val logbackMtlBuilder = project diff --git a/logback-monix-gson/src/main/resources/logback.xml b/logback-monix-gson/src/main/resources/logback.xml deleted file mode 100644 index 396c5a5..0000000 --- a/logback-monix-gson/src/main/resources/logback.xml +++ /dev/null @@ -1,10 +0,0 @@ - - - - log/loggingexperiment.log - - {"application":"loggingexperiment"} - - - - diff --git a/logback-monix-gson/src/main/scala/loggingexperiment/logbackmonix/Main.scala b/logback-monix-gson/src/main/scala/loggingexperiment/logbackmonix/Main.scala deleted file mode 100644 index 7bb2453..0000000 --- a/logback-monix-gson/src/main/scala/loggingexperiment/logbackmonix/Main.scala +++ /dev/null @@ -1,133 +0,0 @@ -package loggingexperiment.logbackmonix - -import cats.effect._ -import com.google.gson.Gson -import monix.eval._ -import monix.execution.Scheduler -import net.logstash.logback.argument.StructuredArguments -import net.logstash.logback.marker.{LogstashMarker, Markers} -import org.slf4j.{Logger, LoggerFactory} - -final case class A(x: Int, y: String) -final case class B(a: A, b: Boolean) - -trait Log { - def info(format: String, xName: String, x: Any): Task[Unit] - def info(format: String, - xName: String, - x: Any, - yName: String, - y: Any): Task[Unit] - def addContext(xName: String, x: Any)( - implicit sch: Scheduler - ): Resource[Task, Unit] -} - -object Log { - private class LogImpl(logger: Logger, mdc: TaskLocal[Map[String, List[Any]]]) - extends Log { - - private val gson = new Gson() - - private def log(body: LogstashMarker => Unit): Task[Unit] = - for { - mdc <- mdc.read - mdcNormalized = mdc.toList.map { - case (k, v :: _) => (k, gson.toJson(v)) - } - markers = mdcNormalized.map { case (k, v) => Markers.appendRaw(k, v) } - _ <- Task.delay { - body(Markers.aggregate(markers: _*)) - } - } yield () - - override def addContext(xName: String, x: Any)( - implicit sch: Scheduler - ): Resource[Task, Unit] = { - Resource.make { - for { - ctx <- mdc.read - ctxNew = ctx.get(xName) match { - case Some(list) => - ctx + ((xName, x :: list)) - case None => - ctx + ((xName, x :: Nil)) - } - _ <- mdc.write(ctxNew) - } yield () - } { _: Unit => - for { - ctx <- mdc.read - ctxNew = ctx.get(xName) match { - case Some(_ :: Nil) => - ctx - xName - case Some(_ :: tail) => - ctx + ((xName, tail)) - } - _ <- mdc.write(ctxNew) - } yield () - } - } - - override def info(format: String, xName: String, x: Any): Task[Unit] = - log { mdc => - logger.info( - mdc, - format, - StructuredArguments.raw(xName, gson.toJson(x)), - ) - } - - override def info(format: String, - xName: String, - x: Any, - yName: String, - y: Any): Task[Unit] = - log { mdc => - logger.info( - mdc, - format, - StructuredArguments.raw(xName, gson.toJson(x)), - StructuredArguments.raw(yName, gson.toJson(y)): Any, - ) - } - } - - def make(logger: Logger): Task[Log] = { - for { - mdc <- TaskLocal(Map.empty[String, List[Any]]) - logImpl = new LogImpl(logger, mdc) - } yield logImpl - } - -} - -object Main extends TaskApp { - - val logger: Logger = LoggerFactory.getLogger(getClass) - val o = B(A(123, "Hello"), b = true) - - override def run(args: List[String]): Task[ExitCode] = - init(scheduler) - .map(_ => ExitCode.Success) - .executeWithOptions(_.enableLocalContextPropagation) - - def init(implicit sch: Scheduler): Task[Unit] = - for { - log <- Log.make(logger) - result <- program(log) - } yield result - - def program(logger: Log)(implicit sch: Scheduler): Task[Unit] = { - for { - _ <- logger.addContext("yyy", A(567, "YYYYYYYYYYYY")).use { _: Unit => - for { - _ <- logger.info("Hello {}", "o", o) - } yield () - } - _ <- logger.info("Hello {}", "o", o) - _ <- logger.info("Hello2 {} and {}", "x", 123, "o", o) - } yield () - } - -} diff --git a/logback-monix-jackson/src/main/resources/logback.xml b/logback-monix-jackson/src/main/resources/logback.xml deleted file mode 100644 index 396c5a5..0000000 --- a/logback-monix-jackson/src/main/resources/logback.xml +++ /dev/null @@ -1,10 +0,0 @@ - - - - log/loggingexperiment.log - - {"application":"loggingexperiment"} - - - - diff --git a/logback-monix-jackson/src/main/scala/loggingexperiment/logbackmonix/Main.scala b/logback-monix-jackson/src/main/scala/loggingexperiment/logbackmonix/Main.scala deleted file mode 100644 index 2108b7b..0000000 --- a/logback-monix-jackson/src/main/scala/loggingexperiment/logbackmonix/Main.scala +++ /dev/null @@ -1,147 +0,0 @@ -package loggingexperiment.logbackmonix - -import cats.effect._ -import com.fasterxml.jackson.annotation.JsonAutoDetect.Visibility -import com.fasterxml.jackson.annotation.PropertyAccessor -import com.fasterxml.jackson.databind.ObjectMapper -import monix.eval._ -import monix.execution.Scheduler -import net.logstash.logback.argument.StructuredArguments -import net.logstash.logback.marker.{LogstashMarker, Markers} -import org.slf4j.{Logger, LoggerFactory} - -final case class A(x: Int, y: String) -final case class B(a: A, b: Boolean) - -trait Log { - def info(format: String, xName: String, x: Any): Task[Unit] - def info(format: String, - xName: String, - x: Any, - yName: String, - y: Any): Task[Unit] - def addContext(xName: String, x: Any)( - implicit sch: Scheduler - ): Resource[Task, Unit] -} - -object Log { - private class LogImpl(logger: Logger, mdc: TaskLocal[Map[String, List[Any]]]) - extends Log { - - private val jackson = new ObjectMapper() - - jackson.setVisibility(PropertyAccessor.ALL, Visibility.NONE) - jackson.setVisibility(PropertyAccessor.FIELD, Visibility.ANY) -// jackson.setVisibility( -// jackson -// .getSerializationConfig() -// .getDefaultVisibilityChecker() -// .withFieldVisibility(JsonAutoDetect.Visibility.ANY) -// .withGetterVisibility(JsonAutoDetect.Visibility.NONE) -// .withSetterVisibility(JsonAutoDetect.Visibility.NONE) -// .withCreatorVisibility(JsonAutoDetect.Visibility.NONE) -// ) - - private def log(body: LogstashMarker => Unit): Task[Unit] = - for { - mdc <- mdc.read - mdcNormalized = mdc.toList.map { - case (k, v :: _) => (k, jackson.writeValueAsString(v)) - } - markers = mdcNormalized.map { case (k, v) => Markers.appendRaw(k, v) } - _ <- Task.delay { - body(Markers.aggregate(markers: _*)) - } - } yield () - - override def addContext(xName: String, x: Any)( - implicit sch: Scheduler - ): Resource[Task, Unit] = { - Resource.make { - for { - ctx <- mdc.read - ctxNew = ctx.get(xName) match { - case Some(list) => - ctx + ((xName, x :: list)) - case None => - ctx + ((xName, x :: Nil)) - } - _ <- mdc.write(ctxNew) - } yield () - } { _: Unit => - for { - ctx <- mdc.read - ctxNew = ctx.get(xName) match { - case Some(_ :: Nil) => - ctx - xName - case Some(_ :: tail) => - ctx + ((xName, tail)) - } - _ <- mdc.write(ctxNew) - } yield () - } - } - - override def info(format: String, xName: String, x: Any): Task[Unit] = - log { mdc => - logger.info( - mdc, - format, - StructuredArguments.raw(xName, jackson.writeValueAsString(x)), - ) - } - - override def info(format: String, - xName: String, - x: Any, - yName: String, - y: Any): Task[Unit] = - log { mdc => - logger.info( - mdc, - format, - StructuredArguments.raw(xName, jackson.writeValueAsString(x)), - StructuredArguments.raw(yName, jackson.writeValueAsString(y)): Any, - ) - } - } - - def make(logger: Logger): Task[Log] = { - for { - mdc <- TaskLocal(Map.empty[String, List[Any]]) - logImpl = new LogImpl(logger, mdc) - } yield logImpl - } - -} - -object Main extends TaskApp { - - val logger: Logger = LoggerFactory.getLogger(getClass) - val o = B(A(123, "Hello"), b = true) - - override def run(args: List[String]): Task[ExitCode] = - init(scheduler) - .map(_ => ExitCode.Success) - .executeWithOptions(_.enableLocalContextPropagation) - - def init(implicit sch: Scheduler): Task[Unit] = - for { - log <- Log.make(logger) - result <- program(log) - } yield result - - def program(logger: Log)(implicit sch: Scheduler): Task[Unit] = { - for { - _ <- logger.addContext("yyy", A(567, "YYYYYYYYYYYY")).use { _: Unit => - for { - _ <- logger.info("Hello {}", "o", o) - } yield () - } - _ <- logger.info("Hello {}", "o", o) - _ <- logger.info("Hello2 {} and {}", "x", 123, "o", o) - } yield () - } - -} diff --git a/logback-mtl/src/main/resources/logback.xml b/logback-mtl/src/main/resources/logback.xml deleted file mode 100644 index 4156d2c..0000000 --- a/logback-mtl/src/main/resources/logback.xml +++ /dev/null @@ -1,17 +0,0 @@ - - - - log/loggingexperiment.json - - {"application":"loggingexperiment"} - true - - - - log/loggingexperiment.log - - %d{HH:mm:ss.SSS} [%thread] %-5level %logger{36} - %msg - %marker%n - - - - diff --git a/logback-mtl/src/main/scala/loggingexperiment/logbackmtl/Main.scala b/logback-mtl/src/main/scala/loggingexperiment/logbackmtl/Main.scala deleted file mode 100644 index 2a9a8e7..0000000 --- a/logback-mtl/src/main/scala/loggingexperiment/logbackmtl/Main.scala +++ /dev/null @@ -1,231 +0,0 @@ -package loggingexperiment.logbackmtl - -import java.security.InvalidParameterException - -import cats.effect._ -import cats.implicits._ -import cats.mtl._ -import com.olegpy.meow.monix._ -import io.circe.Encoder -import io.circe.generic.auto._ -import monix.eval._ -import monix.execution.Scheduler -import net.logstash.logback.marker.{LogstashMarker, Markers} -import org.slf4j.{Logger, LoggerFactory} - -import scala.language.higherKinds - -final case class A(x: Int, y: String) -final case class B(a: A, b: Boolean) - -trait KeySub { - def toString: String -} - -trait KeyTC[A] { - def toString(a: A): String -} - -trait Log[F[_]] { - def info[A](message: String): F[Unit] - def info[A](message: String, name: String, value: A)( - implicit e: Encoder[A] - ): F[Unit] - def info[A](message: String, name: KeySub, value: A)( - implicit e: Encoder[A] - ): F[Unit] - def info[A, K](message: String, name: K, value: A)(implicit e: Encoder[A], - k: KeyTC[K]): F[Unit] - def info[A](message: String, ex: Throwable): F[Unit] - def info[A](message: String, name: String, value: A, ex: Throwable)( - implicit e: Encoder[A] - ): F[Unit] - def withContext[A, B](name: String, value: A)(inner: F[B])( - implicit e: Encoder[A] - ): F[B] - def withContext[A, B](map: Map[String, A])(inner: F[B])( - implicit e: Encoder[A] - ): F[B] - def withContext[A, B, C](name1: String, value1: A, name2: String, value2: B)( - inner: F[C] - )(implicit e1: Encoder[A], e2: Encoder[B]): F[C] -} - -object Log { - private class LogImpl[F[_]](logger: Logger)( - implicit FApplicativeLocal: ApplicativeLocal[F, Map[String, String]], - FSync: Sync[F] - ) extends Log[F] { - - private def log(body: LogstashMarker => Unit): F[Unit] = - for { - mdc <- FApplicativeLocal.ask - markers = mdc.toList.map { case (k, v) => Markers.appendRaw(k, v) } - _ <- FSync.delay { - body(Markers.aggregate(markers: _*)) - } - } yield () - - override def withContext[A, B](name: String, value: A)( - inner: F[B] - )(implicit e: Encoder[A]): F[B] = { - if (logger.isTraceEnabled || logger.isDebugEnabled || logger.isInfoEnabled || logger.isWarnEnabled || logger.isErrorEnabled) { - FApplicativeLocal.local(_ + ((name, e(value).spaces2)))(inner) - } else { - inner - } - } - - override def withContext[A, B]( - map: Map[String, A] - )(inner: F[B])(implicit e: Encoder[A]): F[B] = { - if (logger.isTraceEnabled || logger.isDebugEnabled || logger.isInfoEnabled || logger.isWarnEnabled || logger.isErrorEnabled) { - FApplicativeLocal.local(map.foldLeft(_) { - case (m, (k, v)) => m + ((k, e(v).spaces2)) - })(inner) - } else { - inner - } - } - - def withContext[A, B, C]( - name1: String, - value1: A, - name2: String, - value2: B - )(inner: F[C])(implicit e1: Encoder[A], e2: Encoder[B]): F[C] = { - if (logger.isTraceEnabled || logger.isDebugEnabled || logger.isInfoEnabled || logger.isWarnEnabled || logger.isErrorEnabled) { - FApplicativeLocal.local( - _ + ((name1, e1(value1).spaces2)) + ((name2, e2(value2).spaces2)) - )(inner) - } else { - inner - } - } - - override def info[A](message: String): F[Unit] = - if (logger.isInfoEnabled) { - log { mdc => - logger.info(mdc, message) - } - } else { - FSync.unit - } - - override def info[A](message: String, name: String, value: A)( - implicit e: Encoder[A] - ): F[Unit] = - if (logger.isInfoEnabled) { - withContext(name, value) { - log { mdc => - logger.info(mdc, message) - } - } - } else { - FSync.unit - } - - override def info[A](message: String, name: KeySub, value: A)( - implicit e: Encoder[A] - ): F[Unit] = - if (logger.isInfoEnabled) { - withContext(name.toString, value) { - log { mdc => - logger.info(mdc, message) - } - } - } else { - FSync.unit - } - - override def info[A, K](message: String, name: K, value: A)( - implicit e: Encoder[A], - k: KeyTC[K] - ): F[Unit] = - if (logger.isInfoEnabled) { - withContext(k.toString(name), value) { - log { mdc => - logger.info(mdc, message) - } - } - } else { - FSync.unit - } - - // only for Throwables for which you don't want to create Encoder, otherwise use `withContext` - override def info[A](message: String, ex: Throwable): F[Unit] = - if (logger.isInfoEnabled) { - log { mdc => - logger.info(mdc, message, ex) - } - } else { - FSync.unit - } - - // only for Throwables for which you don't want to create Encoder, otherwise use `withContext` - override def info[A](message: String, - name: String, - value: A, - ex: Throwable)(implicit e: Encoder[A]): F[Unit] = - if (logger.isInfoEnabled) { - withContext(name, value) { - log { mdc => - logger.info(mdc, message, ex) - } - } - } else { - FSync.unit - } - } - - def make[F[_]](logger: Logger)( - implicit FApplicativeLocal: ApplicativeLocal[F, Map[String, String]], - FSync: Sync[F] - ): Log[F] = { - new LogImpl(logger) - } -} - -object MonixLog { - def make(logger: Logger): Task[Log[Task]] = { - for { - mdc <- TaskLocal(Map.empty[String, String]) - result = mdc.runLocal { implicit ev => - Log.make(logger) - } - } yield result - } -} - -object Main extends TaskApp { - - val logger: Logger = LoggerFactory.getLogger(getClass) - val o = B(A(123, "Hello"), b = true) - - override def run(args: List[String]): Task[ExitCode] = - init(scheduler) - .map(_ => ExitCode.Success) - .executeWithOptions(_.enableLocalContextPropagation) - - def init(implicit sch: Scheduler): Task[Unit] = - for { - log <- MonixLog.make(logger) - result <- program(log) - } yield result - - def program(logger: Log[Task])(implicit sch: Scheduler): Task[Unit] = { - val ex = new InvalidParameterException("BOOOOOM") - for { - _ <- logger.withContext("a", A(1, "x")) { - logger.withContext("o", o) { - logger.info("Hello Monix") - } - } - _ <- logger.info("Hello MTL", "o", o, ex) - _ <- logger.withContext("x", 123, "o", o) { - logger.info("Hello2 meow", "x", 9) - } - } yield () - } - -} diff --git a/logback-zio/src/main/resources/logback.xml b/logback-zio/src/main/resources/logback.xml deleted file mode 100644 index 396c5a5..0000000 --- a/logback-zio/src/main/resources/logback.xml +++ /dev/null @@ -1,10 +0,0 @@ - - - - log/loggingexperiment.log - - {"application":"loggingexperiment"} - - - - diff --git a/logback-zio/src/main/scala/loggingexperiment/logbackzio/Main.scala b/logback-zio/src/main/scala/loggingexperiment/logbackzio/Main.scala deleted file mode 100644 index acc6ce5..0000000 --- a/logback-zio/src/main/scala/loggingexperiment/logbackzio/Main.scala +++ /dev/null @@ -1,146 +0,0 @@ -package loggingexperiment.logbackzio - -import io.circe.Encoder -import io.circe.generic.auto._ -import io.circe.syntax._ -import net.logstash.logback.argument.StructuredArguments -import net.logstash.logback.marker.{LogstashMarker, Markers} -import org.slf4j.{Logger, LoggerFactory} -import zio._ - -final case class A(x: Int, y: String) -final case class B(a: A, b: Boolean) - -trait Log { - def log: Log.Service -} - -object Log { - - trait Service { - def info[A](format: String, xName: String, x: A)( - implicit e: Encoder[A] - ): UIO[Unit] - def info[A, B](format: String, xName: String, x: A, yName: String, y: B)( - implicit ex: Encoder[A], - ey: Encoder[B] - ): UIO[Unit] - def addContext[A](xName: String, x: A)( - implicit e: Encoder[A] - ): UManaged[Unit] - } - - def log: ZIO[Log, Nothing, Log.Service] = - ZIO.access[Log](_.log) - - private class LogImpl(logger: Logger, - mdc: FiberRef[Map[String, List[(Any, Encoder[Any])]]]) - extends Service { - - private def log(body: LogstashMarker => Unit): UIO[Unit] = - for { - mdc <- mdc.get - mdcNormalized = mdc.toList.map { - case (k, v) => (k, v.head match { case (v, e) => e(v).toString }) - } - markers = mdcNormalized.map { case (k, v) => Markers.appendRaw(k, v) } - _ <- UIO.effectTotal { - body(Markers.aggregate(markers: _*)) - } - } yield () - - override def addContext[A](xName: String, - x: A)(implicit e: Encoder[A]): UManaged[Unit] = { - Managed.make { - for { - _ <- mdc.update { mdc => - mdc.get(xName) match { - case Some(list) => - mdc + ((xName, (x, e.asInstanceOf[Encoder[Any]]) :: list)) - case None => - mdc + ((xName, (x, e.asInstanceOf[Encoder[Any]]) :: Nil)) - } - } - } yield () - } { _: Unit => - for { - _ <- mdc.update { mdc => - mdc.get(xName) match { - case Some(_ :: Nil) => - mdc - xName - case Some(_ :: tail) => - mdc + ((xName, tail)) - } - } - } yield () - } - } - - override def info[A](format: String, xName: String, x: A)( - implicit e: Encoder[A] - ): UIO[Unit] = - log { mdc => - logger.info( - mdc, - format, - StructuredArguments.raw(xName, x.asJson.toString), - ) - } - - override def info[A, B]( - format: String, - xName: String, - x: A, - yName: String, - y: B - )(implicit ex: Encoder[A], ey: Encoder[B]): UIO[Unit] = - log { mdc => - logger.info( - mdc, - format, - StructuredArguments.raw(xName, x.asJson.toString), - StructuredArguments.raw(yName, y.asJson.toString): Any, - ) - } - } - - def make(logger: Logger): UIO[Log] = { - for { - mdc <- FiberRef.make(Map.empty[String, List[(Any, Encoder[Any])]]) - logImpl = new LogImpl(logger, mdc) - svc = new Log { - override def log: Service = logImpl - } - } yield svc - - } -} - -object Main extends App { - - val logger: Logger = LoggerFactory.getLogger(getClass) - val o = B(A(123, "Hello"), b = true) - - override def run(args: List[String]): ZIO[ZEnv, Nothing, Int] = - init.fold(_ => 1, _ => 0) - - def init: Task[Unit] = - for { - log <- Log.make(logger) - result <- program.provide(log) - } yield result - - def program: RIO[Log, Unit] = { - for { - logger <- Log.log - _ <- logger.addContext("yyy", A(567, "YYYYYYYYYYYY")).use { _: Unit => - for { - _ <- logger.info("Hello {}", "o", o) - } yield () - } - _ <- logger.info("Hello {}", "o", o) - _ <- logger.info("Hello2 {} and {}", "x", 123, "o", o) - } yield () - } - -} diff --git a/logstage-monix/src/main/resources/logback.xml b/logstage-monix/src/main/resources/logback.xml deleted file mode 100644 index c2e2933..0000000 --- a/logstage-monix/src/main/resources/logback.xml +++ /dev/null @@ -1,19 +0,0 @@ - - - - log/loggingexperiment.log - - - - - - - - { "message": "#asJson{%message}" } - - - - - - - diff --git a/logstage-monix/src/main/scala/loggingexperiment/logstagemonix/Main.scala b/logstage-monix/src/main/scala/loggingexperiment/logstagemonix/Main.scala deleted file mode 100644 index eb8ce05..0000000 --- a/logstage-monix/src/main/scala/loggingexperiment/logstagemonix/Main.scala +++ /dev/null @@ -1,45 +0,0 @@ -package loggingexperiment.logstagemonix - -import cats.effect._ -import io.circe.generic.auto._ -import izumi.logstage.api.rendering.json.LogstageCirceRenderingPolicy -import izumi.logstage.sink.slf4j.LogSinkLegacySlf4jImpl -import logstage._ -import logstage.circe._ -import monix.eval._ -import monix.execution.Scheduler - -final case class A(x: Int, y: String) -final case class B(a: A, b: Boolean) - -object Main extends TaskApp { - - val sink = new LogSinkLegacySlf4jImpl(new LogstageCirceRenderingPolicy(true)) - val jsonSink: ConsoleSink = ConsoleSink.json(prettyPrint = true) - val logger = IzLogger(Trace, List(sink, jsonSink)) - val loggerTask: LogIO[Task] = LogIO.fromLogger[Task](logger) - - val o = B(A(123, "Hel\nlo"), b = true) - - override def run(args: List[String]): Task[ExitCode] = - init(scheduler) - .map(_ => ExitCode.Success) - .executeWithOptions(_.enableLocalContextPropagation) - - def init(implicit sch: Scheduler): Task[Unit] = - for { - result <- program(loggerTask) - } yield result - - def program(logger: LogIO[Task])(implicit sch: Scheduler): Task[Unit] = { - val logger_ = logger("yyy" -> A(567, "YYYYYYYYYYYY")) - val justAList = List[Any](10, "green", "bottles") - for { - _ <- logger_.info(s"Hello $o") - _ <- logger.info(s"Hello $o") - _ <- logger.info(s"Hello2 ${123} and $o") - _ <- logger.info(s"Argument: $justAList") - } yield () - } - -} From 161ccce6aed8fa8216cdde0cf086e4031e2940ad Mon Sep 17 00:00:00 2001 From: Ondra Pelech Date: Mon, 9 Dec 2019 15:00:43 +0100 Subject: [PATCH 14/35] Contexter --- .../src/main/scala/slf4cats/slf4cats.scala | 112 ++++++++++++------ 1 file changed, 74 insertions(+), 38 deletions(-) diff --git a/logback-mtl-builder/src/main/scala/slf4cats/slf4cats.scala b/logback-mtl-builder/src/main/scala/slf4cats/slf4cats.scala index 7972c4b..9f501c8 100644 --- a/logback-mtl-builder/src/main/scala/slf4cats/slf4cats.scala +++ b/logback-mtl-builder/src/main/scala/slf4cats/slf4cats.scala @@ -11,14 +11,16 @@ import org.slf4j.{LoggerFactory, Marker} import scala.language.higherKinds import scala.reflect.ClassTag -trait Logger[F[_]] { - def info: LoggerInfo[F] - def context[A](name: String, value: A)(implicit e: Encoder[A]): Logger[F] - def context[A](map: Map[String, A])(implicit e: Encoder[A]): Logger[F] +trait Contexter[F[_]] { + import Contexter._ + type Self <: Contexter[F] + def context[A](name: String, value: A)(implicit e: Encoder[A]): Self + def context[A](map: Map[String, A])(implicit e: Encoder[A]): Self def use[A](inner: F[A]): F[A] + def get: F[Context] } -object Logger { +object Contexter { class JsonInString private (private[slf4cats] val raw: String) extends AnyVal object JsonInString { @@ -32,28 +34,22 @@ object Logger { def empty: Context = Map.empty } - private class LoggerImpl[F[_]]( - underlying: org.slf4j.Logger, - context: Map[String, (Encoder[Any], Any)] - )(implicit FApplicativeLocal: ApplicativeLocal[F, Context], - val FSync: Sync[F]) - extends Logger[F] { - - override def info: LoggerInfo[F] = - new LoggerInfo[F](this, underlying, context) + private class ContexterImpl[F[_]](context: Map[String, (Encoder[Any], Any)])( + implicit FApplicativeLocal: ApplicativeLocal[F, Context], + val FSync: Sync[F] + ) extends Contexter[F] { + override type Self = Contexter[F] override def context[A](name: String, - value: A)(implicit e: Encoder[A]): Logger[F] = - new LoggerImpl[F]( - underlying, + value: A)(implicit e: Encoder[A]): Contexter[F] = + new ContexterImpl[F]( context + ((name, (e.asInstanceOf[Encoder[Any]], value))) ) override def context[A]( map: Map[String, A] - )(implicit e: Encoder[A]): Logger[F] = - new LoggerImpl[F]( - underlying, + )(implicit e: Encoder[A]): Contexter[F] = + new ContexterImpl[F]( context ++ map.mapValues((e.asInstanceOf[Encoder[Any]], _)) ) @@ -61,37 +57,77 @@ object Logger { FApplicativeLocal.local(_ ++ context.mapValues { case (e, v) => JsonInString.make(v)(e) })(inner) + + override def get: F[Context] = FApplicativeLocal.ask } - def make[F[_]](logger: org.slf4j.Logger)( - implicit FApplicativeLocal: ApplicativeLocal[F, Context], - FSync: Sync[F] + def make[F[_]](implicit FApplicativeLocal: ApplicativeLocal[F, Context], + FSync: Sync[F]): Contexter[F] = { + new ContexterImpl(Map()) + } + +} + +trait Logger[F[_]] extends Contexter[F] { + type Self <: Logger[F] + def info: LoggerInfo[F] +} + +object Logger { + + import Contexter._ + + private class LoggerImpl[F[_]]( + underlying: org.slf4j.Logger, + contexter: Contexter[F] + )(implicit FSync: Sync[F]) + extends Logger[F] { + + override type Self = Logger[F] + + override def info: LoggerInfo[F] = + new LoggerInfo[F](this, underlying, contexter) + + override def context[A](name: String, + value: A)(implicit e: Encoder[A]): Logger[F] = + new LoggerImpl[F](underlying, contexter.context(name, value)) + + override def context[A]( + map: Map[String, A] + )(implicit e: Encoder[A]): Logger[F] = + new LoggerImpl[F](underlying, contexter.context(map)) + + override def use[A](inner: F[A]): F[A] = contexter.use(inner) + + override def get: F[Context] = contexter.get + } + + def make[F[_]](logger: org.slf4j.Logger, contexter: Contexter[F])( + implicit FSync: Sync[F] ): Logger[F] = { - new LoggerImpl(logger, Map()) + new LoggerImpl(logger, contexter) } - def make[F[_]](name: String)( - implicit FApplicativeLocal: ApplicativeLocal[F, Context], - FSync: Sync[F] + def make[F[_]](name: String, contexter: Contexter[F])( + implicit FSync: Sync[F] ): Logger[F] = { - make(LoggerFactory.getLogger(name)) + make(LoggerFactory.getLogger(name), contexter) } - def make[F[_], T](implicit classTag: ClassTag[T], - FApplicativeLocal: ApplicativeLocal[F, Context], - FSync: Sync[F]): Logger[F] = { - make(LoggerFactory.getLogger(classTag.runtimeClass)) + def make[F[_], T](contexter: Contexter[F])(implicit classTag: ClassTag[T], + FSync: Sync[F]): Logger[F] = { + make(LoggerFactory.getLogger(classTag.runtimeClass), contexter) } } sealed class LoggerCommand[F[_]] private[slf4cats] ( logger: Logger[F], underlying: org.slf4j.Logger, - context: Map[String, (Encoder[Any], Any)] -)(implicit FApplicativeLocal: ApplicativeLocal[F, Logger.Context], + contexter: Contexter[F] +)(implicit FSync: Sync[F]) { - protected val marker: F[Marker] = FApplicativeLocal.ask.map { mdc => + protected val marker: F[Marker] = contexter.get.map { mdc => val markers = mdc.toList.map { case (k, v) => Markers.appendRaw(k, v.raw) @@ -130,10 +166,10 @@ object LoggerCommand { class LoggerInfo[F[_]] private[slf4cats] ( logger: Logger[F], underlying: org.slf4j.Logger, - context: Map[String, (Encoder[Any], Any)] -)(implicit FApplicativeLocal: ApplicativeLocal[F, Logger.Context], + contexter: Contexter[F] +)(implicit FSync: Sync[F]) - extends LoggerCommand(logger, underlying, context) { + extends LoggerCommand(logger, underlying, contexter) { import scala.language.experimental.macros def apply(message: String): F[Unit] = macro LoggerInfo.Macros.info[F] def apply(message: String, throwable: Throwable): F[Unit] = From 04638a11ad6dcee082fcf89b93382f62efdbfa10 Mon Sep 17 00:00:00 2001 From: Ondra Pelech Date: Tue, 10 Dec 2019 13:55:18 +0100 Subject: [PATCH 15/35] split Contexter and Logger --- .../loggingexperiment/logbackmtl/Main.scala | 20 +-- .../src/main/scala/slf4cats/slf4cats.scala | 147 +++++++++++++----- 2 files changed, 120 insertions(+), 47 deletions(-) diff --git a/logback-mtl-builder-app/src/main/scala/loggingexperiment/logbackmtl/Main.scala b/logback-mtl-builder-app/src/main/scala/loggingexperiment/logbackmtl/Main.scala index 67da8fc..aab262b 100644 --- a/logback-mtl-builder-app/src/main/scala/loggingexperiment/logbackmtl/Main.scala +++ b/logback-mtl-builder-app/src/main/scala/loggingexperiment/logbackmtl/Main.scala @@ -15,25 +15,25 @@ import scala.reflect.ClassTag object MonixLog { def make( logger: org.slf4j.Logger - )(taskLocalContext: TaskLocal[Logger.Context]): Logger[Task] = { + )(taskLocalContext: TaskLocal[Contexter.Context]): ContextLogger[Task] = { taskLocalContext.runLocal { implicit ev => - Logger.make(logger) + ContextLogger.make(logger) } } def make( name: String - )(taskLocalContext: TaskLocal[Logger.Context]): Logger[Task] = { + )(taskLocalContext: TaskLocal[Contexter.Context]): ContextLogger[Task] = { taskLocalContext.runLocal { implicit ev => - Logger.make(name) + ContextLogger.make(name) } } def make[T]( - taskLocalContext: TaskLocal[Logger.Context] - )(implicit classTag: ClassTag[T]): Logger[Task] = { + taskLocalContext: TaskLocal[Contexter.Context] + )(implicit classTag: ClassTag[T]): ContextLogger[Task] = { taskLocalContext.runLocal { implicit ev => - Logger.make + ContextLogger.make } } } @@ -53,12 +53,14 @@ object Main extends TaskApp { def init(implicit sch: Scheduler): Task[Unit] = for { - mdc <- TaskLocal(Logger.Context.empty) + mdc <- TaskLocal(Contexter.Context.empty) logger = MonixLog.make[Main.type](mdc) result <- program(logger) } yield result - def program(logger: Logger[Task])(implicit sch: Scheduler): Task[Unit] = { + def program( + logger: ContextLogger[Task] + )(implicit sch: Scheduler): Task[Unit] = { val ex = new InvalidParameterException("BOOOOOM") for { _ <- logger diff --git a/logback-mtl-builder/src/main/scala/slf4cats/slf4cats.scala b/logback-mtl-builder/src/main/scala/slf4cats/slf4cats.scala index 9f501c8..fc4c2a2 100644 --- a/logback-mtl-builder/src/main/scala/slf4cats/slf4cats.scala +++ b/logback-mtl-builder/src/main/scala/slf4cats/slf4cats.scala @@ -12,12 +12,10 @@ import scala.language.higherKinds import scala.reflect.ClassTag trait Contexter[F[_]] { - import Contexter._ type Self <: Contexter[F] def context[A](name: String, value: A)(implicit e: Encoder[A]): Self def context[A](map: Map[String, A])(implicit e: Encoder[A]): Self def use[A](inner: F[A]): F[A] - def get: F[Context] } object Contexter { @@ -36,7 +34,7 @@ object Contexter { private class ContexterImpl[F[_]](context: Map[String, (Encoder[Any], Any)])( implicit FApplicativeLocal: ApplicativeLocal[F, Context], - val FSync: Sync[F] + FSync: Sync[F] ) extends Contexter[F] { override type Self = Contexter[F] @@ -57,8 +55,6 @@ object Contexter { FApplicativeLocal.local(_ ++ context.mapValues { case (e, v) => JsonInString.make(v)(e) })(inner) - - override def get: F[Context] = FApplicativeLocal.ask } def make[F[_]](implicit FApplicativeLocal: ApplicativeLocal[F, Context], @@ -68,67 +64,81 @@ object Contexter { } -trait Logger[F[_]] extends Contexter[F] { +trait Logger[F[_]] { type Self <: Logger[F] + def context[A](name: String, value: A)(implicit e: Encoder[A]): Self + def context[A](map: Map[String, A])(implicit e: Encoder[A]): Self def info: LoggerInfo[F] } object Logger { - import Contexter._ - private class LoggerImpl[F[_]]( underlying: org.slf4j.Logger, - contexter: Contexter[F] - )(implicit FSync: Sync[F]) + context: Map[String, (Encoder[Any], Any)] + )(implicit FSync: Sync[F], + FApplicativeAsk: ApplicativeAsk[F, Contexter.Context]) extends Logger[F] { override type Self = Logger[F] override def info: LoggerInfo[F] = - new LoggerInfo[F](this, underlying, contexter) + new LoggerInfo[F](underlying, context) override def context[A](name: String, value: A)(implicit e: Encoder[A]): Logger[F] = - new LoggerImpl[F](underlying, contexter.context(name, value)) + new LoggerImpl[F]( + underlying, + context + ((name, (e.asInstanceOf[Encoder[Any]], value))) + ) override def context[A]( map: Map[String, A] )(implicit e: Encoder[A]): Logger[F] = - new LoggerImpl[F](underlying, contexter.context(map)) - - override def use[A](inner: F[A]): F[A] = contexter.use(inner) + new LoggerImpl[F]( + underlying, + context ++ map.mapValues(v => (e.asInstanceOf[Encoder[Any]], v)) + ) - override def get: F[Context] = contexter.get } - def make[F[_]](logger: org.slf4j.Logger, contexter: Contexter[F])( - implicit FSync: Sync[F] + def make[F[_]](logger: org.slf4j.Logger)( + implicit FSync: Sync[F], + FApplicativeAsk: ApplicativeAsk[F, Contexter.Context] ): Logger[F] = { - new LoggerImpl(logger, contexter) + new LoggerImpl(logger, Map.empty) } - def make[F[_]](name: String, contexter: Contexter[F])( - implicit FSync: Sync[F] + def make[F[_]](name: String)( + implicit FSync: Sync[F], + FApplicativeAsk: ApplicativeAsk[F, Contexter.Context] ): Logger[F] = { - make(LoggerFactory.getLogger(name), contexter) + make(LoggerFactory.getLogger(name)) } - def make[F[_], T](contexter: Contexter[F])(implicit classTag: ClassTag[T], - FSync: Sync[F]): Logger[F] = { - make(LoggerFactory.getLogger(classTag.runtimeClass), contexter) + def make[F[_], T](contexter: Contexter[F])( + implicit classTag: ClassTag[T], + FSync: Sync[F], + FApplicativeAsk: ApplicativeAsk[F, Contexter.Context] + ): Logger[F] = { + make(LoggerFactory.getLogger(classTag.runtimeClass)) } } sealed class LoggerCommand[F[_]] private[slf4cats] ( - logger: Logger[F], underlying: org.slf4j.Logger, - contexter: Contexter[F] + context: Map[String, (Encoder[Any], Any)] )(implicit - FSync: Sync[F]) { + FSync: Sync[F], + FApplicativeAsk: ApplicativeAsk[F, Contexter.Context]) { - protected val marker: F[Marker] = contexter.get.map { mdc => - val markers = mdc.toList.map { + import Contexter._ + + protected val marker: F[Marker] = FApplicativeAsk.ask.map { mdc => + val contextEncoded = context.mapValues { + case (e, v) => JsonInString.make(v)(e) + } + val markers = (mdc ++ contextEncoded).toList.map { case (k, v) => Markers.appendRaw(k, v.raw) } @@ -143,10 +153,8 @@ sealed class LoggerCommand[F[_]] private[slf4cats] ( val (isEnabled, body) = macroCallback(FSync, underlying) isEnabled.flatMap { isEnabled => if (isEnabled) { - logger.use { - marker.flatMap { marker => - body(marker) - } + marker.flatMap { marker => + body(marker) } } else { FSync.unit @@ -156,6 +164,69 @@ sealed class LoggerCommand[F[_]] private[slf4cats] ( } +trait ContextLogger[F[_]] extends Contexter[F] with Logger[F] { + type Self <: ContextLogger[F] +} + +object ContextLogger { + + import Contexter._ + + private class ContextLoggerImpl[F[_]]( + underlying: org.slf4j.Logger, + context: Map[String, (Encoder[Any], Any)] + )(implicit FApplicativeLocal: ApplicativeLocal[F, Context], FSync: Sync[F]) + extends ContextLogger[F] { + + override type Self = ContextLogger[F] + + override def info: LoggerInfo[F] = + new LoggerInfo[F](underlying, context) + + override def context[A](name: String, + value: A)(implicit e: Encoder[A]): Self = + new ContextLoggerImpl[F]( + underlying, + context + ((name, (e.asInstanceOf[Encoder[Any]], value))) + ) + + override def context[A](map: Map[String, A])(implicit e: Encoder[A]): Self = + new ContextLoggerImpl[F]( + underlying, + context ++ map.mapValues(v => (e.asInstanceOf[Encoder[Any]], v)) + ) + + override def use[A](inner: F[A]): F[A] = + FApplicativeLocal.local(_ ++ context.mapValues { + case (e, v) => JsonInString.make(v)(e) + })(inner) + + } + + def make[F[_]](logger: org.slf4j.Logger)( + implicit FSync: Sync[F], + FApplicativeLocal: ApplicativeLocal[F, Contexter.Context] + ): ContextLogger[F] = { + new ContextLoggerImpl[F](logger, Map.empty) + } + + def make[F[_]](name: String)( + implicit FSync: Sync[F], + FApplicativeAsk: ApplicativeLocal[F, Contexter.Context] + ): ContextLogger[F] = { + make(LoggerFactory.getLogger(name)) + } + + def make[F[_], T]( + implicit classTag: ClassTag[T], + FSync: Sync[F], + FApplicativeAsk: ApplicativeLocal[F, Contexter.Context] + ): ContextLogger[F] = { + make(LoggerFactory.getLogger(classTag.runtimeClass)) + } + +} + object LoggerCommand { private[slf4cats] object Macros { import scala.reflect.macros.blackbox @@ -164,12 +235,12 @@ object LoggerCommand { } class LoggerInfo[F[_]] private[slf4cats] ( - logger: Logger[F], underlying: org.slf4j.Logger, - contexter: Contexter[F] + context: Map[String, (Encoder[Any], Any)] )(implicit - FSync: Sync[F]) - extends LoggerCommand(logger, underlying, contexter) { + FSync: Sync[F], + FApplicativeAsk: ApplicativeAsk[F, Contexter.Context]) + extends LoggerCommand(underlying, context) { import scala.language.experimental.macros def apply(message: String): F[Unit] = macro LoggerInfo.Macros.info[F] def apply(message: String, throwable: Throwable): F[Unit] = From 1c7ca9f879baf86679245d0c2a540aeb8edbd122 Mon Sep 17 00:00:00 2001 From: Ondra Pelech Date: Wed, 11 Dec 2019 19:45:36 +0100 Subject: [PATCH 16/35] memoization --- .../loggingexperiment/logbackmtl/Main.scala | 34 ++- .../src/main/scala/slf4cats/slf4cats.scala | 247 +++++++++++------- project/plugins.sbt | 1 + 3 files changed, 169 insertions(+), 113 deletions(-) create mode 100644 project/plugins.sbt diff --git a/logback-mtl-builder-app/src/main/scala/loggingexperiment/logbackmtl/Main.scala b/logback-mtl-builder-app/src/main/scala/loggingexperiment/logbackmtl/Main.scala index aab262b..e68571a 100644 --- a/logback-mtl-builder-app/src/main/scala/loggingexperiment/logbackmtl/Main.scala +++ b/logback-mtl-builder-app/src/main/scala/loggingexperiment/logbackmtl/Main.scala @@ -6,31 +6,29 @@ import cats.effect._ import com.olegpy.meow.monix._ import io.circe.generic.auto._ import monix.eval._ -import monix.execution.Scheduler import slf4cats._ -import scala.language.higherKinds import scala.reflect.ClassTag object MonixLog { - def make( - logger: org.slf4j.Logger - )(taskLocalContext: TaskLocal[Contexter.Context]): ContextLogger[Task] = { + def make(logger: org.slf4j.Logger)( + taskLocalContext: TaskLocal[ContextManager.Context[Task]] + ): ContextLogger[Task] = { taskLocalContext.runLocal { implicit ev => ContextLogger.make(logger) } } - def make( - name: String - )(taskLocalContext: TaskLocal[Contexter.Context]): ContextLogger[Task] = { + def make(name: String)( + taskLocalContext: TaskLocal[ContextManager.Context[Task]] + ): ContextLogger[Task] = { taskLocalContext.runLocal { implicit ev => ContextLogger.make(name) } } def make[T]( - taskLocalContext: TaskLocal[Contexter.Context] + taskLocalContext: TaskLocal[ContextManager.Context[Task]] )(implicit classTag: ClassTag[T]): ContextLogger[Task] = { taskLocalContext.runLocal { implicit ev => ContextLogger.make @@ -47,29 +45,27 @@ object Main extends TaskApp { private val o = B(A(123, "Hello"), b = true) override def run(args: List[String]): Task[ExitCode] = - init(scheduler) + init .map(_ => ExitCode.Success) .executeWithOptions(_.enableLocalContextPropagation) - def init(implicit sch: Scheduler): Task[Unit] = + def init: Task[Unit] = for { - mdc <- TaskLocal(Contexter.Context.empty) + mdc <- TaskLocal(ContextManager.Context.empty[Task]) logger = MonixLog.make[Main.type](mdc) result <- program(logger) } yield result - def program( - logger: ContextLogger[Task] - )(implicit sch: Scheduler): Task[Unit] = { + def program(logger: ContextLogger[Task]): Task[Unit] = { val ex = new InvalidParameterException("BOOOOOM") for { _ <- logger - .context("a", A(1, "x")) - .context("o", o) + .withArg("a", A(1, "x")) + .withArg("o", o) .info("Hello Monix") _ <- logger.info("Hello MTL", ex) - _ <- logger.context("x", 123).context("o", o).use { - logger.context("x", 9).info("Hello2 meow") + _ <- logger.withArg("x", 123).withArg("o", o).use { + logger.withArg("x", 9).info("Hello2 meow") } } yield () } diff --git a/logback-mtl-builder/src/main/scala/slf4cats/slf4cats.scala b/logback-mtl-builder/src/main/scala/slf4cats/slf4cats.scala index fc4c2a2..799b26f 100644 --- a/logback-mtl-builder/src/main/scala/slf4cats/slf4cats.scala +++ b/logback-mtl-builder/src/main/scala/slf4cats/slf4cats.scala @@ -1,73 +1,105 @@ package slf4cats +import cats._ import cats.effect._ import cats.implicits._ import cats.mtl._ import io.circe.Encoder -import io.circe.generic.auto._ import net.logstash.logback.marker.Markers import org.slf4j.{LoggerFactory, Marker} import scala.language.higherKinds import scala.reflect.ClassTag -trait Contexter[F[_]] { - type Self <: Contexter[F] - def context[A](name: String, value: A)(implicit e: Encoder[A]): Self - def context[A](map: Map[String, A])(implicit e: Encoder[A]): Self +trait ContextManager[F[_]] { + type Self <: ContextManager[F] + def withArg[A](name: String, value: => A)(implicit e: Encoder[A]): Self + def withComputed[A](name: String, value: F[A])(implicit e: Encoder[A]): Self + def withArgs[A](map: Map[String, A])(implicit e: Encoder[A]): Self def use[A](inner: F[A]): F[A] } -object Contexter { +object ContextManager { - class JsonInString private (private[slf4cats] val raw: String) extends AnyVal - object JsonInString { + private[slf4cats] class JsonInString private ( + private[slf4cats] val raw: String + ) extends AnyVal + + private[slf4cats] object JsonInString { def make[A](x: A)(implicit e: Encoder[A]): JsonInString = { new JsonInString(e(x).spaces2) } } - type Context = Map[String, JsonInString] + type Context[F[_]] = Map[String, F[JsonInString]] object Context { - def empty: Context = Map.empty + def empty[F[_]]: Context[F] = Map.empty } - private class ContexterImpl[F[_]](context: Map[String, (Encoder[Any], Any)])( - implicit FApplicativeLocal: ApplicativeLocal[F, Context], - FSync: Sync[F] - ) extends Contexter[F] { - override type Self = Contexter[F] - - override def context[A](name: String, - value: A)(implicit e: Encoder[A]): Contexter[F] = - new ContexterImpl[F]( - context + ((name, (e.asInstanceOf[Encoder[Any]], value))) - ) + private class ContextManagerImpl[F[_]]( + tmpContext: Map[String, F[F[JsonInString]]] + )(implicit FApplicativeLocal: ApplicativeLocal[F, Context[F]], + FAsync: Async[F]) + extends ContextManager[F] { + + override type Self = ContextManager[F] + + override def withArg[A](name: String, value: => A)( + implicit e: Encoder[A] + ): ContextManager[F] = + withComputed(name, FAsync.delay { + value + }) + + override def withComputed[A](name: String, value: F[A])( + implicit e: Encoder[A] + ): ContextManager[F] = { + val memoizedJson = Async.memoize(value.map(JsonInString.make(_))) + new ContextManagerImpl[F](tmpContext + ((name, memoizedJson))) + } - override def context[A]( + override def withArgs[A]( map: Map[String, A] - )(implicit e: Encoder[A]): Contexter[F] = - new ContexterImpl[F]( - context ++ map.mapValues((e.asInstanceOf[Encoder[Any]], _)) + )(implicit e: Encoder[A]): ContextManager[F] = + new ContextManagerImpl[F]( + tmpContext ++ map + .mapValues(v => FAsync.pure(FAsync.delay { JsonInString.make(v) })) ) - override def use[A](inner: F[A]): F[A] = - FApplicativeLocal.local(_ ++ context.mapValues { - case (e, v) => JsonInString.make(v)(e) - })(inner) + override def use[A](inner: F[A]): F[A] = { + val contextMemoized = tmpContext.toList + .traverse(p => p._2.map((p._1, _))) + .map(_.toMap) + contextMemoized.flatMap { contextMemoized => + FApplicativeLocal.local(_ ++ contextMemoized)(inner) + } + } + } + + private[slf4cats] def mapSequence[F[_], K, V]( + m: Map[K, F[V]] + )(implicit FApplicative: Applicative[F]): F[Map[K, V]] = { + m.foldLeft(FApplicative.pure(Map.empty[K, V])) { + case (m, (k, fv)) => + FApplicative.tuple2(m, fv).map { + case (m, v) => + m + ((k, v)) + } + } } - def make[F[_]](implicit FApplicativeLocal: ApplicativeLocal[F, Context], - FSync: Sync[F]): Contexter[F] = { - new ContexterImpl(Map()) + def make[F[_]](implicit FApplicativeLocal: ApplicativeLocal[F, Context[F]], + FAsync: Async[F]): ContextManager[F] = { + new ContextManagerImpl(Map()) } } trait Logger[F[_]] { type Self <: Logger[F] - def context[A](name: String, value: A)(implicit e: Encoder[A]): Self - def context[A](map: Map[String, A])(implicit e: Encoder[A]): Self + def withArg[A](name: String, value: => A)(implicit e: Encoder[A]): Self + def withComputed[A](name: String, value: F[A])(implicit e: Encoder[A]): Self + def withArgs[A](map: Map[String, A])(implicit e: Encoder[A]): Self def info: LoggerInfo[F] } @@ -75,82 +107,89 @@ object Logger { private class LoggerImpl[F[_]]( underlying: org.slf4j.Logger, - context: Map[String, (Encoder[Any], Any)] + context: ContextManager.Context[F] )(implicit FSync: Sync[F], - FApplicativeAsk: ApplicativeAsk[F, Contexter.Context]) + FApplicativeAsk: ApplicativeAsk[F, ContextManager.Context[F]]) extends Logger[F] { override type Self = Logger[F] override def info: LoggerInfo[F] = - new LoggerInfo[F](underlying, context) + new LoggerInfo[F](underlying, context.mapValues(FSync.pure)) - override def context[A](name: String, - value: A)(implicit e: Encoder[A]): Logger[F] = - new LoggerImpl[F]( - underlying, - context + ((name, (e.asInstanceOf[Encoder[Any]], value))) - ) + override def withArg[A](name: String, value: => A)( + implicit e: Encoder[A] + ): Logger[F] = withComputed(name, FSync.delay { value }) + + override def withComputed[A](name: String, value: F[A])( + implicit e: Encoder[A] + ): Logger[F] = { + val json = value.map(ContextManager.JsonInString.make(_)) + new LoggerImpl[F](underlying, context + ((name, json))) + } - override def context[A]( + override def withArgs[A]( map: Map[String, A] )(implicit e: Encoder[A]): Logger[F] = new LoggerImpl[F]( underlying, - context ++ map.mapValues(v => (e.asInstanceOf[Encoder[Any]], v)) + context ++ map + .mapValues(v => FSync.delay { ContextManager.JsonInString.make(v) }) ) } def make[F[_]](logger: org.slf4j.Logger)( - implicit FSync: Sync[F], - FApplicativeAsk: ApplicativeAsk[F, Contexter.Context] + implicit FAsync: Async[F], + FApplicativeAsk: ApplicativeAsk[F, ContextManager.Context[F]] ): Logger[F] = { new LoggerImpl(logger, Map.empty) } def make[F[_]](name: String)( - implicit FSync: Sync[F], - FApplicativeAsk: ApplicativeAsk[F, Contexter.Context] + implicit FAsync: Async[F], + FApplicativeAsk: ApplicativeAsk[F, ContextManager.Context[F]] ): Logger[F] = { make(LoggerFactory.getLogger(name)) } - def make[F[_], T](contexter: Contexter[F])( + def make[F[_], T]( implicit classTag: ClassTag[T], - FSync: Sync[F], - FApplicativeAsk: ApplicativeAsk[F, Contexter.Context] + FAsync: Async[F], + FApplicativeAsk: ApplicativeAsk[F, ContextManager.Context[F]] ): Logger[F] = { make(LoggerFactory.getLogger(classTag.runtimeClass)) } } -sealed class LoggerCommand[F[_]] private[slf4cats] ( +sealed abstract class LoggerCommand[F[_]] private[slf4cats] ( underlying: org.slf4j.Logger, - context: Map[String, (Encoder[Any], Any)] + tmpContext: Map[String, F[F[ContextManager.JsonInString]]] )(implicit FSync: Sync[F], - FApplicativeAsk: ApplicativeAsk[F, Contexter.Context]) { + FApplicativeAsk: ApplicativeAsk[F, ContextManager.Context[F]]) { - import Contexter._ + import ContextManager._ - protected val marker: F[Marker] = FApplicativeAsk.ask.map { mdc => - val contextEncoded = context.mapValues { - case (e, v) => JsonInString.make(v)(e) - } - val markers = (mdc ++ contextEncoded).toList.map { + protected val marker: F[Marker] = for { + context1 <- FApplicativeAsk.ask + context2 <- mapSequence(tmpContext) + union <- mapSequence(context1 ++ context2) + markers = union.toList.map { case (k, v) => Markers.appendRaw(k, v.raw) } - Markers.aggregate(markers: _*) - } + result = Markers.aggregate(markers: _*) + } yield result + + protected def isEnabled + : F[Boolean] // could be made public if there's interest /** only to be used used by macro */ def withUnderlying( - macroCallback: (Sync[F], org.slf4j.Logger) => (F[Boolean], - Marker => F[Unit]) + macroCallback: (Sync[F], org.slf4j.Logger) => (Marker => F[Unit]) ): F[Unit] = { - val (isEnabled, body) = macroCallback(FSync, underlying) + val body = macroCallback(FSync, underlying) isEnabled.flatMap { isEnabled => if (isEnabled) { marker.flatMap { marker => @@ -164,18 +203,19 @@ sealed class LoggerCommand[F[_]] private[slf4cats] ( } -trait ContextLogger[F[_]] extends Contexter[F] with Logger[F] { +trait ContextLogger[F[_]] extends ContextManager[F] with Logger[F] { type Self <: ContextLogger[F] } object ContextLogger { - import Contexter._ + import ContextManager._ private class ContextLoggerImpl[F[_]]( underlying: org.slf4j.Logger, - context: Map[String, (Encoder[Any], Any)] - )(implicit FApplicativeLocal: ApplicativeLocal[F, Context], FSync: Sync[F]) + context: Map[String, F[F[JsonInString]]] + )(implicit FApplicativeLocal: ApplicativeLocal[F, Context[F]], + FAsync: Async[F]) extends ContextLogger[F] { override type Self = ContextLogger[F] @@ -183,44 +223,57 @@ object ContextLogger { override def info: LoggerInfo[F] = new LoggerInfo[F](underlying, context) - override def context[A](name: String, - value: A)(implicit e: Encoder[A]): Self = - new ContextLoggerImpl[F]( - underlying, - context + ((name, (e.asInstanceOf[Encoder[Any]], value))) - ) + override def withArg[A](name: String, value: => A)( + implicit e: Encoder[A] + ): ContextLogger[F] = + withComputed(name, FAsync.delay { + value + }) + + override def withComputed[A](name: String, value: F[A])( + implicit e: Encoder[A] + ): ContextLogger[F] = { + val memoizedJson = Async.memoize(value.map(JsonInString.make(_))) + new ContextLoggerImpl[F](underlying, context + ((name, memoizedJson))) + } - override def context[A](map: Map[String, A])(implicit e: Encoder[A]): Self = + override def withArgs[A]( + map: Map[String, A] + )(implicit e: Encoder[A]): ContextLogger[F] = new ContextLoggerImpl[F]( underlying, - context ++ map.mapValues(v => (e.asInstanceOf[Encoder[Any]], v)) + context ++ map + .mapValues( + v => + FAsync.pure(FAsync.delay { ContextManager.JsonInString.make(v) }) + ) ) - override def use[A](inner: F[A]): F[A] = - FApplicativeLocal.local(_ ++ context.mapValues { - case (e, v) => JsonInString.make(v)(e) - })(inner) - + override def use[A](inner: F[A]): F[A] = { + mapSequence(context).flatMap { contextMemoized => + FApplicativeLocal.local(_ ++ contextMemoized)(inner) + } + } } def make[F[_]](logger: org.slf4j.Logger)( - implicit FSync: Sync[F], - FApplicativeLocal: ApplicativeLocal[F, Contexter.Context] + implicit FAsync: Async[F], + FApplicativeLocal: ApplicativeLocal[F, ContextManager.Context[F]] ): ContextLogger[F] = { new ContextLoggerImpl[F](logger, Map.empty) } def make[F[_]](name: String)( - implicit FSync: Sync[F], - FApplicativeAsk: ApplicativeLocal[F, Contexter.Context] + implicit FAsync: Async[F], + FApplicativeAsk: ApplicativeLocal[F, ContextManager.Context[F]] ): ContextLogger[F] = { make(LoggerFactory.getLogger(name)) } def make[F[_], T]( implicit classTag: ClassTag[T], - FSync: Sync[F], - FApplicativeAsk: ApplicativeLocal[F, Contexter.Context] + FAsync: Async[F], + FApplicativeAsk: ApplicativeLocal[F, ContextManager.Context[F]] ): ContextLogger[F] = { make(LoggerFactory.getLogger(classTag.runtimeClass)) } @@ -236,12 +289,18 @@ object LoggerCommand { class LoggerInfo[F[_]] private[slf4cats] ( underlying: org.slf4j.Logger, - context: Map[String, (Encoder[Any], Any)] + tmpContext: Map[String, F[F[ContextManager.JsonInString]]] )(implicit FSync: Sync[F], - FApplicativeAsk: ApplicativeAsk[F, Contexter.Context]) - extends LoggerCommand(underlying, context) { + FApplicativeAsk: ApplicativeAsk[F, ContextManager.Context[F]]) + extends LoggerCommand(underlying, tmpContext) { + import scala.language.experimental.macros + + override protected val isEnabled: F[Boolean] = FSync.delay { + underlying.isInfoEnabled + } + def apply(message: String): F[Unit] = macro LoggerInfo.Macros.info[F] def apply(message: String, throwable: Throwable): F[Unit] = macro LoggerInfo.Macros.infoThrowable[F] @@ -255,7 +314,7 @@ object LoggerInfo { def info[F[_]](c: Context[F])(message: c.Expr[String]): c.Expr[F[Unit]] = { import c.universe._ val tree = - q"${c.prefix}.withUnderlying { case (fsync, underlying) => (fsync.delay { underlying.isInfoEnabled }, marker => fsync.delay { underlying.info(marker, $message) }) }" + q"${c.prefix}.withUnderlying { case (fsync, underlying) => (marker => fsync.delay { underlying.info(marker, $message) }) }" c.Expr[F[Unit]](tree) } @@ -265,7 +324,7 @@ object LoggerInfo { ): c.Expr[F[Unit]] = { import c.universe._ val tree = - q"${c.prefix}.withUnderlying { case (fsync, underlying) => (fsync.delay { underlying.isInfoEnabled }, marker => fsync.delay { underlying.info(marker, $message, $throwable) }) }" + q"${c.prefix}.withUnderlying { case (fsync, underlying) => (marker => fsync.delay { underlying.info(marker, $message, $throwable) }) }" c.Expr[F[Unit]](tree) } } diff --git a/project/plugins.sbt b/project/plugins.sbt new file mode 100644 index 0000000..8a37c46 --- /dev/null +++ b/project/plugins.sbt @@ -0,0 +1 @@ +addSbtPlugin("io.github.davidgregory084" % "sbt-tpolecat" % "0.1.10") From a9c69594b8b84db4a168e372c8f622f7eaca314a Mon Sep 17 00:00:00 2001 From: Ondra Pelech Date: Wed, 11 Dec 2019 19:55:59 +0100 Subject: [PATCH 17/35] update README --- README.md | 54 ++++++++++++++++++++++++++++-------------------------- 1 file changed, 28 insertions(+), 26 deletions(-) diff --git a/README.md b/README.md index aa4d50f..fa90f6f 100644 --- a/README.md +++ b/README.md @@ -32,15 +32,17 @@ This repo contains experiments with possible implementations of structured loggi ## Interface ```scala -trait Logger[F[_]] { +trait ContextLogger[F[_]] { + type Self <: ContextLogger[F] + def withArg[A](name: String, value: => A)(implicit e: Encoder[A]): Self + def withComputed[A](name: String, value: F[A])(implicit e: Encoder[A]): Self + def withArgs[A](map: Map[String, A])(implicit e: Encoder[A]): Self + def use[A](inner: F[A]): F[A] // excerpt for `info` logging def info: LoggerInfo[F] //... - def context[A](name: String, value: A)(implicit e: Encoder[A]): Logger[F] - def context[A](map: Map[String, A])(implicit e: Encoder[A]): Logger[F] - def use[A](inner: F[A]): F[A] } -class LoggerInfo[F[_]] (...) { +class LoggerInfo[F[_]] (???) { def apply(message: String): F[Unit] = macro ??? def apply(message: String, throwable: Throwable): F[Unit] = macro ??? } @@ -49,16 +51,16 @@ class LoggerInfo[F[_]] (...) { ## Usage ```scala -def program(logger: Logger[Task])(implicit sch: Scheduler): Task[Unit] = { +def program(logger: ContextLogger[Task]): Task[Unit] = { val ex = new InvalidParameterException("BOOOOOM") for { _ <- logger - .context("a", A(1, "x")) - .context("o", o) + .withArg("a", A(1, "x")) + .withArg("o", o) .info("Hello Monix") _ <- logger.info("Hello MTL", ex) - _ <- logger.context("x", 123).context("o", o).use { - logger.context("x", 9).info("Hello2 meow") + _ <- logger.withArg("x", 123).withArg("o", o).use { + logger.withArg("x", 9).info("Hello2 meow") } } yield () } @@ -67,17 +69,17 @@ def program(logger: Logger[Task])(implicit sch: Scheduler): Task[Unit] = { ### Multiple contexts ```scala _ <- logger - .context("a", A(1, "x")) - .context("o", o) + .withArg("a", A(1, "x")) + .withArg("o", o) .info("Hello Monix") ``` ```json { - "@timestamp": "2019-12-06T23:20:55.237+01:00", + "@timestamp": "2019-12-11T19:52:54.619+01:00", "@version": "1", "message": "Hello Monix", "logger_name": "loggingexperiment.logbackmtl.Main$", - "thread_name": "scala-execution-context-global-11", + "thread_name": "scala-execution-context-global-13", "level": "INFO", "level_value": 20000, "a": { @@ -93,9 +95,9 @@ _ <- logger }, "application": "loggingexperiment", "caller_class_name": "loggingexperiment.logbackmtl.Main$", - "caller_method_name": "$anonfun$program$6", + "caller_method_name": "$anonfun$program$7", "caller_file_name": "Main.scala", - "caller_line_number": 66 + "caller_line_number": 65 } ``` @@ -105,35 +107,35 @@ _ <- logger.info("Hello MTL", ex) ``` ```json { - "@timestamp": "2019-12-06T23:20:55.254+01:00", + "@timestamp": "2019-12-11T19:52:54.631+01:00", "@version": "1", "message": "Hello MTL", "logger_name": "loggingexperiment.logbackmtl.Main$", - "thread_name": "scala-execution-context-global-11", + "thread_name": "scala-execution-context-global-13", "level": "INFO", "level_value": 20000, - "stack_trace": "java.security.InvalidParameterException: BOOOOOM\n\tat loggingexperiment.logbackmtl.Main$.program(Main.scala:61)\n...", + "stack_trace": "java.security.InvalidParameterException: BOOOOOM\n\tat loggingexperiment.logbackmtl.Main$.program(Main.scala:60)\n...", "application": "loggingexperiment", "caller_class_name": "loggingexperiment.logbackmtl.Main$", "caller_method_name": "$anonfun$program$11", "caller_file_name": "Main.scala", - "caller_line_number": 67 + "caller_line_number": 66 } ``` ### Context overriding ```scala -_ <- logger.context("x", 123).context("o", o).use { - logger.context("x", 9).info("Hello2 meow") +_ <- logger.withArg("x", 123).withArg("o", o).use { + logger.withArg("x", 9).info("Hello2 meow") } ``` ```json { - "@timestamp": "2019-12-06T23:20:55.263+01:00", + "@timestamp": "2019-12-11T19:52:54.645+01:00", "@version": "1", "message": "Hello2 meow", "logger_name": "loggingexperiment.logbackmtl.Main$", - "thread_name": "scala-execution-context-global-11", + "thread_name": "scala-execution-context-global-13", "level": "INFO", "level_value": 20000, "x": 9, @@ -146,8 +148,8 @@ _ <- logger.context("x", 123).context("o", o).use { }, "application": "loggingexperiment", "caller_class_name": "loggingexperiment.logbackmtl.Main$", - "caller_method_name": "$anonfun$program$17", + "caller_method_name": "$anonfun$program$19", "caller_file_name": "Main.scala", - "caller_line_number": 69 + "caller_line_number": 68 } ``` From 072fa6ac90c30614910fa47a2e0d68439dff373c Mon Sep 17 00:00:00 2001 From: Ondra Pelech Date: Thu, 12 Dec 2019 13:01:39 +0100 Subject: [PATCH 18/35] tmpContext -> localContext, use Async.memoize where appropriate (instead of Async.pure) --- .../src/main/scala/slf4cats/slf4cats.scala | 29 +++++++++---------- 1 file changed, 14 insertions(+), 15 deletions(-) diff --git a/logback-mtl-builder/src/main/scala/slf4cats/slf4cats.scala b/logback-mtl-builder/src/main/scala/slf4cats/slf4cats.scala index 799b26f..02e87c5 100644 --- a/logback-mtl-builder/src/main/scala/slf4cats/slf4cats.scala +++ b/logback-mtl-builder/src/main/scala/slf4cats/slf4cats.scala @@ -37,7 +37,7 @@ object ContextManager { } private class ContextManagerImpl[F[_]]( - tmpContext: Map[String, F[F[JsonInString]]] + localContext: Map[String, F[F[JsonInString]]] )(implicit FApplicativeLocal: ApplicativeLocal[F, Context[F]], FAsync: Async[F]) extends ContextManager[F] { @@ -55,22 +55,19 @@ object ContextManager { implicit e: Encoder[A] ): ContextManager[F] = { val memoizedJson = Async.memoize(value.map(JsonInString.make(_))) - new ContextManagerImpl[F](tmpContext + ((name, memoizedJson))) + new ContextManagerImpl[F](localContext + ((name, memoizedJson))) } override def withArgs[A]( map: Map[String, A] )(implicit e: Encoder[A]): ContextManager[F] = new ContextManagerImpl[F]( - tmpContext ++ map - .mapValues(v => FAsync.pure(FAsync.delay { JsonInString.make(v) })) + localContext ++ map + .mapValues(v => Async.memoize(FAsync.delay { JsonInString.make(v) })) ) override def use[A](inner: F[A]): F[A] = { - val contextMemoized = tmpContext.toList - .traverse(p => p._2.map((p._1, _))) - .map(_.toMap) - contextMemoized.flatMap { contextMemoized => + mapSequence(localContext).flatMap { contextMemoized => FApplicativeLocal.local(_ ++ contextMemoized)(inner) } } @@ -107,7 +104,7 @@ object Logger { private class LoggerImpl[F[_]]( underlying: org.slf4j.Logger, - context: ContextManager.Context[F] + localContext: ContextManager.Context[F] )(implicit FSync: Sync[F], FApplicativeAsk: ApplicativeAsk[F, ContextManager.Context[F]]) extends Logger[F] { @@ -115,7 +112,7 @@ object Logger { override type Self = Logger[F] override def info: LoggerInfo[F] = - new LoggerInfo[F](underlying, context.mapValues(FSync.pure)) + new LoggerInfo[F](underlying, localContext.mapValues(FSync.pure)) override def withArg[A](name: String, value: => A)( implicit e: Encoder[A] @@ -125,7 +122,7 @@ object Logger { implicit e: Encoder[A] ): Logger[F] = { val json = value.map(ContextManager.JsonInString.make(_)) - new LoggerImpl[F](underlying, context + ((name, json))) + new LoggerImpl[F](underlying, localContext + ((name, json))) } override def withArgs[A]( @@ -133,7 +130,7 @@ object Logger { )(implicit e: Encoder[A]): Logger[F] = new LoggerImpl[F]( underlying, - context ++ map + localContext ++ map .mapValues(v => FSync.delay { ContextManager.JsonInString.make(v) }) ) @@ -164,7 +161,7 @@ object Logger { sealed abstract class LoggerCommand[F[_]] private[slf4cats] ( underlying: org.slf4j.Logger, - tmpContext: Map[String, F[F[ContextManager.JsonInString]]] + localContext: Map[String, F[F[ContextManager.JsonInString]]] )(implicit FSync: Sync[F], FApplicativeAsk: ApplicativeAsk[F, ContextManager.Context[F]]) { @@ -173,7 +170,7 @@ sealed abstract class LoggerCommand[F[_]] private[slf4cats] ( protected val marker: F[Marker] = for { context1 <- FApplicativeAsk.ask - context2 <- mapSequence(tmpContext) + context2 <- mapSequence(localContext) union <- mapSequence(context1 ++ context2) markers = union.toList.map { case (k, v) => @@ -245,7 +242,9 @@ object ContextLogger { context ++ map .mapValues( v => - FAsync.pure(FAsync.delay { ContextManager.JsonInString.make(v) }) + Async.memoize( + FAsync.delay { ContextManager.JsonInString.make(v) } + ) ) ) From 15434dbeaeab8e99f9dc29eb4933ba4abaf92706 Mon Sep 17 00:00:00 2001 From: Ondra Pelech Date: Tue, 17 Dec 2019 23:54:38 +0100 Subject: [PATCH 19/35] JSON keys README --- README.md | 9 +++------ 1 file changed, 3 insertions(+), 6 deletions(-) diff --git a/README.md b/README.md index fa90f6f..06f57e5 100644 --- a/README.md +++ b/README.md @@ -18,16 +18,13 @@ This repo contains experiments with possible implementations of structured loggi * line number * loglevel as both string and number * ... to be specified - * JSON keys, possibilities: - * always as free-form strings -- simplest solution - * library of standardized JSON keys - * JSON keys via extendable type - * JSON keys via typeclass + * JSON keys will be just strings, at lest for the beginning ## Implementation considerations * use Circe for the encoding - * mimic `slf4j`'s `Logger` API + * mimic `slf4j`'s `Logger` API/capabilities + * always as free-form strings -- simplest solution ## Interface From 70598eac5cb5a7ec9aaeb9a7950031aac9ffe258 Mon Sep 17 00:00:00 2001 From: Ondra Pelech Date: Wed, 18 Dec 2019 00:58:19 +0100 Subject: [PATCH 20/35] extract common macro part --- .../src/main/scala/slf4cats/slf4cats.scala | 40 ++++++++++++------- 1 file changed, 25 insertions(+), 15 deletions(-) diff --git a/logback-mtl-builder/src/main/scala/slf4cats/slf4cats.scala b/logback-mtl-builder/src/main/scala/slf4cats/slf4cats.scala index 02e87c5..a20e8f0 100644 --- a/logback-mtl-builder/src/main/scala/slf4cats/slf4cats.scala +++ b/logback-mtl-builder/src/main/scala/slf4cats/slf4cats.scala @@ -283,6 +283,25 @@ object LoggerCommand { private[slf4cats] object Macros { import scala.reflect.macros.blackbox type Context[F[_]] = blackbox.Context { type PrefixType = LoggerCommand[F] } + + def log[F[_]](c: Context[F])(level: c.TermName, + message: c.Expr[String]): c.Expr[F[Unit]] = { + import c.universe._ + val tree = + q"${c.prefix}.withUnderlying { case (fsync, underlying) => (marker => fsync.delay { underlying.$level(marker, $message) }) }" + c.Expr[F[Unit]](tree) + } + + def logThrowable[F[_]](c: Context[F])( + level: c.TermName, + message: c.Expr[String], + throwable: c.Expr[Throwable] + ): c.Expr[F[Unit]] = { + import c.universe._ + val tree = + q"${c.prefix}.withUnderlying { case (fsync, underlying) => (marker => fsync.delay { underlying.$level(marker, $message, $throwable) }) }" + c.Expr[F[Unit]](tree) + } } } @@ -310,22 +329,13 @@ object LoggerInfo { private[LoggerInfo] object Macros { import LoggerCommand.Macros._ - def info[F[_]](c: Context[F])(message: c.Expr[String]): c.Expr[F[Unit]] = { - import c.universe._ - val tree = - q"${c.prefix}.withUnderlying { case (fsync, underlying) => (marker => fsync.delay { underlying.info(marker, $message) }) }" - c.Expr[F[Unit]](tree) - } + def info[F[_]](c: Context[F])(message: c.Expr[String]): c.Expr[F[Unit]] = + log(c)(c.universe.TermName("info"), message) - def infoThrowable[F[_]](c: Context[F])( - message: c.Expr[String], - throwable: c.Expr[Throwable] - ): c.Expr[F[Unit]] = { - import c.universe._ - val tree = - q"${c.prefix}.withUnderlying { case (fsync, underlying) => (marker => fsync.delay { underlying.info(marker, $message, $throwable) }) }" - c.Expr[F[Unit]](tree) - } + def infoThrowable[F[_]]( + c: Context[F] + )(message: c.Expr[String], throwable: c.Expr[Throwable]): c.Expr[F[Unit]] = + logThrowable(c)(c.universe.TermName("info"), message, throwable) } } From 8f1cccb00fa241ed617ede7a6f44239ce0a06873 Mon Sep 17 00:00:00 2001 From: Ondra Pelech Date: Wed, 18 Dec 2019 00:37:11 +0100 Subject: [PATCH 21/35] use Jackson --- .../loggingexperiment/logbackmtl/Main.scala | 1 - .../src/main/scala/slf4cats/slf4cats.scala | 69 ++++++++----------- 2 files changed, 30 insertions(+), 40 deletions(-) diff --git a/logback-mtl-builder-app/src/main/scala/loggingexperiment/logbackmtl/Main.scala b/logback-mtl-builder-app/src/main/scala/loggingexperiment/logbackmtl/Main.scala index e68571a..e00f19d 100644 --- a/logback-mtl-builder-app/src/main/scala/loggingexperiment/logbackmtl/Main.scala +++ b/logback-mtl-builder-app/src/main/scala/loggingexperiment/logbackmtl/Main.scala @@ -4,7 +4,6 @@ import java.security.InvalidParameterException import cats.effect._ import com.olegpy.meow.monix._ -import io.circe.generic.auto._ import monix.eval._ import slf4cats._ diff --git a/logback-mtl-builder/src/main/scala/slf4cats/slf4cats.scala b/logback-mtl-builder/src/main/scala/slf4cats/slf4cats.scala index a20e8f0..1201ad9 100644 --- a/logback-mtl-builder/src/main/scala/slf4cats/slf4cats.scala +++ b/logback-mtl-builder/src/main/scala/slf4cats/slf4cats.scala @@ -4,7 +4,9 @@ import cats._ import cats.effect._ import cats.implicits._ import cats.mtl._ -import io.circe.Encoder +import com.fasterxml.jackson.annotation.JsonAutoDetect.Visibility +import com.fasterxml.jackson.annotation.PropertyAccessor +import com.fasterxml.jackson.databind.ObjectMapper import net.logstash.logback.marker.Markers import org.slf4j.{LoggerFactory, Marker} @@ -13,9 +15,9 @@ import scala.reflect.ClassTag trait ContextManager[F[_]] { type Self <: ContextManager[F] - def withArg[A](name: String, value: => A)(implicit e: Encoder[A]): Self - def withComputed[A](name: String, value: F[A])(implicit e: Encoder[A]): Self - def withArgs[A](map: Map[String, A])(implicit e: Encoder[A]): Self + def withArg(name: String, value: => Any): Self + def withComputed(name: String, value: F[Any]): Self + def withArgs(map: Map[String, Any]): Self def use[A](inner: F[A]): F[A] } @@ -26,8 +28,13 @@ object ContextManager { ) extends AnyVal private[slf4cats] object JsonInString { - def make[A](x: A)(implicit e: Encoder[A]): JsonInString = { - new JsonInString(e(x).spaces2) + + private val jackson = new ObjectMapper() + jackson.setVisibility(PropertyAccessor.ALL, Visibility.NONE) + jackson.setVisibility(PropertyAccessor.FIELD, Visibility.ANY) + + def make(x: Any): JsonInString = { + new JsonInString(jackson.writeValueAsString(x)) } } @@ -44,23 +51,18 @@ object ContextManager { override type Self = ContextManager[F] - override def withArg[A](name: String, value: => A)( - implicit e: Encoder[A] - ): ContextManager[F] = + override def withArg(name: String, value: => Any): ContextManager[F] = withComputed(name, FAsync.delay { value }) - override def withComputed[A](name: String, value: F[A])( - implicit e: Encoder[A] - ): ContextManager[F] = { - val memoizedJson = Async.memoize(value.map(JsonInString.make(_))) + override def withComputed(name: String, + value: F[Any]): ContextManager[F] = { + val memoizedJson = Async.memoize(value.map(JsonInString.make)) new ContextManagerImpl[F](localContext + ((name, memoizedJson))) } - override def withArgs[A]( - map: Map[String, A] - )(implicit e: Encoder[A]): ContextManager[F] = + override def withArgs(map: Map[String, Any]): ContextManager[F] = new ContextManagerImpl[F]( localContext ++ map .mapValues(v => Async.memoize(FAsync.delay { JsonInString.make(v) })) @@ -94,9 +96,9 @@ object ContextManager { trait Logger[F[_]] { type Self <: Logger[F] - def withArg[A](name: String, value: => A)(implicit e: Encoder[A]): Self - def withComputed[A](name: String, value: F[A])(implicit e: Encoder[A]): Self - def withArgs[A](map: Map[String, A])(implicit e: Encoder[A]): Self + def withArg(name: String, value: => Any): Self + def withComputed(name: String, value: F[Any]): Self + def withArgs(map: Map[String, Any]): Self def info: LoggerInfo[F] } @@ -114,20 +116,15 @@ object Logger { override def info: LoggerInfo[F] = new LoggerInfo[F](underlying, localContext.mapValues(FSync.pure)) - override def withArg[A](name: String, value: => A)( - implicit e: Encoder[A] - ): Logger[F] = withComputed(name, FSync.delay { value }) + override def withArg(name: String, value: => Any): Logger[F] = + withComputed(name, FSync.delay { value }) - override def withComputed[A](name: String, value: F[A])( - implicit e: Encoder[A] - ): Logger[F] = { - val json = value.map(ContextManager.JsonInString.make(_)) + override def withComputed(name: String, value: F[Any]): Logger[F] = { + val json = value.map(ContextManager.JsonInString.make) new LoggerImpl[F](underlying, localContext + ((name, json))) } - override def withArgs[A]( - map: Map[String, A] - )(implicit e: Encoder[A]): Logger[F] = + override def withArgs(map: Map[String, Any]): Logger[F] = new LoggerImpl[F]( underlying, localContext ++ map @@ -220,23 +217,17 @@ object ContextLogger { override def info: LoggerInfo[F] = new LoggerInfo[F](underlying, context) - override def withArg[A](name: String, value: => A)( - implicit e: Encoder[A] - ): ContextLogger[F] = + override def withArg(name: String, value: => Any): ContextLogger[F] = withComputed(name, FAsync.delay { value }) - override def withComputed[A](name: String, value: F[A])( - implicit e: Encoder[A] - ): ContextLogger[F] = { - val memoizedJson = Async.memoize(value.map(JsonInString.make(_))) + override def withComputed(name: String, value: F[Any]): ContextLogger[F] = { + val memoizedJson = Async.memoize(value.map(JsonInString.make)) new ContextLoggerImpl[F](underlying, context + ((name, memoizedJson))) } - override def withArgs[A]( - map: Map[String, A] - )(implicit e: Encoder[A]): ContextLogger[F] = + override def withArgs(map: Map[String, Any]): ContextLogger[F] = new ContextLoggerImpl[F]( underlying, context ++ map From 0b87960dd49fc7067d99f50df38e0616a1ad31a3 Mon Sep 17 00:00:00 2001 From: Ondra Pelech Date: Wed, 18 Dec 2019 01:12:19 +0100 Subject: [PATCH 22/35] remove circe dependency --- build.sbt | 3 --- 1 file changed, 3 deletions(-) diff --git a/build.sbt b/build.sbt index 55418b2..2283b81 100644 --- a/build.sbt +++ b/build.sbt @@ -5,7 +5,6 @@ version := "0.1" scalaVersion := "2.12.10" lazy val Version = new { - val circe = "0.11.1" val slf4j = "1.7.29" val logback = "1.2.3" val logstashLogback = "6.2" @@ -34,8 +33,6 @@ lazy val logbackMtlBuilder = project "org.slf4j" % "slf4j-api" % Version.slf4j, "ch.qos.logback" % "logback-classic" % Version.logback, "net.logstash.logback" % "logstash-logback-encoder" % Version.logstashLogback, - "io.circe" %% "circe-core" % Version.circe, - "io.circe" %% "circe-generic" % Version.circe, "org.typelevel" %% "cats-mtl-core" % Version.catsMtl, "org.typelevel" %% "cats-effect" % Version.catsEffect, "org.scala-lang" % "scala-reflect" % scalaVersion.value, From efd45ef89fdd31c3152203265203f1fbc144e4a2 Mon Sep 17 00:00:00 2001 From: Ondra Pelech Date: Wed, 18 Dec 2019 03:10:01 +0100 Subject: [PATCH 23/35] customizable `toJson: Any => String` --- .../loggingexperiment/logbackmtl/Main.scala | 6 +- .../src/main/scala/slf4cats/slf4cats.scala | 186 ++++++++++-------- 2 files changed, 110 insertions(+), 82 deletions(-) diff --git a/logback-mtl-builder-app/src/main/scala/loggingexperiment/logbackmtl/Main.scala b/logback-mtl-builder-app/src/main/scala/loggingexperiment/logbackmtl/Main.scala index e00f19d..23689f5 100644 --- a/logback-mtl-builder-app/src/main/scala/loggingexperiment/logbackmtl/Main.scala +++ b/logback-mtl-builder-app/src/main/scala/loggingexperiment/logbackmtl/Main.scala @@ -14,7 +14,7 @@ object MonixLog { taskLocalContext: TaskLocal[ContextManager.Context[Task]] ): ContextLogger[Task] = { taskLocalContext.runLocal { implicit ev => - ContextLogger.make(logger) + ContextLogger.fromLogger(logger) } } @@ -22,7 +22,7 @@ object MonixLog { taskLocalContext: TaskLocal[ContextManager.Context[Task]] ): ContextLogger[Task] = { taskLocalContext.runLocal { implicit ev => - ContextLogger.make(name) + ContextLogger.fromName(name) } } @@ -30,7 +30,7 @@ object MonixLog { taskLocalContext: TaskLocal[ContextManager.Context[Task]] )(implicit classTag: ClassTag[T]): ContextLogger[Task] = { taskLocalContext.runLocal { implicit ev => - ContextLogger.make + ContextLogger.fromClass() } } } diff --git a/logback-mtl-builder/src/main/scala/slf4cats/slf4cats.scala b/logback-mtl-builder/src/main/scala/slf4cats/slf4cats.scala index 1201ad9..20f2554 100644 --- a/logback-mtl-builder/src/main/scala/slf4cats/slf4cats.scala +++ b/logback-mtl-builder/src/main/scala/slf4cats/slf4cats.scala @@ -9,6 +9,7 @@ import com.fasterxml.jackson.annotation.PropertyAccessor import com.fasterxml.jackson.databind.ObjectMapper import net.logstash.logback.marker.Markers import org.slf4j.{LoggerFactory, Marker} +import slf4cats.ContextManager.JsonInString import scala.language.higherKinds import scala.reflect.ClassTag @@ -27,14 +28,20 @@ object ContextManager { private[slf4cats] val raw: String ) extends AnyVal - private[slf4cats] object JsonInString { + object JsonInString { - private val jackson = new ObjectMapper() - jackson.setVisibility(PropertyAccessor.ALL, Visibility.NONE) - jackson.setVisibility(PropertyAccessor.FIELD, Visibility.ANY) + val defaultToJson: Any => String = { + val jackson = new ObjectMapper() + jackson.setVisibility(PropertyAccessor.ALL, Visibility.NONE) + jackson.setVisibility(PropertyAccessor.FIELD, Visibility.ANY) + x => + jackson.writeValueAsString(x) + } - def make(x: Any): JsonInString = { - new JsonInString(jackson.writeValueAsString(x)) + private[slf4cats] def make[F[_]]( + toJson: Any => String + )(x: Any)(implicit F: Sync[F]): F[JsonInString] = { + F.delay { new JsonInString(toJson(x)) } } } @@ -44,7 +51,8 @@ object ContextManager { } private class ContextManagerImpl[F[_]]( - localContext: Map[String, F[F[JsonInString]]] + localContext: Map[String, F[F[JsonInString]]], + toJson: Any => String, )(implicit FApplicativeLocal: ApplicativeLocal[F, Context[F]], FAsync: Async[F]) extends ContextManager[F] { @@ -58,14 +66,16 @@ object ContextManager { override def withComputed(name: String, value: F[Any]): ContextManager[F] = { - val memoizedJson = Async.memoize(value.map(JsonInString.make)) - new ContextManagerImpl[F](localContext + ((name, memoizedJson))) + val memoizedJson = + Async.memoize(value.flatMap(JsonInString.make(toJson)(_))) + new ContextManagerImpl[F](localContext + ((name, memoizedJson)), toJson) } override def withArgs(map: Map[String, Any]): ContextManager[F] = new ContextManagerImpl[F]( localContext ++ map - .mapValues(v => Async.memoize(FAsync.delay { JsonInString.make(v) })) + .mapValues(v => Async.memoize(JsonInString.make(toJson)(v))), + toJson ) override def use[A](inner: F[A]): F[A] = { @@ -87,9 +97,11 @@ object ContextManager { } } - def make[F[_]](implicit FApplicativeLocal: ApplicativeLocal[F, Context[F]], - FAsync: Async[F]): ContextManager[F] = { - new ContextManagerImpl(Map()) + def make[F[_]](toJson: Option[Any => String] = None)( + implicit FApplicativeLocal: ApplicativeLocal[F, Context[F]], + FAsync: Async[F] + ): ContextManager[F] = { + new ContextManagerImpl(Map(), toJson.getOrElse(JsonInString.defaultToJson)) } } @@ -106,7 +118,8 @@ object Logger { private class LoggerImpl[F[_]]( underlying: org.slf4j.Logger, - localContext: ContextManager.Context[F] + localContext: ContextManager.Context[F], + toJson: Any => String )(implicit FSync: Sync[F], FApplicativeAsk: ApplicativeAsk[F, ContextManager.Context[F]]) extends Logger[F] { @@ -120,83 +133,48 @@ object Logger { withComputed(name, FSync.delay { value }) override def withComputed(name: String, value: F[Any]): Logger[F] = { - val json = value.map(ContextManager.JsonInString.make) - new LoggerImpl[F](underlying, localContext + ((name, json))) + val json = value.flatMap(ContextManager.JsonInString.make(toJson)(_)) + new LoggerImpl[F](underlying, localContext + ((name, json)), toJson) } override def withArgs(map: Map[String, Any]): Logger[F] = new LoggerImpl[F]( underlying, localContext ++ map - .mapValues(v => FSync.delay { ContextManager.JsonInString.make(v) }) + .mapValues(v => ContextManager.JsonInString.make(toJson)(v)), + toJson ) } - def make[F[_]](logger: org.slf4j.Logger)( + def fromLogger[F[_]](logger: org.slf4j.Logger, + toJson: Option[Any => String] = None)( implicit FAsync: Async[F], FApplicativeAsk: ApplicativeAsk[F, ContextManager.Context[F]] ): Logger[F] = { - new LoggerImpl(logger, Map.empty) + new LoggerImpl( + logger, + Map.empty, + toJson.getOrElse(JsonInString.defaultToJson) + ) } - def make[F[_]](name: String)( + def fromName[F[_]](name: String, toJson: Option[Any => String] = None)( implicit FAsync: Async[F], FApplicativeAsk: ApplicativeAsk[F, ContextManager.Context[F]] ): Logger[F] = { - make(LoggerFactory.getLogger(name)) + fromLogger(LoggerFactory.getLogger(name), toJson) } - def make[F[_], T]( + def fromClass[F[_], T](toJson: Option[Any => String] = None)( implicit classTag: ClassTag[T], FAsync: Async[F], FApplicativeAsk: ApplicativeAsk[F, ContextManager.Context[F]] ): Logger[F] = { - make(LoggerFactory.getLogger(classTag.runtimeClass)) + fromLogger(LoggerFactory.getLogger(classTag.runtimeClass), toJson) } } -sealed abstract class LoggerCommand[F[_]] private[slf4cats] ( - underlying: org.slf4j.Logger, - localContext: Map[String, F[F[ContextManager.JsonInString]]] -)(implicit - FSync: Sync[F], - FApplicativeAsk: ApplicativeAsk[F, ContextManager.Context[F]]) { - - import ContextManager._ - - protected val marker: F[Marker] = for { - context1 <- FApplicativeAsk.ask - context2 <- mapSequence(localContext) - union <- mapSequence(context1 ++ context2) - markers = union.toList.map { - case (k, v) => - Markers.appendRaw(k, v.raw) - } - result = Markers.aggregate(markers: _*) - } yield result - - protected def isEnabled - : F[Boolean] // could be made public if there's interest - - /** only to be used used by macro */ - def withUnderlying( - macroCallback: (Sync[F], org.slf4j.Logger) => (Marker => F[Unit]) - ): F[Unit] = { - val body = macroCallback(FSync, underlying) - isEnabled.flatMap { isEnabled => - if (isEnabled) { - marker.flatMap { marker => - body(marker) - } - } else { - FSync.unit - } - } - } - -} - trait ContextLogger[F[_]] extends ContextManager[F] with Logger[F] { type Self <: ContextLogger[F] } @@ -207,7 +185,8 @@ object ContextLogger { private class ContextLoggerImpl[F[_]]( underlying: org.slf4j.Logger, - context: Map[String, F[F[JsonInString]]] + context: Map[String, F[F[JsonInString]]], + toJson: Any => String )(implicit FApplicativeLocal: ApplicativeLocal[F, Context[F]], FAsync: Async[F]) extends ContextLogger[F] { @@ -223,8 +202,13 @@ object ContextLogger { }) override def withComputed(name: String, value: F[Any]): ContextLogger[F] = { - val memoizedJson = Async.memoize(value.map(JsonInString.make)) - new ContextLoggerImpl[F](underlying, context + ((name, memoizedJson))) + val memoizedJson = + Async.memoize(value.flatMap(JsonInString.make(toJson)(_))) + new ContextLoggerImpl[F]( + underlying, + context + ((name, memoizedJson)), + toJson + ) } override def withArgs(map: Map[String, Any]): ContextLogger[F] = @@ -232,11 +216,9 @@ object ContextLogger { underlying, context ++ map .mapValues( - v => - Async.memoize( - FAsync.delay { ContextManager.JsonInString.make(v) } - ) - ) + v => Async.memoize(ContextManager.JsonInString.make(toJson)(v)) + ), + toJson ) override def use[A](inner: F[A]): F[A] = { @@ -246,26 +228,72 @@ object ContextLogger { } } - def make[F[_]](logger: org.slf4j.Logger)( + def fromLogger[F[_]](logger: org.slf4j.Logger, + toJson: Option[Any => String] = None)( implicit FAsync: Async[F], FApplicativeLocal: ApplicativeLocal[F, ContextManager.Context[F]] ): ContextLogger[F] = { - new ContextLoggerImpl[F](logger, Map.empty) + new ContextLoggerImpl[F]( + logger, + Map.empty, + toJson.getOrElse(JsonInString.defaultToJson) + ) } - def make[F[_]](name: String)( + def fromName[F[_]](name: String, toJson: Option[Any => String] = None)( implicit FAsync: Async[F], FApplicativeAsk: ApplicativeLocal[F, ContextManager.Context[F]] ): ContextLogger[F] = { - make(LoggerFactory.getLogger(name)) + fromLogger(LoggerFactory.getLogger(name), toJson) } - def make[F[_], T]( + def fromClass[F[_], T](toJson: Option[Any => String] = None)( implicit classTag: ClassTag[T], FAsync: Async[F], FApplicativeAsk: ApplicativeLocal[F, ContextManager.Context[F]] ): ContextLogger[F] = { - make(LoggerFactory.getLogger(classTag.runtimeClass)) + fromLogger(LoggerFactory.getLogger(classTag.runtimeClass), toJson) + } + +} + +abstract class LoggerCommand[F[_]]( + underlying: org.slf4j.Logger, + localContext: Map[String, F[F[ContextManager.JsonInString]]] +)(implicit + FSync: Sync[F], + FApplicativeAsk: ApplicativeAsk[F, ContextManager.Context[F]]) { + + import ContextManager._ + + private val marker: F[Marker] = for { + context1 <- FApplicativeAsk.ask + context2 <- mapSequence(localContext) + union <- mapSequence(context1 ++ context2) + markers = union.toList.map { + case (k, v) => + Markers.appendRaw(k, v.raw) + } + result = Markers.aggregate(markers: _*) + } yield result + + protected def isEnabled + : F[Boolean] // could be made public if there's interest + + /** only to be used used by macro */ + def withUnderlying( + macroCallback: (Sync[F], org.slf4j.Logger) => (Marker => F[Unit]) + ): F[Unit] = { + val body = macroCallback(FSync, underlying) + isEnabled.flatMap { isEnabled => + if (isEnabled) { + marker.flatMap { marker => + body(marker) + } + } else { + FSync.unit + } + } } } @@ -296,7 +324,7 @@ object LoggerCommand { } } -class LoggerInfo[F[_]] private[slf4cats] ( +class LoggerInfo[F[_]]( underlying: org.slf4j.Logger, tmpContext: Map[String, F[F[ContextManager.JsonInString]]] )(implicit From dfafd74166aa817411e99d6341ccd7cea1506a6e Mon Sep 17 00:00:00 2001 From: Ondra Pelech Date: Fri, 20 Dec 2019 09:21:53 +0100 Subject: [PATCH 24/35] withArg with toJson --- .../src/main/scala/slf4cats/slf4cats.scala | 125 +++++++++++++----- 1 file changed, 91 insertions(+), 34 deletions(-) diff --git a/logback-mtl-builder/src/main/scala/slf4cats/slf4cats.scala b/logback-mtl-builder/src/main/scala/slf4cats/slf4cats.scala index 20f2554..46ec163 100644 --- a/logback-mtl-builder/src/main/scala/slf4cats/slf4cats.scala +++ b/logback-mtl-builder/src/main/scala/slf4cats/slf4cats.scala @@ -16,9 +16,13 @@ import scala.reflect.ClassTag trait ContextManager[F[_]] { type Self <: ContextManager[F] - def withArg(name: String, value: => Any): Self - def withComputed(name: String, value: F[Any]): Self - def withArgs(map: Map[String, Any]): Self + def withArg[A](name: String, + value: => A, + toJson: Option[A => String] = None): Self + def withComputed[A](name: String, + value: F[A], + toJson: Option[A => String] = None): Self + def withArgs[A](map: Map[String, A], toJson: Option[A => String] = None): Self def use[A](inner: F[A]): F[A] } @@ -38,9 +42,9 @@ object ContextManager { jackson.writeValueAsString(x) } - private[slf4cats] def make[F[_]]( - toJson: Any => String - )(x: Any)(implicit F: Sync[F]): F[JsonInString] = { + private[slf4cats] def make[F[_], A]( + toJson: A => String + )(x: A)(implicit F: Sync[F]): F[JsonInString] = { F.delay { new JsonInString(toJson(x)) } } } @@ -52,30 +56,49 @@ object ContextManager { private class ContextManagerImpl[F[_]]( localContext: Map[String, F[F[JsonInString]]], - toJson: Any => String, + toJsonGlobal: Any => String, )(implicit FApplicativeLocal: ApplicativeLocal[F, Context[F]], FAsync: Async[F]) extends ContextManager[F] { override type Self = ContextManager[F] - override def withArg(name: String, value: => Any): ContextManager[F] = + override def withArg[A]( + name: String, + value: => A, + toJson: Option[A => String] = None + ): ContextManager[F] = withComputed(name, FAsync.delay { value }) - override def withComputed(name: String, - value: F[Any]): ContextManager[F] = { + override def withComputed[A]( + name: String, + value: F[A], + toJson: Option[A => String] = None + ): ContextManager[F] = { val memoizedJson = - Async.memoize(value.flatMap(JsonInString.make(toJson)(_))) - new ContextManagerImpl[F](localContext + ((name, memoizedJson)), toJson) + Async.memoize( + value.flatMap(JsonInString.make(toJson.getOrElse(toJsonGlobal))(_)) + ) + new ContextManagerImpl[F]( + localContext + ((name, memoizedJson)), + toJsonGlobal + ) } - override def withArgs(map: Map[String, Any]): ContextManager[F] = + override def withArgs[A]( + map: Map[String, A], + toJson: Option[A => String] = None + ): ContextManager[F] = new ContextManagerImpl[F]( localContext ++ map - .mapValues(v => Async.memoize(JsonInString.make(toJson)(v))), - toJson + .mapValues( + v => + Async + .memoize(JsonInString.make(toJson.getOrElse(toJsonGlobal))(v)) + ), + toJsonGlobal ) override def use[A](inner: F[A]): F[A] = { @@ -108,9 +131,13 @@ object ContextManager { trait Logger[F[_]] { type Self <: Logger[F] - def withArg(name: String, value: => Any): Self - def withComputed(name: String, value: F[Any]): Self - def withArgs(map: Map[String, Any]): Self + def withArg[A](name: String, + value: => A, + toJson: Option[A => String] = None): Self + def withComputed[A](name: String, + value: F[A], + toJson: Option[A => String] = None): Self + def withArgs[A](map: Map[String, A], toJson: Option[A => String] = None): Self def info: LoggerInfo[F] } @@ -119,7 +146,7 @@ object Logger { private class LoggerImpl[F[_]]( underlying: org.slf4j.Logger, localContext: ContextManager.Context[F], - toJson: Any => String + toJsonGlobal: Any => String )(implicit FSync: Sync[F], FApplicativeAsk: ApplicativeAsk[F, ContextManager.Context[F]]) extends Logger[F] { @@ -129,20 +156,33 @@ object Logger { override def info: LoggerInfo[F] = new LoggerInfo[F](underlying, localContext.mapValues(FSync.pure)) - override def withArg(name: String, value: => Any): Logger[F] = + override def withArg[A](name: String, + value: => A, + toJson: Option[A => String] = None): Logger[F] = withComputed(name, FSync.delay { value }) - override def withComputed(name: String, value: F[Any]): Logger[F] = { - val json = value.flatMap(ContextManager.JsonInString.make(toJson)(_)) - new LoggerImpl[F](underlying, localContext + ((name, json)), toJson) + override def withComputed[A]( + name: String, + value: F[A], + toJson: Option[A => String] = None + ): Logger[F] = { + val json = value.flatMap( + ContextManager.JsonInString.make(toJson.getOrElse(toJsonGlobal))(_) + ) + new LoggerImpl[F](underlying, localContext + ((name, json)), toJsonGlobal) } - override def withArgs(map: Map[String, Any]): Logger[F] = + override def withArgs[A](map: Map[String, A], + toJson: Option[A => String] = None): Logger[F] = new LoggerImpl[F]( underlying, localContext ++ map - .mapValues(v => ContextManager.JsonInString.make(toJson)(v)), - toJson + .mapValues( + v => + ContextManager.JsonInString + .make(toJson.getOrElse(toJsonGlobal))(v) + ), + toJsonGlobal ) } @@ -186,7 +226,7 @@ object ContextLogger { private class ContextLoggerImpl[F[_]]( underlying: org.slf4j.Logger, context: Map[String, F[F[JsonInString]]], - toJson: Any => String + toJsonGlobal: Any => String )(implicit FApplicativeLocal: ApplicativeLocal[F, Context[F]], FAsync: Async[F]) extends ContextLogger[F] { @@ -196,29 +236,46 @@ object ContextLogger { override def info: LoggerInfo[F] = new LoggerInfo[F](underlying, context) - override def withArg(name: String, value: => Any): ContextLogger[F] = + override def withArg[A]( + name: String, + value: => A, + toJson: Option[A => String] = None + ): ContextLogger[F] = withComputed(name, FAsync.delay { value }) - override def withComputed(name: String, value: F[Any]): ContextLogger[F] = { + override def withComputed[A]( + name: String, + value: F[A], + toJson: Option[A => String] = None + ): ContextLogger[F] = { val memoizedJson = - Async.memoize(value.flatMap(JsonInString.make(toJson)(_))) + Async.memoize( + value.flatMap(JsonInString.make(toJson.getOrElse(toJsonGlobal))(_)) + ) new ContextLoggerImpl[F]( underlying, context + ((name, memoizedJson)), - toJson + toJsonGlobal ) } - override def withArgs(map: Map[String, Any]): ContextLogger[F] = + override def withArgs[A]( + map: Map[String, A], + toJson: Option[A => String] = None + ): ContextLogger[F] = new ContextLoggerImpl[F]( underlying, context ++ map .mapValues( - v => Async.memoize(ContextManager.JsonInString.make(toJson)(v)) + v => + Async.memoize( + ContextManager.JsonInString + .make(toJson.getOrElse(toJsonGlobal))(v) + ) ), - toJson + toJsonGlobal ) override def use[A](inner: F[A]): F[A] = { From 1d8c997f7090177820576ae2920023a374903db2 Mon Sep 17 00:00:00 2001 From: Ondra Pelech Date: Fri, 20 Dec 2019 10:52:14 +0100 Subject: [PATCH 25/35] separate API and implementation --- build.sbt | 36 +- .../src/main/scala/slf4cats/slf4cats.scala | 417 ------------------ .../scala/slf4cats/api/slf4cats-api.scala | 82 ++++ .../src/main/resources/logback.xml | 0 .../main/scala/slf4cats/example}/Main.scala | 13 +- .../scala/slf4cats/impl/ContextLogger.scala | 199 +++++++++ 6 files changed, 312 insertions(+), 435 deletions(-) delete mode 100644 logback-mtl-builder/src/main/scala/slf4cats/slf4cats.scala create mode 100644 slf4cats-api/src/main/scala/slf4cats/api/slf4cats-api.scala rename {logback-mtl-builder-app => slf4cats-example}/src/main/resources/logback.xml (100%) rename {logback-mtl-builder-app/src/main/scala/loggingexperiment/logbackmtl => slf4cats-example/src/main/scala/slf4cats/example}/Main.scala (82%) create mode 100644 slf4cats-impl/src/main/scala/slf4cats/impl/ContextLogger.scala diff --git a/build.sbt b/build.sbt index 2283b81..2629ee0 100644 --- a/build.sbt +++ b/build.sbt @@ -17,35 +17,47 @@ lazy val Version = new { lazy val root = project .in(file(".")) .settings( - name := "loggingexperiment", + name := "slf4cats", publish / skip := true, // doesn't publish ivy XML files, in contrast to "publishArtifact := false" ) .aggregate( - logbackMtlBuilder, - logbackMtlBuilderApp, + slf4catsApi, + slf4catsImpl, + slf4catsExample, ) -lazy val logbackMtlBuilder = project - .in(file("logback-mtl-builder")) +lazy val slf4catsApi = project + .in(file("slf4cats-api")) .settings( - name := "logback-mtl-builder", + name := "slf4cats-api", + libraryDependencies ++= Seq( + "org.slf4j" % "slf4j-api" % Version.slf4j, + "org.typelevel" %% "cats-effect" % Version.catsEffect, + "org.scala-lang" % "scala-reflect" % scalaVersion.value, + ) + ) + +lazy val slf4catsImpl = project + .in(file("slf4cats-impl")) + .settings( + name := "slf4cats-impl", libraryDependencies ++= Seq( "org.slf4j" % "slf4j-api" % Version.slf4j, - "ch.qos.logback" % "logback-classic" % Version.logback, "net.logstash.logback" % "logstash-logback-encoder" % Version.logstashLogback, "org.typelevel" %% "cats-mtl-core" % Version.catsMtl, "org.typelevel" %% "cats-effect" % Version.catsEffect, - "org.scala-lang" % "scala-reflect" % scalaVersion.value, ) ) + .dependsOn(slf4catsApi) -lazy val logbackMtlBuilderApp = project - .in(file("logback-mtl-builder-app")) +lazy val slf4catsExample = project + .in(file("slf4cats-example")) .settings( - name := "logback-mtl-builder-app", + name := "slf4cats-example", libraryDependencies ++= Seq( + "ch.qos.logback" % "logback-classic" % Version.logback, "io.monix" %% "monix" % Version.monix, "com.olegpy" %% "meow-mtl-monix" % Version.meowMtl, ) ) - .dependsOn(logbackMtlBuilder) + .dependsOn(slf4catsImpl) diff --git a/logback-mtl-builder/src/main/scala/slf4cats/slf4cats.scala b/logback-mtl-builder/src/main/scala/slf4cats/slf4cats.scala deleted file mode 100644 index 46ec163..0000000 --- a/logback-mtl-builder/src/main/scala/slf4cats/slf4cats.scala +++ /dev/null @@ -1,417 +0,0 @@ -package slf4cats - -import cats._ -import cats.effect._ -import cats.implicits._ -import cats.mtl._ -import com.fasterxml.jackson.annotation.JsonAutoDetect.Visibility -import com.fasterxml.jackson.annotation.PropertyAccessor -import com.fasterxml.jackson.databind.ObjectMapper -import net.logstash.logback.marker.Markers -import org.slf4j.{LoggerFactory, Marker} -import slf4cats.ContextManager.JsonInString - -import scala.language.higherKinds -import scala.reflect.ClassTag - -trait ContextManager[F[_]] { - type Self <: ContextManager[F] - def withArg[A](name: String, - value: => A, - toJson: Option[A => String] = None): Self - def withComputed[A](name: String, - value: F[A], - toJson: Option[A => String] = None): Self - def withArgs[A](map: Map[String, A], toJson: Option[A => String] = None): Self - def use[A](inner: F[A]): F[A] -} - -object ContextManager { - - private[slf4cats] class JsonInString private ( - private[slf4cats] val raw: String - ) extends AnyVal - - object JsonInString { - - val defaultToJson: Any => String = { - val jackson = new ObjectMapper() - jackson.setVisibility(PropertyAccessor.ALL, Visibility.NONE) - jackson.setVisibility(PropertyAccessor.FIELD, Visibility.ANY) - x => - jackson.writeValueAsString(x) - } - - private[slf4cats] def make[F[_], A]( - toJson: A => String - )(x: A)(implicit F: Sync[F]): F[JsonInString] = { - F.delay { new JsonInString(toJson(x)) } - } - } - - type Context[F[_]] = Map[String, F[JsonInString]] - object Context { - def empty[F[_]]: Context[F] = Map.empty - } - - private class ContextManagerImpl[F[_]]( - localContext: Map[String, F[F[JsonInString]]], - toJsonGlobal: Any => String, - )(implicit FApplicativeLocal: ApplicativeLocal[F, Context[F]], - FAsync: Async[F]) - extends ContextManager[F] { - - override type Self = ContextManager[F] - - override def withArg[A]( - name: String, - value: => A, - toJson: Option[A => String] = None - ): ContextManager[F] = - withComputed(name, FAsync.delay { - value - }) - - override def withComputed[A]( - name: String, - value: F[A], - toJson: Option[A => String] = None - ): ContextManager[F] = { - val memoizedJson = - Async.memoize( - value.flatMap(JsonInString.make(toJson.getOrElse(toJsonGlobal))(_)) - ) - new ContextManagerImpl[F]( - localContext + ((name, memoizedJson)), - toJsonGlobal - ) - } - - override def withArgs[A]( - map: Map[String, A], - toJson: Option[A => String] = None - ): ContextManager[F] = - new ContextManagerImpl[F]( - localContext ++ map - .mapValues( - v => - Async - .memoize(JsonInString.make(toJson.getOrElse(toJsonGlobal))(v)) - ), - toJsonGlobal - ) - - override def use[A](inner: F[A]): F[A] = { - mapSequence(localContext).flatMap { contextMemoized => - FApplicativeLocal.local(_ ++ contextMemoized)(inner) - } - } - } - - private[slf4cats] def mapSequence[F[_], K, V]( - m: Map[K, F[V]] - )(implicit FApplicative: Applicative[F]): F[Map[K, V]] = { - m.foldLeft(FApplicative.pure(Map.empty[K, V])) { - case (m, (k, fv)) => - FApplicative.tuple2(m, fv).map { - case (m, v) => - m + ((k, v)) - } - } - } - - def make[F[_]](toJson: Option[Any => String] = None)( - implicit FApplicativeLocal: ApplicativeLocal[F, Context[F]], - FAsync: Async[F] - ): ContextManager[F] = { - new ContextManagerImpl(Map(), toJson.getOrElse(JsonInString.defaultToJson)) - } - -} - -trait Logger[F[_]] { - type Self <: Logger[F] - def withArg[A](name: String, - value: => A, - toJson: Option[A => String] = None): Self - def withComputed[A](name: String, - value: F[A], - toJson: Option[A => String] = None): Self - def withArgs[A](map: Map[String, A], toJson: Option[A => String] = None): Self - def info: LoggerInfo[F] -} - -object Logger { - - private class LoggerImpl[F[_]]( - underlying: org.slf4j.Logger, - localContext: ContextManager.Context[F], - toJsonGlobal: Any => String - )(implicit FSync: Sync[F], - FApplicativeAsk: ApplicativeAsk[F, ContextManager.Context[F]]) - extends Logger[F] { - - override type Self = Logger[F] - - override def info: LoggerInfo[F] = - new LoggerInfo[F](underlying, localContext.mapValues(FSync.pure)) - - override def withArg[A](name: String, - value: => A, - toJson: Option[A => String] = None): Logger[F] = - withComputed(name, FSync.delay { value }) - - override def withComputed[A]( - name: String, - value: F[A], - toJson: Option[A => String] = None - ): Logger[F] = { - val json = value.flatMap( - ContextManager.JsonInString.make(toJson.getOrElse(toJsonGlobal))(_) - ) - new LoggerImpl[F](underlying, localContext + ((name, json)), toJsonGlobal) - } - - override def withArgs[A](map: Map[String, A], - toJson: Option[A => String] = None): Logger[F] = - new LoggerImpl[F]( - underlying, - localContext ++ map - .mapValues( - v => - ContextManager.JsonInString - .make(toJson.getOrElse(toJsonGlobal))(v) - ), - toJsonGlobal - ) - - } - - def fromLogger[F[_]](logger: org.slf4j.Logger, - toJson: Option[Any => String] = None)( - implicit FAsync: Async[F], - FApplicativeAsk: ApplicativeAsk[F, ContextManager.Context[F]] - ): Logger[F] = { - new LoggerImpl( - logger, - Map.empty, - toJson.getOrElse(JsonInString.defaultToJson) - ) - } - - def fromName[F[_]](name: String, toJson: Option[Any => String] = None)( - implicit FAsync: Async[F], - FApplicativeAsk: ApplicativeAsk[F, ContextManager.Context[F]] - ): Logger[F] = { - fromLogger(LoggerFactory.getLogger(name), toJson) - } - - def fromClass[F[_], T](toJson: Option[Any => String] = None)( - implicit classTag: ClassTag[T], - FAsync: Async[F], - FApplicativeAsk: ApplicativeAsk[F, ContextManager.Context[F]] - ): Logger[F] = { - fromLogger(LoggerFactory.getLogger(classTag.runtimeClass), toJson) - } -} - -trait ContextLogger[F[_]] extends ContextManager[F] with Logger[F] { - type Self <: ContextLogger[F] -} - -object ContextLogger { - - import ContextManager._ - - private class ContextLoggerImpl[F[_]]( - underlying: org.slf4j.Logger, - context: Map[String, F[F[JsonInString]]], - toJsonGlobal: Any => String - )(implicit FApplicativeLocal: ApplicativeLocal[F, Context[F]], - FAsync: Async[F]) - extends ContextLogger[F] { - - override type Self = ContextLogger[F] - - override def info: LoggerInfo[F] = - new LoggerInfo[F](underlying, context) - - override def withArg[A]( - name: String, - value: => A, - toJson: Option[A => String] = None - ): ContextLogger[F] = - withComputed(name, FAsync.delay { - value - }) - - override def withComputed[A]( - name: String, - value: F[A], - toJson: Option[A => String] = None - ): ContextLogger[F] = { - val memoizedJson = - Async.memoize( - value.flatMap(JsonInString.make(toJson.getOrElse(toJsonGlobal))(_)) - ) - new ContextLoggerImpl[F]( - underlying, - context + ((name, memoizedJson)), - toJsonGlobal - ) - } - - override def withArgs[A]( - map: Map[String, A], - toJson: Option[A => String] = None - ): ContextLogger[F] = - new ContextLoggerImpl[F]( - underlying, - context ++ map - .mapValues( - v => - Async.memoize( - ContextManager.JsonInString - .make(toJson.getOrElse(toJsonGlobal))(v) - ) - ), - toJsonGlobal - ) - - override def use[A](inner: F[A]): F[A] = { - mapSequence(context).flatMap { contextMemoized => - FApplicativeLocal.local(_ ++ contextMemoized)(inner) - } - } - } - - def fromLogger[F[_]](logger: org.slf4j.Logger, - toJson: Option[Any => String] = None)( - implicit FAsync: Async[F], - FApplicativeLocal: ApplicativeLocal[F, ContextManager.Context[F]] - ): ContextLogger[F] = { - new ContextLoggerImpl[F]( - logger, - Map.empty, - toJson.getOrElse(JsonInString.defaultToJson) - ) - } - - def fromName[F[_]](name: String, toJson: Option[Any => String] = None)( - implicit FAsync: Async[F], - FApplicativeAsk: ApplicativeLocal[F, ContextManager.Context[F]] - ): ContextLogger[F] = { - fromLogger(LoggerFactory.getLogger(name), toJson) - } - - def fromClass[F[_], T](toJson: Option[Any => String] = None)( - implicit classTag: ClassTag[T], - FAsync: Async[F], - FApplicativeAsk: ApplicativeLocal[F, ContextManager.Context[F]] - ): ContextLogger[F] = { - fromLogger(LoggerFactory.getLogger(classTag.runtimeClass), toJson) - } - -} - -abstract class LoggerCommand[F[_]]( - underlying: org.slf4j.Logger, - localContext: Map[String, F[F[ContextManager.JsonInString]]] -)(implicit - FSync: Sync[F], - FApplicativeAsk: ApplicativeAsk[F, ContextManager.Context[F]]) { - - import ContextManager._ - - private val marker: F[Marker] = for { - context1 <- FApplicativeAsk.ask - context2 <- mapSequence(localContext) - union <- mapSequence(context1 ++ context2) - markers = union.toList.map { - case (k, v) => - Markers.appendRaw(k, v.raw) - } - result = Markers.aggregate(markers: _*) - } yield result - - protected def isEnabled - : F[Boolean] // could be made public if there's interest - - /** only to be used used by macro */ - def withUnderlying( - macroCallback: (Sync[F], org.slf4j.Logger) => (Marker => F[Unit]) - ): F[Unit] = { - val body = macroCallback(FSync, underlying) - isEnabled.flatMap { isEnabled => - if (isEnabled) { - marker.flatMap { marker => - body(marker) - } - } else { - FSync.unit - } - } - } - -} - -object LoggerCommand { - private[slf4cats] object Macros { - import scala.reflect.macros.blackbox - type Context[F[_]] = blackbox.Context { type PrefixType = LoggerCommand[F] } - - def log[F[_]](c: Context[F])(level: c.TermName, - message: c.Expr[String]): c.Expr[F[Unit]] = { - import c.universe._ - val tree = - q"${c.prefix}.withUnderlying { case (fsync, underlying) => (marker => fsync.delay { underlying.$level(marker, $message) }) }" - c.Expr[F[Unit]](tree) - } - - def logThrowable[F[_]](c: Context[F])( - level: c.TermName, - message: c.Expr[String], - throwable: c.Expr[Throwable] - ): c.Expr[F[Unit]] = { - import c.universe._ - val tree = - q"${c.prefix}.withUnderlying { case (fsync, underlying) => (marker => fsync.delay { underlying.$level(marker, $message, $throwable) }) }" - c.Expr[F[Unit]](tree) - } - } -} - -class LoggerInfo[F[_]]( - underlying: org.slf4j.Logger, - tmpContext: Map[String, F[F[ContextManager.JsonInString]]] -)(implicit - FSync: Sync[F], - FApplicativeAsk: ApplicativeAsk[F, ContextManager.Context[F]]) - extends LoggerCommand(underlying, tmpContext) { - - import scala.language.experimental.macros - - override protected val isEnabled: F[Boolean] = FSync.delay { - underlying.isInfoEnabled - } - - def apply(message: String): F[Unit] = macro LoggerInfo.Macros.info[F] - def apply(message: String, throwable: Throwable): F[Unit] = - macro LoggerInfo.Macros.infoThrowable[F] -} - -object LoggerInfo { - - private[LoggerInfo] object Macros { - import LoggerCommand.Macros._ - - def info[F[_]](c: Context[F])(message: c.Expr[String]): c.Expr[F[Unit]] = - log(c)(c.universe.TermName("info"), message) - - def infoThrowable[F[_]]( - c: Context[F] - )(message: c.Expr[String], throwable: c.Expr[Throwable]): c.Expr[F[Unit]] = - logThrowable(c)(c.universe.TermName("info"), message, throwable) - } - -} diff --git a/slf4cats-api/src/main/scala/slf4cats/api/slf4cats-api.scala b/slf4cats-api/src/main/scala/slf4cats/api/slf4cats-api.scala new file mode 100644 index 0000000..e153f34 --- /dev/null +++ b/slf4cats-api/src/main/scala/slf4cats/api/slf4cats-api.scala @@ -0,0 +1,82 @@ +package slf4cats.api + +import cats.effect.Sync +import org.slf4j.Marker + +trait ContextManager[F[_]] { + type Self <: ContextManager[F] + def withArg[A](name: String, + value: => A, + toJson: Option[A => String] = None): Self + def withComputed[A](name: String, + value: F[A], + toJson: Option[A => String] = None): Self + def withArgs[A](map: Map[String, A], toJson: Option[A => String] = None): Self + def use[A](inner: F[A]): F[A] +} + +trait Logger[F[_]] { + type Self <: Logger[F] + def withArg[A](name: String, + value: => A, + toJson: Option[A => String] = None): Self + def withComputed[A](name: String, + value: F[A], + toJson: Option[A => String] = None): Self + def withArgs[A](map: Map[String, A], toJson: Option[A => String] = None): Self + def info: LoggerInfo[F] +} + +trait ContextLogger[F[_]] extends ContextManager[F] with Logger[F] { + type Self <: ContextLogger[F] +} + +trait LoggerCommand[F[_]] { + +// could be made available if there's interest +//def isEnabled: F[Boolean] + + def withUnderlying( + macroCallback: (Sync[F], org.slf4j.Logger) => (Marker => F[Unit]) + ): F[Unit] +} + +object LoggerCommand { + private[api] object Macros { + import scala.reflect.macros.blackbox + type Context[F[_]] = blackbox.Context { type PrefixType = LoggerCommand[F] } + + def log[F[_]](c: Context[F])(level: c.TermName, + message: c.Expr[String]): c.Expr[F[Unit]] = { + import c.universe._ + val tree = + q"${c.prefix}.withUnderlying { case (fsync, underlying) => (marker => fsync.delay { underlying.$level(marker, $message) }) }" + c.Expr[F[Unit]](tree) + } + + def logThrowable[F[_]](c: Context[F])( + level: c.TermName, + message: c.Expr[String], + throwable: c.Expr[Throwable] + ): c.Expr[F[Unit]] = { + import c.universe._ + val tree = + q"${c.prefix}.withUnderlying { case (fsync, underlying) => (marker => fsync.delay { underlying.$level(marker, $message, $throwable) }) }" + c.Expr[F[Unit]](tree) + } + + def info[F[_]](c: Context[F])(message: c.Expr[String]): c.Expr[F[Unit]] = + log(c)(c.universe.TermName("info"), message) + + def infoThrowable[F[_]]( + c: Context[F] + )(message: c.Expr[String], throwable: c.Expr[Throwable]): c.Expr[F[Unit]] = + logThrowable(c)(c.universe.TermName("info"), message, throwable) + } +} + +abstract class LoggerInfo[F[_]]() extends LoggerCommand[F] { + def apply(message: String): F[Unit] = macro LoggerCommand.Macros.info[F] + def apply(message: String, throwable: Throwable): F[Unit] = + macro LoggerCommand.Macros.infoThrowable[F] +} diff --git a/logback-mtl-builder-app/src/main/resources/logback.xml b/slf4cats-example/src/main/resources/logback.xml similarity index 100% rename from logback-mtl-builder-app/src/main/resources/logback.xml rename to slf4cats-example/src/main/resources/logback.xml diff --git a/logback-mtl-builder-app/src/main/scala/loggingexperiment/logbackmtl/Main.scala b/slf4cats-example/src/main/scala/slf4cats/example/Main.scala similarity index 82% rename from logback-mtl-builder-app/src/main/scala/loggingexperiment/logbackmtl/Main.scala rename to slf4cats-example/src/main/scala/slf4cats/example/Main.scala index 23689f5..c06397e 100644 --- a/logback-mtl-builder-app/src/main/scala/loggingexperiment/logbackmtl/Main.scala +++ b/slf4cats-example/src/main/scala/slf4cats/example/Main.scala @@ -1,17 +1,18 @@ -package loggingexperiment.logbackmtl +package slf4cats.example import java.security.InvalidParameterException import cats.effect._ import com.olegpy.meow.monix._ import monix.eval._ -import slf4cats._ +import slf4cats.api._ +import slf4cats.impl._ import scala.reflect.ClassTag object MonixLog { def make(logger: org.slf4j.Logger)( - taskLocalContext: TaskLocal[ContextManager.Context[Task]] + taskLocalContext: TaskLocal[ContextLogger.Context[Task]] ): ContextLogger[Task] = { taskLocalContext.runLocal { implicit ev => ContextLogger.fromLogger(logger) @@ -19,7 +20,7 @@ object MonixLog { } def make(name: String)( - taskLocalContext: TaskLocal[ContextManager.Context[Task]] + taskLocalContext: TaskLocal[ContextLogger.Context[Task]] ): ContextLogger[Task] = { taskLocalContext.runLocal { implicit ev => ContextLogger.fromName(name) @@ -27,7 +28,7 @@ object MonixLog { } def make[T]( - taskLocalContext: TaskLocal[ContextManager.Context[Task]] + taskLocalContext: TaskLocal[ContextLogger.Context[Task]] )(implicit classTag: ClassTag[T]): ContextLogger[Task] = { taskLocalContext.runLocal { implicit ev => ContextLogger.fromClass() @@ -50,7 +51,7 @@ object Main extends TaskApp { def init: Task[Unit] = for { - mdc <- TaskLocal(ContextManager.Context.empty[Task]) + mdc <- TaskLocal(ContextLogger.Context.empty[Task]) logger = MonixLog.make[Main.type](mdc) result <- program(logger) } yield result diff --git a/slf4cats-impl/src/main/scala/slf4cats/impl/ContextLogger.scala b/slf4cats-impl/src/main/scala/slf4cats/impl/ContextLogger.scala new file mode 100644 index 0000000..c8fd65f --- /dev/null +++ b/slf4cats-impl/src/main/scala/slf4cats/impl/ContextLogger.scala @@ -0,0 +1,199 @@ +package slf4cats.impl + +import cats._ +import cats.effect._ +import cats.implicits._ +import cats.mtl._ +import com.fasterxml.jackson.annotation.JsonAutoDetect.Visibility +import com.fasterxml.jackson.annotation.PropertyAccessor +import com.fasterxml.jackson.databind.ObjectMapper +import net.logstash.logback.marker.Markers +import org.slf4j.{LoggerFactory, Marker} +import slf4cats.api._ + +import scala.reflect.ClassTag + +object ContextLogger { + + class JsonInString private (private[ContextLogger] val raw: String) + extends AnyVal + + object JsonInString { + + val defaultToJson: Any => String = { + val jackson = new ObjectMapper() + jackson.setVisibility(PropertyAccessor.ALL, Visibility.NONE) + jackson.setVisibility(PropertyAccessor.FIELD, Visibility.ANY) + x => + jackson.writeValueAsString(x) + } + + private[ContextLogger] def make[F[_], A]( + toJson: A => String + )(x: A)(implicit F: Sync[F]): F[JsonInString] = { + F.delay { new JsonInString(toJson(x)) } + } + } + + type Context[F[_]] = Map[String, F[JsonInString]] + object Context { + def empty[F[_]]: Context[F] = Map.empty + } + + private[slf4cats] def mapSequence[F[_], K, V]( + m: Map[K, F[V]] + )(implicit FApplicative: Applicative[F]): F[Map[K, V]] = { + m.foldLeft(FApplicative.pure(Map.empty[K, V])) { + case (m, (k, fv)) => + FApplicative.tuple2(m, fv).map { + case (m, v) => + m + ((k, v)) + } + } + } + + private trait LoggerCommandImpl[F[_]] { + + def underlying: org.slf4j.Logger + + def localContext: Map[String, F[F[JsonInString]]] + + implicit def FSync: Sync[F] + + implicit def FApplicativeAsk: ApplicativeAsk[F, Context[F]] + + private val marker: F[Marker] = for { + context1 <- FApplicativeAsk.ask + context2 <- mapSequence(localContext) + union <- mapSequence(context1 ++ context2) + markers = union.toList.map { + case (k, v) => + Markers.appendRaw(k, v.raw) + } + result = Markers.aggregate(markers: _*) + } yield result + + protected def isEnabled: F[Boolean] + + def withUnderlying( + macroCallback: (Sync[F], org.slf4j.Logger) => (Marker => F[Unit]) + ): F[Unit] = { + val body = macroCallback(FSync, underlying) + isEnabled.flatMap { isEnabled => + if (isEnabled) { + marker.flatMap { marker => + body(marker) + } + } else { + FSync.unit + } + } + } + } + + private class LoggerInfoImpl[F[_]]( + val underlying: org.slf4j.Logger, + val localContext: Map[String, F[F[JsonInString]]] + )(implicit + val FSync: Sync[F], + val FApplicativeAsk: ApplicativeAsk[F, Context[F]]) + extends LoggerInfo[F] + with LoggerCommandImpl[F] { + + override protected val isEnabled: F[Boolean] = FSync.delay { + underlying.isInfoEnabled + } + } + + private class ContextLoggerImpl[F[_]]( + underlying: org.slf4j.Logger, + context: Map[String, F[F[JsonInString]]], + toJsonGlobal: Any => String + )(implicit FApplicativeLocal: ApplicativeLocal[F, Context[F]], + FAsync: Async[F]) + extends ContextLogger[F] { + + override type Self = ContextLogger[F] + + override def info: LoggerInfo[F] = + new LoggerInfoImpl[F](underlying, context) + + override def withArg[A]( + name: String, + value: => A, + toJson: Option[A => String] = None + ): ContextLogger[F] = + withComputed(name, FAsync.delay { + value + }) + + override def withComputed[A]( + name: String, + value: F[A], + toJson: Option[A => String] = None + ): ContextLogger[F] = { + val memoizedJson = + Async.memoize( + value.flatMap(JsonInString.make(toJson.getOrElse(toJsonGlobal))(_)) + ) + new ContextLoggerImpl[F]( + underlying, + context + ((name, memoizedJson)), + toJsonGlobal + ) + } + + override def withArgs[A]( + map: Map[String, A], + toJson: Option[A => String] = None + ): ContextLogger[F] = { + val toJsonLocal = toJson.getOrElse(toJsonGlobal) + new ContextLoggerImpl[F]( + underlying, + context ++ map + .mapValues( + v => + Async.memoize( + JsonInString + .make(toJsonLocal)(v) + ) + ), + toJsonGlobal + ) + } + + override def use[A](inner: F[A]): F[A] = { + mapSequence(context).flatMap { contextMemoized => + FApplicativeLocal.local(_ ++ contextMemoized)(inner) + } + } + } + + def fromLogger[F[_]]( + logger: org.slf4j.Logger, + toJson: Option[Any => String] = None + )(implicit FAsync: Async[F], + FApplicativeLocal: ApplicativeLocal[F, Context[F]]): ContextLogger[F] = { + new ContextLoggerImpl[F]( + logger, + Map.empty, + toJson.getOrElse(JsonInString.defaultToJson) + ) + } + + def fromName[F[_]](name: String, toJson: Option[Any => String] = None)( + implicit FAsync: Async[F], + FApplicativeAsk: ApplicativeLocal[F, Context[F]] + ): ContextLogger[F] = { + fromLogger(LoggerFactory.getLogger(name), toJson) + } + + def fromClass[F[_], T](toJson: Option[Any => String] = None)( + implicit classTag: ClassTag[T], + FAsync: Async[F], + FApplicativeAsk: ApplicativeLocal[F, Context[F]] + ): ContextLogger[F] = { + fromLogger(LoggerFactory.getLogger(classTag.runtimeClass), toJson) + } + +} From 0a7ce9cbb3aad312eb47d45c1d9f36ccb238d993 Mon Sep 17 00:00:00 2001 From: Ondra Pelech Date: Fri, 20 Dec 2019 12:39:48 +0100 Subject: [PATCH 26/35] add warn --- .../main/scala/slf4cats/api/slf4cats-api.scala | 15 +++++++++++++++ .../src/main/scala/slf4cats/example/Main.scala | 8 ++++---- .../scala/slf4cats/impl/ContextLogger.scala | 17 +++++++++++++++++ 3 files changed, 36 insertions(+), 4 deletions(-) diff --git a/slf4cats-api/src/main/scala/slf4cats/api/slf4cats-api.scala b/slf4cats-api/src/main/scala/slf4cats/api/slf4cats-api.scala index e153f34..53136ee 100644 --- a/slf4cats-api/src/main/scala/slf4cats/api/slf4cats-api.scala +++ b/slf4cats-api/src/main/scala/slf4cats/api/slf4cats-api.scala @@ -25,6 +25,7 @@ trait Logger[F[_]] { toJson: Option[A => String] = None): Self def withArgs[A](map: Map[String, A], toJson: Option[A => String] = None): Self def info: LoggerInfo[F] + def warn: LoggerWarn[F] } trait ContextLogger[F[_]] extends ContextManager[F] with Logger[F] { @@ -72,6 +73,14 @@ object LoggerCommand { c: Context[F] )(message: c.Expr[String], throwable: c.Expr[Throwable]): c.Expr[F[Unit]] = logThrowable(c)(c.universe.TermName("info"), message, throwable) + + def warn[F[_]](c: Context[F])(message: c.Expr[String]): c.Expr[F[Unit]] = + log(c)(c.universe.TermName("warn"), message) + + def warnThrowable[F[_]]( + c: Context[F] + )(message: c.Expr[String], throwable: c.Expr[Throwable]): c.Expr[F[Unit]] = + logThrowable(c)(c.universe.TermName("warn"), message, throwable) } } @@ -80,3 +89,9 @@ abstract class LoggerInfo[F[_]]() extends LoggerCommand[F] { def apply(message: String, throwable: Throwable): F[Unit] = macro LoggerCommand.Macros.infoThrowable[F] } + +abstract class LoggerWarn[F[_]]() extends LoggerCommand[F] { + def apply(message: String): F[Unit] = macro LoggerCommand.Macros.warn[F] + def apply(message: String, throwable: Throwable): F[Unit] = + macro LoggerCommand.Macros.warnThrowable[F] +} diff --git a/slf4cats-example/src/main/scala/slf4cats/example/Main.scala b/slf4cats-example/src/main/scala/slf4cats/example/Main.scala index c06397e..fad5a70 100644 --- a/slf4cats-example/src/main/scala/slf4cats/example/Main.scala +++ b/slf4cats-example/src/main/scala/slf4cats/example/Main.scala @@ -38,11 +38,11 @@ object MonixLog { object Main extends TaskApp { - final case class A(x: Int, y: String) + final case class A(x: Int, y: String, bytes: Array[Byte]) final case class B(a: A, b: Boolean) - private val o = B(A(123, "Hello"), b = true) + private val o = B(A(123, "Hello", Array(1, 2, 3)), b = true) override def run(args: List[String]): Task[ExitCode] = init @@ -60,10 +60,10 @@ object Main extends TaskApp { val ex = new InvalidParameterException("BOOOOOM") for { _ <- logger - .withArg("a", A(1, "x")) + .withArg("a", A(1, "x", Array(127))) .withArg("o", o) .info("Hello Monix") - _ <- logger.info("Hello MTL", ex) + _ <- logger.warn("Hello MTL", ex) _ <- logger.withArg("x", 123).withArg("o", o).use { logger.withArg("x", 9).info("Hello2 meow") } diff --git a/slf4cats-impl/src/main/scala/slf4cats/impl/ContextLogger.scala b/slf4cats-impl/src/main/scala/slf4cats/impl/ContextLogger.scala index c8fd65f..02788dc 100644 --- a/slf4cats-impl/src/main/scala/slf4cats/impl/ContextLogger.scala +++ b/slf4cats-impl/src/main/scala/slf4cats/impl/ContextLogger.scala @@ -105,6 +105,20 @@ object ContextLogger { } } + private class LoggerWarnImpl[F[_]]( + val underlying: org.slf4j.Logger, + val localContext: Map[String, F[F[JsonInString]]] + )(implicit + val FSync: Sync[F], + val FApplicativeAsk: ApplicativeAsk[F, Context[F]]) + extends LoggerWarn[F] + with LoggerCommandImpl[F] { + + override protected val isEnabled: F[Boolean] = FSync.delay { + underlying.isWarnEnabled + } + } + private class ContextLoggerImpl[F[_]]( underlying: org.slf4j.Logger, context: Map[String, F[F[JsonInString]]], @@ -118,6 +132,9 @@ object ContextLogger { override def info: LoggerInfo[F] = new LoggerInfoImpl[F](underlying, context) + override def warn: LoggerWarn[F] = + new LoggerWarnImpl[F](underlying, context) + override def withArg[A]( name: String, value: => A, From b2dbe6c6fcaf9ac0b674acd2112bcfef8ae75042 Mon Sep 17 00:00:00 2001 From: Ondra Pelech Date: Fri, 20 Dec 2019 15:14:27 +0100 Subject: [PATCH 27/35] update README.md --- README.md | 82 +++++++++++++++++++++++++++++++++++-------------------- 1 file changed, 52 insertions(+), 30 deletions(-) diff --git a/README.md b/README.md index 06f57e5..196d0eb 100644 --- a/README.md +++ b/README.md @@ -29,16 +29,35 @@ This repo contains experiments with possible implementations of structured loggi ## Interface ```scala -trait ContextLogger[F[_]] { - type Self <: ContextLogger[F] - def withArg[A](name: String, value: => A)(implicit e: Encoder[A]): Self - def withComputed[A](name: String, value: F[A])(implicit e: Encoder[A]): Self - def withArgs[A](map: Map[String, A])(implicit e: Encoder[A]): Self +trait ContextManager[F[_]] { + type Self <: ContextManager[F] + def withArg[A](name: String, + value: => A, + toJson: Option[A => String] = None): Self + def withComputed[A](name: String, + value: F[A], + toJson: Option[A => String] = None): Self + def withArgs[A](map: Map[String, A], toJson: Option[A => String] = None): Self def use[A](inner: F[A]): F[A] +} + +trait Logger[F[_]] { + type Self <: Logger[F] + def withArg[A](name: String, + value: => A, + toJson: Option[A => String] = None): Self + def withComputed[A](name: String, + value: F[A], + toJson: Option[A => String] = None): Self + def withArgs[A](map: Map[String, A], toJson: Option[A => String] = None): Self // excerpt for `info` logging def info: LoggerInfo[F] //... } + +trait ContextLogger[F[_]] extends ContextManager[F] with Logger[F] { + type Self <: ContextLogger[F] +} class LoggerInfo[F[_]] (???) { def apply(message: String): F[Unit] = macro ??? def apply(message: String, throwable: Throwable): F[Unit] = macro ??? @@ -52,10 +71,10 @@ def program(logger: ContextLogger[Task]): Task[Unit] = { val ex = new InvalidParameterException("BOOOOOM") for { _ <- logger - .withArg("a", A(1, "x")) + .withArg("a", A(1, "x", Array[Byte](127))) .withArg("o", o) .info("Hello Monix") - _ <- logger.info("Hello MTL", ex) + _ <- logger.warn("Hello MTL", ex) _ <- logger.withArg("x", 123).withArg("o", o).use { logger.withArg("x", 9).info("Hello2 meow") } @@ -66,33 +85,35 @@ def program(logger: ContextLogger[Task]): Task[Unit] = { ### Multiple contexts ```scala _ <- logger - .withArg("a", A(1, "x")) + .withArg("a", A(1, "x", Array[Byte](127))) .withArg("o", o) .info("Hello Monix") ``` ```json { - "@timestamp": "2019-12-11T19:52:54.619+01:00", + "@timestamp": "2019-12-20T11:02:44.837+01:00", "@version": "1", "message": "Hello Monix", - "logger_name": "loggingexperiment.logbackmtl.Main$", - "thread_name": "scala-execution-context-global-13", + "logger_name": "slf4cats.example.Main$", + "thread_name": "scala-execution-context-global-14", "level": "INFO", "level_value": 20000, "a": { "x": 1, - "y": "x" + "y": "x", + "bytes": "fw==" }, "o": { "a": { "x": 123, - "y": "Hello" + "y": "Hello", + "bytes": "AQID" }, "b": true }, "application": "loggingexperiment", - "caller_class_name": "loggingexperiment.logbackmtl.Main$", - "caller_method_name": "$anonfun$program$7", + "caller_class_name": "slf4cats.example.Main$", + "caller_method_name": "$anonfun$program$5", "caller_file_name": "Main.scala", "caller_line_number": 65 } @@ -100,21 +121,21 @@ _ <- logger ### Logging exception ```scala -_ <- logger.info("Hello MTL", ex) +_ <- logger.warn("Hello MTL", ex) ``` ```json { - "@timestamp": "2019-12-11T19:52:54.631+01:00", + "@timestamp": "2019-12-20T11:02:44.856+01:00", "@version": "1", "message": "Hello MTL", - "logger_name": "loggingexperiment.logbackmtl.Main$", - "thread_name": "scala-execution-context-global-13", - "level": "INFO", - "level_value": 20000, - "stack_trace": "java.security.InvalidParameterException: BOOOOOM\n\tat loggingexperiment.logbackmtl.Main$.program(Main.scala:60)\n...", + "logger_name": "slf4cats.example.Main$", + "thread_name": "scala-execution-context-global-14", + "level": "WARN", + "level_value": 30000, + "stack_trace": "java.security.InvalidParameterException: BOOOOOM\n\tat slf4cats.example.Main$.program(Main.scala:60)\n...", "application": "loggingexperiment", - "caller_class_name": "loggingexperiment.logbackmtl.Main$", - "caller_method_name": "$anonfun$program$11", + "caller_class_name": "slf4cats.example.Main$", + "caller_method_name": "$anonfun$program$9", "caller_file_name": "Main.scala", "caller_line_number": 66 } @@ -128,24 +149,25 @@ _ <- logger.withArg("x", 123).withArg("o", o).use { ``` ```json { - "@timestamp": "2019-12-11T19:52:54.645+01:00", + "@timestamp": "2019-12-20T11:02:44.882+01:00", "@version": "1", "message": "Hello2 meow", - "logger_name": "loggingexperiment.logbackmtl.Main$", - "thread_name": "scala-execution-context-global-13", + "logger_name": "slf4cats.example.Main$", + "thread_name": "scala-execution-context-global-15", "level": "INFO", "level_value": 20000, "x": 9, "o": { "a": { "x": 123, - "y": "Hello" + "y": "Hello", + "bytes": "AQID" }, "b": true }, "application": "loggingexperiment", - "caller_class_name": "loggingexperiment.logbackmtl.Main$", - "caller_method_name": "$anonfun$program$19", + "caller_class_name": "slf4cats.example.Main$", + "caller_method_name": "$anonfun$program$16", "caller_file_name": "Main.scala", "caller_line_number": 68 } From 6dafc58251d953943043d23119ad45bb5119f56c Mon Sep 17 00:00:00 2001 From: Ondra Pelech Date: Fri, 20 Dec 2019 17:02:09 +0100 Subject: [PATCH 28/35] Update README.md --- README.md | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/README.md b/README.md index 196d0eb..3b8888f 100644 --- a/README.md +++ b/README.md @@ -58,7 +58,7 @@ trait Logger[F[_]] { trait ContextLogger[F[_]] extends ContextManager[F] with Logger[F] { type Self <: ContextLogger[F] } -class LoggerInfo[F[_]] (???) { +class LoggerInfo[F[_]]() { def apply(message: String): F[Unit] = macro ??? def apply(message: String, throwable: Throwable): F[Unit] = macro ??? } From b1510b53386925d276e085d2616b13c11167e822 Mon Sep 17 00:00:00 2001 From: Ondra Pelech Date: Fri, 20 Dec 2019 17:03:49 +0100 Subject: [PATCH 29/35] Update README.md --- README.md | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/README.md b/README.md index 3b8888f..4ece477 100644 --- a/README.md +++ b/README.md @@ -22,7 +22,7 @@ This repo contains experiments with possible implementations of structured loggi ## Implementation considerations - * use Circe for the encoding + * use Jackson for the encoding by default (used by Logback Logstash encoder too) * mimic `slf4j`'s `Logger` API/capabilities * always as free-form strings -- simplest solution From 9e0894fe5be95207499eb15af4fd2ab82c25f722 Mon Sep 17 00:00:00 2001 From: Ondra Pelech Date: Tue, 7 Jan 2020 20:04:19 +0100 Subject: [PATCH 30/35] rename ContextManager -> LoggingContext --- .scalafmt.conf | 2 + README.md | 6 +- build.sbt | 9 +- .../scala/slf4cats/api/slf4cats-api.scala | 56 ++++---- .../main/scala/slf4cats/example/Main.scala | 6 +- .../scala/slf4cats/impl/ContextLogger.scala | 125 +++++++++--------- 6 files changed, 109 insertions(+), 95 deletions(-) create mode 100644 .scalafmt.conf diff --git a/.scalafmt.conf b/.scalafmt.conf new file mode 100644 index 0000000..9b803ea --- /dev/null +++ b/.scalafmt.conf @@ -0,0 +1,2 @@ +version=2.3.2 +trailingCommas = always diff --git a/README.md b/README.md index 4ece477..4acb23e 100644 --- a/README.md +++ b/README.md @@ -29,8 +29,8 @@ This repo contains experiments with possible implementations of structured loggi ## Interface ```scala -trait ContextManager[F[_]] { - type Self <: ContextManager[F] +trait LoggingContext[F[_]] { + type Self <: LoggingContext[F] def withArg[A](name: String, value: => A, toJson: Option[A => String] = None): Self @@ -55,7 +55,7 @@ trait Logger[F[_]] { //... } -trait ContextLogger[F[_]] extends ContextManager[F] with Logger[F] { +trait ContextLogger[F[_]] extends LoggingContext[F] with Logger[F] { type Self <: ContextLogger[F] } class LoggerInfo[F[_]]() { diff --git a/build.sbt b/build.sbt index 2629ee0..b1cbe06 100644 --- a/build.sbt +++ b/build.sbt @@ -34,7 +34,7 @@ lazy val slf4catsApi = project "org.slf4j" % "slf4j-api" % Version.slf4j, "org.typelevel" %% "cats-effect" % Version.catsEffect, "org.scala-lang" % "scala-reflect" % scalaVersion.value, - ) + ), ) lazy val slf4catsImpl = project @@ -42,11 +42,10 @@ lazy val slf4catsImpl = project .settings( name := "slf4cats-impl", libraryDependencies ++= Seq( - "org.slf4j" % "slf4j-api" % Version.slf4j, "net.logstash.logback" % "logstash-logback-encoder" % Version.logstashLogback, "org.typelevel" %% "cats-mtl-core" % Version.catsMtl, "org.typelevel" %% "cats-effect" % Version.catsEffect, - ) + ), ) .dependsOn(slf4catsApi) @@ -56,8 +55,8 @@ lazy val slf4catsExample = project name := "slf4cats-example", libraryDependencies ++= Seq( "ch.qos.logback" % "logback-classic" % Version.logback, - "io.monix" %% "monix" % Version.monix, + "io.monix" %% "monix" % Version.monix, "com.olegpy" %% "meow-mtl-monix" % Version.meowMtl, - ) + ), ) .dependsOn(slf4catsImpl) diff --git a/slf4cats-api/src/main/scala/slf4cats/api/slf4cats-api.scala b/slf4cats-api/src/main/scala/slf4cats/api/slf4cats-api.scala index 53136ee..bf7bc7b 100644 --- a/slf4cats-api/src/main/scala/slf4cats/api/slf4cats-api.scala +++ b/slf4cats-api/src/main/scala/slf4cats/api/slf4cats-api.scala @@ -3,32 +3,40 @@ package slf4cats.api import cats.effect.Sync import org.slf4j.Marker -trait ContextManager[F[_]] { - type Self <: ContextManager[F] - def withArg[A](name: String, - value: => A, - toJson: Option[A => String] = None): Self - def withComputed[A](name: String, - value: F[A], - toJson: Option[A => String] = None): Self +trait LoggingContext[F[_]] { + type Self <: LoggingContext[F] + def withArg[A]( + name: String, + value: => A, + toJson: Option[A => String] = None, + ): Self + def withComputed[A]( + name: String, + value: F[A], + toJson: Option[A => String] = None, + ): Self def withArgs[A](map: Map[String, A], toJson: Option[A => String] = None): Self def use[A](inner: F[A]): F[A] } trait Logger[F[_]] { type Self <: Logger[F] - def withArg[A](name: String, - value: => A, - toJson: Option[A => String] = None): Self - def withComputed[A](name: String, - value: F[A], - toJson: Option[A => String] = None): Self + def withArg[A]( + name: String, + value: => A, + toJson: Option[A => String] = None, + ): Self + def withComputed[A]( + name: String, + value: F[A], + toJson: Option[A => String] = None, + ): Self def withArgs[A](map: Map[String, A], toJson: Option[A => String] = None): Self def info: LoggerInfo[F] def warn: LoggerWarn[F] } -trait ContextLogger[F[_]] extends ContextManager[F] with Logger[F] { +trait ContextLogger[F[_]] extends LoggingContext[F] with Logger[F] { type Self <: ContextLogger[F] } @@ -37,8 +45,9 @@ trait LoggerCommand[F[_]] { // could be made available if there's interest //def isEnabled: F[Boolean] + /** To be used by a macro, don't use this yourself */ def withUnderlying( - macroCallback: (Sync[F], org.slf4j.Logger) => (Marker => F[Unit]) + macroCallback: (Sync[F], org.slf4j.Logger) => (Marker => F[Unit]), ): F[Unit] } @@ -47,8 +56,9 @@ object LoggerCommand { import scala.reflect.macros.blackbox type Context[F[_]] = blackbox.Context { type PrefixType = LoggerCommand[F] } - def log[F[_]](c: Context[F])(level: c.TermName, - message: c.Expr[String]): c.Expr[F[Unit]] = { + def log[F[_]]( + c: Context[F], + )(level: c.TermName, message: c.Expr[String]): c.Expr[F[Unit]] = { import c.universe._ val tree = q"${c.prefix}.withUnderlying { case (fsync, underlying) => (marker => fsync.delay { underlying.$level(marker, $message) }) }" @@ -56,9 +66,9 @@ object LoggerCommand { } def logThrowable[F[_]](c: Context[F])( - level: c.TermName, - message: c.Expr[String], - throwable: c.Expr[Throwable] + level: c.TermName, + message: c.Expr[String], + throwable: c.Expr[Throwable], ): c.Expr[F[Unit]] = { import c.universe._ val tree = @@ -70,7 +80,7 @@ object LoggerCommand { log(c)(c.universe.TermName("info"), message) def infoThrowable[F[_]]( - c: Context[F] + c: Context[F], )(message: c.Expr[String], throwable: c.Expr[Throwable]): c.Expr[F[Unit]] = logThrowable(c)(c.universe.TermName("info"), message, throwable) @@ -78,7 +88,7 @@ object LoggerCommand { log(c)(c.universe.TermName("warn"), message) def warnThrowable[F[_]]( - c: Context[F] + c: Context[F], )(message: c.Expr[String], throwable: c.Expr[Throwable]): c.Expr[F[Unit]] = logThrowable(c)(c.universe.TermName("warn"), message, throwable) } diff --git a/slf4cats-example/src/main/scala/slf4cats/example/Main.scala b/slf4cats-example/src/main/scala/slf4cats/example/Main.scala index fad5a70..8e225a2 100644 --- a/slf4cats-example/src/main/scala/slf4cats/example/Main.scala +++ b/slf4cats-example/src/main/scala/slf4cats/example/Main.scala @@ -12,7 +12,7 @@ import scala.reflect.ClassTag object MonixLog { def make(logger: org.slf4j.Logger)( - taskLocalContext: TaskLocal[ContextLogger.Context[Task]] + taskLocalContext: TaskLocal[ContextLogger.Context[Task]], ): ContextLogger[Task] = { taskLocalContext.runLocal { implicit ev => ContextLogger.fromLogger(logger) @@ -20,7 +20,7 @@ object MonixLog { } def make(name: String)( - taskLocalContext: TaskLocal[ContextLogger.Context[Task]] + taskLocalContext: TaskLocal[ContextLogger.Context[Task]], ): ContextLogger[Task] = { taskLocalContext.runLocal { implicit ev => ContextLogger.fromName(name) @@ -28,7 +28,7 @@ object MonixLog { } def make[T]( - taskLocalContext: TaskLocal[ContextLogger.Context[Task]] + taskLocalContext: TaskLocal[ContextLogger.Context[Task]], )(implicit classTag: ClassTag[T]): ContextLogger[Task] = { taskLocalContext.runLocal { implicit ev => ContextLogger.fromClass() diff --git a/slf4cats-impl/src/main/scala/slf4cats/impl/ContextLogger.scala b/slf4cats-impl/src/main/scala/slf4cats/impl/ContextLogger.scala index 02788dc..8487a67 100644 --- a/slf4cats-impl/src/main/scala/slf4cats/impl/ContextLogger.scala +++ b/slf4cats-impl/src/main/scala/slf4cats/impl/ContextLogger.scala @@ -15,37 +15,36 @@ import scala.reflect.ClassTag object ContextLogger { - class JsonInString private (private[ContextLogger] val raw: String) - extends AnyVal - object JsonInString { val defaultToJson: Any => String = { val jackson = new ObjectMapper() jackson.setVisibility(PropertyAccessor.ALL, Visibility.NONE) jackson.setVisibility(PropertyAccessor.FIELD, Visibility.ANY) - x => - jackson.writeValueAsString(x) + jackson.writeValueAsString } private[ContextLogger] def make[F[_], A]( - toJson: A => String - )(x: A)(implicit F: Sync[F]): F[JsonInString] = { - F.delay { new JsonInString(toJson(x)) } + toJson: A => String, + )(x: A)(implicit F: Sync[F]): F[String] = { + F.delay { + toJson(x) + } + .handleError(e => "\"<" + e + ">\"") } } - type Context[F[_]] = Map[String, F[JsonInString]] + type Context[F[_]] = Map[String, F[String]] object Context { def empty[F[_]]: Context[F] = Map.empty } - private[slf4cats] def mapSequence[F[_], K, V]( - m: Map[K, F[V]] + private def mapSequence[F[_], K, V]( + m: Map[K, F[V]], )(implicit FApplicative: Applicative[F]): F[Map[K, V]] = { m.foldLeft(FApplicative.pure(Map.empty[K, V])) { - case (m, (k, fv)) => - FApplicative.tuple2(m, fv).map { + case (fm, (k, fv)) => + FApplicative.tuple2(fm, fv).map { case (m, v) => m + ((k, v)) } @@ -56,7 +55,7 @@ object ContextLogger { def underlying: org.slf4j.Logger - def localContext: Map[String, F[F[JsonInString]]] + def localContext: Map[String, F[F[String]]] implicit def FSync: Sync[F] @@ -68,7 +67,7 @@ object ContextLogger { union <- mapSequence(context1 ++ context2) markers = union.toList.map { case (k, v) => - Markers.appendRaw(k, v.raw) + Markers.appendRaw(k, v) } result = Markers.aggregate(markers: _*) } yield result @@ -76,7 +75,7 @@ object ContextLogger { protected def isEnabled: F[Boolean] def withUnderlying( - macroCallback: (Sync[F], org.slf4j.Logger) => (Marker => F[Unit]) + macroCallback: (Sync[F], org.slf4j.Logger) => (Marker => F[Unit]), ): F[Unit] = { val body = macroCallback(FSync, underlying) isEnabled.flatMap { isEnabled => @@ -92,12 +91,13 @@ object ContextLogger { } private class LoggerInfoImpl[F[_]]( - val underlying: org.slf4j.Logger, - val localContext: Map[String, F[F[JsonInString]]] - )(implicit - val FSync: Sync[F], - val FApplicativeAsk: ApplicativeAsk[F, Context[F]]) - extends LoggerInfo[F] + val underlying: org.slf4j.Logger, + val localContext: Map[String, F[F[String]]], + )( + implicit + val FSync: Sync[F], + val FApplicativeAsk: ApplicativeAsk[F, Context[F]], + ) extends LoggerInfo[F] with LoggerCommandImpl[F] { override protected val isEnabled: F[Boolean] = FSync.delay { @@ -106,12 +106,13 @@ object ContextLogger { } private class LoggerWarnImpl[F[_]]( - val underlying: org.slf4j.Logger, - val localContext: Map[String, F[F[JsonInString]]] - )(implicit - val FSync: Sync[F], - val FApplicativeAsk: ApplicativeAsk[F, Context[F]]) - extends LoggerWarn[F] + val underlying: org.slf4j.Logger, + val localContext: Map[String, F[F[String]]], + )( + implicit + val FSync: Sync[F], + val FApplicativeAsk: ApplicativeAsk[F, Context[F]], + ) extends LoggerWarn[F] with LoggerCommandImpl[F] { override protected val isEnabled: F[Boolean] = FSync.delay { @@ -120,12 +121,13 @@ object ContextLogger { } private class ContextLoggerImpl[F[_]]( - underlying: org.slf4j.Logger, - context: Map[String, F[F[JsonInString]]], - toJsonGlobal: Any => String - )(implicit FApplicativeLocal: ApplicativeLocal[F, Context[F]], - FAsync: Async[F]) - extends ContextLogger[F] { + underlying: org.slf4j.Logger, + context: Map[String, F[F[String]]], + toJsonGlobal: Any => String, + )( + implicit FApplicativeLocal: ApplicativeLocal[F, Context[F]], + FAsync: Async[F], + ) extends ContextLogger[F] { override type Self = ContextLogger[F] @@ -136,46 +138,45 @@ object ContextLogger { new LoggerWarnImpl[F](underlying, context) override def withArg[A]( - name: String, - value: => A, - toJson: Option[A => String] = None + name: String, + value: => A, + toJson: Option[A => String] = None, ): ContextLogger[F] = withComputed(name, FAsync.delay { value }) override def withComputed[A]( - name: String, - value: F[A], - toJson: Option[A => String] = None + name: String, + value: F[A], + toJson: Option[A => String] = None, ): ContextLogger[F] = { val memoizedJson = Async.memoize( - value.flatMap(JsonInString.make(toJson.getOrElse(toJsonGlobal))(_)) + value.flatMap(JsonInString.make(toJson.getOrElse(toJsonGlobal))(_)), ) new ContextLoggerImpl[F]( underlying, context + ((name, memoizedJson)), - toJsonGlobal + toJsonGlobal, ) } override def withArgs[A]( - map: Map[String, A], - toJson: Option[A => String] = None + map: Map[String, A], + toJson: Option[A => String] = None, ): ContextLogger[F] = { val toJsonLocal = toJson.getOrElse(toJsonGlobal) new ContextLoggerImpl[F]( underlying, context ++ map - .mapValues( - v => - Async.memoize( - JsonInString - .make(toJsonLocal)(v) - ) + .mapValues(v => + Async.memoize( + JsonInString + .make(toJsonLocal)(v), + ), ), - toJsonGlobal + toJsonGlobal, ) } @@ -187,28 +188,30 @@ object ContextLogger { } def fromLogger[F[_]]( - logger: org.slf4j.Logger, - toJson: Option[Any => String] = None - )(implicit FAsync: Async[F], - FApplicativeLocal: ApplicativeLocal[F, Context[F]]): ContextLogger[F] = { + logger: org.slf4j.Logger, + toJson: Option[Any => String] = None, + )( + implicit FAsync: Async[F], + FApplicativeLocal: ApplicativeLocal[F, Context[F]], + ): ContextLogger[F] = { new ContextLoggerImpl[F]( logger, Map.empty, - toJson.getOrElse(JsonInString.defaultToJson) + toJson.getOrElse(JsonInString.defaultToJson), ) } def fromName[F[_]](name: String, toJson: Option[Any => String] = None)( - implicit FAsync: Async[F], - FApplicativeAsk: ApplicativeLocal[F, Context[F]] + implicit FAsync: Async[F], + FApplicativeAsk: ApplicativeLocal[F, Context[F]], ): ContextLogger[F] = { fromLogger(LoggerFactory.getLogger(name), toJson) } def fromClass[F[_], T](toJson: Option[Any => String] = None)( - implicit classTag: ClassTag[T], - FAsync: Async[F], - FApplicativeAsk: ApplicativeLocal[F, Context[F]] + implicit classTag: ClassTag[T], + FAsync: Async[F], + FApplicativeAsk: ApplicativeLocal[F, Context[F]], ): ContextLogger[F] = { fromLogger(LoggerFactory.getLogger(classTag.runtimeClass), toJson) } From 9592c8a5428e1573f27a5e8e0175fbb9b70b9d5b Mon Sep 17 00:00:00 2001 From: Ondra Pelech Date: Tue, 7 Jan 2020 20:16:15 +0100 Subject: [PATCH 31/35] fix withArg and local toJson --- .../main/scala/slf4cats/impl/ContextLogger.scala | 13 +++++++++---- 1 file changed, 9 insertions(+), 4 deletions(-) diff --git a/slf4cats-impl/src/main/scala/slf4cats/impl/ContextLogger.scala b/slf4cats-impl/src/main/scala/slf4cats/impl/ContextLogger.scala index 8487a67..f284e2c 100644 --- a/slf4cats-impl/src/main/scala/slf4cats/impl/ContextLogger.scala +++ b/slf4cats-impl/src/main/scala/slf4cats/impl/ContextLogger.scala @@ -12,6 +12,7 @@ import org.slf4j.{LoggerFactory, Marker} import slf4cats.api._ import scala.reflect.ClassTag +import scala.util.control.NonFatal object ContextLogger { @@ -30,7 +31,7 @@ object ContextLogger { F.delay { toJson(x) } - .handleError(e => "\"<" + e + ">\"") + .recover { case NonFatal(e) => "\"<" + e + ">\"" } } } @@ -142,9 +143,13 @@ object ContextLogger { value: => A, toJson: Option[A => String] = None, ): ContextLogger[F] = - withComputed(name, FAsync.delay { - value - }) + withComputed( + name, + FAsync.delay { + value + }, + toJson, + ) override def withComputed[A]( name: String, From 6e9cb1627b90a97edb29c0e4a50abaa267778de7 Mon Sep 17 00:00:00 2001 From: Ondra Pelech Date: Wed, 8 Jan 2020 00:33:54 +0100 Subject: [PATCH 32/35] update README --- README.md | 13 +++++++++---- 1 file changed, 9 insertions(+), 4 deletions(-) diff --git a/README.md b/README.md index 4acb23e..884a8d0 100644 --- a/README.md +++ b/README.md @@ -20,11 +20,16 @@ This repo contains experiments with possible implementations of structured loggi * ... to be specified * JSON keys will be just strings, at lest for the beginning -## Implementation considerations +## Features - * use Jackson for the encoding by default (used by Logback Logstash encoder too) - * mimic `slf4j`'s `Logger` API/capabilities - * always as free-form strings -- simplest solution + * thin wrapper over `slf4j` + * each logging statement is inlined on the same line using macros + * rest of the logging pipeline works as expected + * JSON logging + * uses `logstash-logback-encoder` for JSON log formatting + * uses Jackson for the encoding of log parameters by default (imported by Logback Logstash encoder anyway; can be overridden if necessary) + * CPU expensive or side-effectful actions can be passed to logs + * will be memoized == computed only once or never at all, if log level too low ## Interface From 5832e429a690f73aa4fc1b3771e6bf903bf49a6a Mon Sep 17 00:00:00 2001 From: Ondra Pelech Date: Wed, 8 Jan 2020 02:36:36 +0100 Subject: [PATCH 33/35] Jackson for Scala --- README.md | 42 +++++++++++++------ build.sbt | 2 + .../main/scala/slf4cats/example/Main.scala | 7 ++-- .../scala/slf4cats/impl/ContextLogger.scala | 6 +-- 4 files changed, 37 insertions(+), 20 deletions(-) diff --git a/README.md b/README.md index 884a8d0..99be91c 100644 --- a/README.md +++ b/README.md @@ -96,11 +96,11 @@ _ <- logger ``` ```json { - "@timestamp": "2019-12-20T11:02:44.837+01:00", + "@timestamp": "2020-01-08T02:31:16.503+01:00", "@version": "1", "message": "Hello Monix", "logger_name": "slf4cats.example.Main$", - "thread_name": "scala-execution-context-global-14", + "thread_name": "scala-execution-context-global-13", "level": "INFO", "level_value": 20000, "a": { @@ -114,13 +114,19 @@ _ <- logger "y": "Hello", "bytes": "AQID" }, - "b": true + "b": [ + false, + true + ], + "c": { + "r": 456 + } }, "application": "loggingexperiment", "caller_class_name": "slf4cats.example.Main$", "caller_method_name": "$anonfun$program$5", "caller_file_name": "Main.scala", - "caller_line_number": 65 + "caller_line_number": 66 } ``` @@ -130,19 +136,19 @@ _ <- logger.warn("Hello MTL", ex) ``` ```json { - "@timestamp": "2019-12-20T11:02:44.856+01:00", + "@timestamp": "2020-01-08T02:31:16.520+01:00", "@version": "1", "message": "Hello MTL", "logger_name": "slf4cats.example.Main$", - "thread_name": "scala-execution-context-global-14", + "thread_name": "scala-execution-context-global-13", "level": "WARN", "level_value": 30000, - "stack_trace": "java.security.InvalidParameterException: BOOOOOM\n\tat slf4cats.example.Main$.program(Main.scala:60)\n...", + "stack_trace": "java.security.InvalidParameterException: BOOOOOM\n\tat slf4cats.example.Main$.program(Main.scala:61)\n...", "application": "loggingexperiment", "caller_class_name": "slf4cats.example.Main$", "caller_method_name": "$anonfun$program$9", "caller_file_name": "Main.scala", - "caller_line_number": 66 + "caller_line_number": 67 } ``` @@ -154,26 +160,36 @@ _ <- logger.withArg("x", 123).withArg("o", o).use { ``` ```json { - "@timestamp": "2019-12-20T11:02:44.882+01:00", + "@timestamp": "2020-01-08T02:31:16.539+01:00", "@version": "1", "message": "Hello2 meow", "logger_name": "slf4cats.example.Main$", - "thread_name": "scala-execution-context-global-15", + "thread_name": "scala-execution-context-global-13", "level": "INFO", "level_value": 20000, - "x": 9, + "x": [ + 1, + 2, + 3 + ], "o": { "a": { "x": 123, "y": "Hello", "bytes": "AQID" }, - "b": true + "b": [ + false, + true + ], + "c": { + "r": 456 + } }, "application": "loggingexperiment", "caller_class_name": "slf4cats.example.Main$", "caller_method_name": "$anonfun$program$16", "caller_file_name": "Main.scala", - "caller_line_number": 68 + "caller_line_number": 69 } ``` diff --git a/build.sbt b/build.sbt index b1cbe06..0f1dc24 100644 --- a/build.sbt +++ b/build.sbt @@ -7,6 +7,7 @@ scalaVersion := "2.12.10" lazy val Version = new { val slf4j = "1.7.29" val logback = "1.2.3" + val jacksonScala = "2.10.2" val logstashLogback = "6.2" val monix = "3.1.0" val catsMtl = "0.7.0" @@ -42,6 +43,7 @@ lazy val slf4catsImpl = project .settings( name := "slf4cats-impl", libraryDependencies ++= Seq( + "com.fasterxml.jackson.module" %% "jackson-module-scala" % Version.jacksonScala, "net.logstash.logback" % "logstash-logback-encoder" % Version.logstashLogback, "org.typelevel" %% "cats-mtl-core" % Version.catsMtl, "org.typelevel" %% "cats-effect" % Version.catsEffect, diff --git a/slf4cats-example/src/main/scala/slf4cats/example/Main.scala b/slf4cats-example/src/main/scala/slf4cats/example/Main.scala index 8e225a2..2d4d620 100644 --- a/slf4cats-example/src/main/scala/slf4cats/example/Main.scala +++ b/slf4cats-example/src/main/scala/slf4cats/example/Main.scala @@ -40,9 +40,10 @@ object Main extends TaskApp { final case class A(x: Int, y: String, bytes: Array[Byte]) - final case class B(a: A, b: Boolean) + final case class B(a: A, b: List[Boolean], c: Either[String, Int]) - private val o = B(A(123, "Hello", Array(1, 2, 3)), b = true) + private val o = + B(A(123, "Hello", Array(1, 2, 3)), List(false, true), Right(456)) override def run(args: List[String]): Task[ExitCode] = init @@ -65,7 +66,7 @@ object Main extends TaskApp { .info("Hello Monix") _ <- logger.warn("Hello MTL", ex) _ <- logger.withArg("x", 123).withArg("o", o).use { - logger.withArg("x", 9).info("Hello2 meow") + logger.withArg("x", List(1, 2, 3)).info("Hello2 meow") } } yield () } diff --git a/slf4cats-impl/src/main/scala/slf4cats/impl/ContextLogger.scala b/slf4cats-impl/src/main/scala/slf4cats/impl/ContextLogger.scala index f284e2c..a8dce92 100644 --- a/slf4cats-impl/src/main/scala/slf4cats/impl/ContextLogger.scala +++ b/slf4cats-impl/src/main/scala/slf4cats/impl/ContextLogger.scala @@ -4,9 +4,8 @@ import cats._ import cats.effect._ import cats.implicits._ import cats.mtl._ -import com.fasterxml.jackson.annotation.JsonAutoDetect.Visibility -import com.fasterxml.jackson.annotation.PropertyAccessor import com.fasterxml.jackson.databind.ObjectMapper +import com.fasterxml.jackson.module.scala.DefaultScalaModule import net.logstash.logback.marker.Markers import org.slf4j.{LoggerFactory, Marker} import slf4cats.api._ @@ -20,8 +19,7 @@ object ContextLogger { val defaultToJson: Any => String = { val jackson = new ObjectMapper() - jackson.setVisibility(PropertyAccessor.ALL, Visibility.NONE) - jackson.setVisibility(PropertyAccessor.FIELD, Visibility.ANY) + jackson.registerModule(DefaultScalaModule) jackson.writeValueAsString } From fb95dde50e55bdb42244e3e8adce18bfd0a92c93 Mon Sep 17 00:00:00 2001 From: Ondra Pelech Date: Fri, 10 Jan 2020 12:54:50 +0100 Subject: [PATCH 34/35] monix logger --- build.sbt | 15 +++++-- .../main/scala/slf4cats/example/Main.scala | 39 +++++-------------- .../slf4cats/monix/ContextLoggerMonix.scala | 35 +++++++++++++++++ 3 files changed, 56 insertions(+), 33 deletions(-) create mode 100644 slf4cats-monix/src/main/scala/slf4cats/monix/ContextLoggerMonix.scala diff --git a/build.sbt b/build.sbt index 0f1dc24..7818d81 100644 --- a/build.sbt +++ b/build.sbt @@ -51,14 +51,23 @@ lazy val slf4catsImpl = project ) .dependsOn(slf4catsApi) +lazy val slf4catsMonix = project + .in(file("slf4cats-monix")) + .settings( + name := "slf4cats-monix", + libraryDependencies ++= Seq( + "io.monix" %% "monix" % Version.monix, + "com.olegpy" %% "meow-mtl-monix" % Version.meowMtl, + ), + ) + .dependsOn(slf4catsImpl) + lazy val slf4catsExample = project .in(file("slf4cats-example")) .settings( name := "slf4cats-example", libraryDependencies ++= Seq( "ch.qos.logback" % "logback-classic" % Version.logback, - "io.monix" %% "monix" % Version.monix, - "com.olegpy" %% "meow-mtl-monix" % Version.meowMtl, ), ) - .dependsOn(slf4catsImpl) + .dependsOn(slf4catsMonix) diff --git a/slf4cats-example/src/main/scala/slf4cats/example/Main.scala b/slf4cats-example/src/main/scala/slf4cats/example/Main.scala index 2d4d620..b4dc708 100644 --- a/slf4cats-example/src/main/scala/slf4cats/example/Main.scala +++ b/slf4cats-example/src/main/scala/slf4cats/example/Main.scala @@ -3,38 +3,10 @@ package slf4cats.example import java.security.InvalidParameterException import cats.effect._ -import com.olegpy.meow.monix._ import monix.eval._ import slf4cats.api._ import slf4cats.impl._ - -import scala.reflect.ClassTag - -object MonixLog { - def make(logger: org.slf4j.Logger)( - taskLocalContext: TaskLocal[ContextLogger.Context[Task]], - ): ContextLogger[Task] = { - taskLocalContext.runLocal { implicit ev => - ContextLogger.fromLogger(logger) - } - } - - def make(name: String)( - taskLocalContext: TaskLocal[ContextLogger.Context[Task]], - ): ContextLogger[Task] = { - taskLocalContext.runLocal { implicit ev => - ContextLogger.fromName(name) - } - } - - def make[T]( - taskLocalContext: TaskLocal[ContextLogger.Context[Task]], - )(implicit classTag: ClassTag[T]): ContextLogger[Task] = { - taskLocalContext.runLocal { implicit ev => - ContextLogger.fromClass() - } - } -} +import slf4cats.monix.ContextLoggerMonix object Main extends TaskApp { @@ -53,7 +25,7 @@ object Main extends TaskApp { def init: Task[Unit] = for { mdc <- TaskLocal(ContextLogger.Context.empty[Task]) - logger = MonixLog.make[Main.type](mdc) + logger = ContextLoggerMonix.make[Main.type](mdc) result <- program(logger) } yield result @@ -68,6 +40,13 @@ object Main extends TaskApp { _ <- logger.withArg("x", 123).withArg("o", o).use { logger.withArg("x", List(1, 2, 3)).info("Hello2 meow") } + _ <- logger + .withArg( + "xxxx", + 1, + Some((_: Any) => throw new RuntimeException("asdf")), + ) + .info("yyyy") } yield () } diff --git a/slf4cats-monix/src/main/scala/slf4cats/monix/ContextLoggerMonix.scala b/slf4cats-monix/src/main/scala/slf4cats/monix/ContextLoggerMonix.scala new file mode 100644 index 0000000..c63d9cb --- /dev/null +++ b/slf4cats-monix/src/main/scala/slf4cats/monix/ContextLoggerMonix.scala @@ -0,0 +1,35 @@ +package slf4cats.monix + +import com.olegpy.meow.monix._ +import monix.eval.{Task, TaskLocal} +import slf4cats.api.ContextLogger +import slf4cats.impl.ContextLogger + +import scala.reflect.ClassTag + +object ContextLoggerMonix { + + def make(logger: org.slf4j.Logger)( + taskLocalContext: TaskLocal[ContextLogger.Context[Task]], + ): ContextLogger[Task] = { + taskLocalContext.runLocal { implicit ev => + ContextLogger.fromLogger(logger) + } + } + + def make(name: String)( + taskLocalContext: TaskLocal[ContextLogger.Context[Task]], + ): ContextLogger[Task] = { + taskLocalContext.runLocal { implicit ev => + ContextLogger.fromName(name) + } + } + + def make[T]( + taskLocalContext: TaskLocal[ContextLogger.Context[Task]], + )(implicit classTag: ClassTag[T]): ContextLogger[Task] = { + taskLocalContext.runLocal { implicit ev => + ContextLogger.fromClass() + } + } +} From a83101f77332bc3a5453b021c1e3aeff2544877f Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Ji=C5=99=C3=AD=20Veselka?= Date: Mon, 13 Jan 2020 17:11:58 +0100 Subject: [PATCH 35/35] Introducing LogEncoder (#5) * Introduced LogEncoder * Update slf4cats-impl/src/main/scala/slf4cats/encoders/jackson/package.scala Co-Authored-By: Ondra Pelech * Update slf4cats-api/src/main/scala/slf4cats/api/slf4cats-api.scala Co-Authored-By: Ondra Pelech * Update slf4cats-api/src/main/scala/slf4cats/api/slf4cats-api.scala Co-Authored-By: Ondra Pelech * Added circe encoder and fixes from review * Introduced slf4cats-jackson project * Changed printer used for circe encoding Co-authored-by: Ondra Pelech --- .gitignore | 5 ++- build.sbt | 26 ++++++++++++- .../scala/slf4cats/api/slf4cats-api.scala | 37 +++++++++---------- .../slf4cats/encoders/circe/package.scala | 9 +++++ .../main/scala/slf4cats/example/Main.scala | 27 +++++++++++--- .../scala/slf4cats/impl/ContextLogger.scala | 37 +++++-------------- .../slf4cats/encoders/jackson/package.scala | 13 +++++++ 7 files changed, 97 insertions(+), 57 deletions(-) create mode 100644 slf4cats-circe/src/main/scala/slf4cats/encoders/circe/package.scala create mode 100644 slf4cats-jackson/src/main/scala/slf4cats/encoders/jackson/package.scala diff --git a/.gitignore b/.gitignore index 0a3e62d..5ea571b 100644 --- a/.gitignore +++ b/.gitignore @@ -1,2 +1,3 @@ -target -/log +target +/log +.idea/ diff --git a/build.sbt b/build.sbt index 7818d81..3181a94 100644 --- a/build.sbt +++ b/build.sbt @@ -13,6 +13,7 @@ lazy val Version = new { val catsMtl = "0.7.0" val catsEffect = "2.0.0" val meowMtl = "0.4.0" + val circe = "0.13.0-M2" } lazy val root = project @@ -24,6 +25,7 @@ lazy val root = project .aggregate( slf4catsApi, slf4catsImpl, + slf4catsCirce, slf4catsExample, ) @@ -43,7 +45,6 @@ lazy val slf4catsImpl = project .settings( name := "slf4cats-impl", libraryDependencies ++= Seq( - "com.fasterxml.jackson.module" %% "jackson-module-scala" % Version.jacksonScala, "net.logstash.logback" % "logstash-logback-encoder" % Version.logstashLogback, "org.typelevel" %% "cats-mtl-core" % Version.catsMtl, "org.typelevel" %% "cats-effect" % Version.catsEffect, @@ -62,12 +63,33 @@ lazy val slf4catsMonix = project ) .dependsOn(slf4catsImpl) +lazy val slf4catsCirce = project + .in(file("slf4cats-circe")) + .settings( + name := "slf4cats-circe", + libraryDependencies ++= Seq( + "io.circe" %% "circe-core" % Version.circe, + ), + ) + .dependsOn(slf4catsApi) + +lazy val slf4catsJackson = project + .in(file("slf4cats-jackson")) + .settings( + name := "slf4cats-jackson", + libraryDependencies ++= Seq( + "com.fasterxml.jackson.module" %% "jackson-module-scala" % Version.jacksonScala, + ), + ) + .dependsOn(slf4catsApi) + lazy val slf4catsExample = project .in(file("slf4cats-example")) .settings( name := "slf4cats-example", libraryDependencies ++= Seq( "ch.qos.logback" % "logback-classic" % Version.logback, + "io.circe" %% "circe-generic" % Version.circe, ), ) - .dependsOn(slf4catsMonix) + .dependsOn(slf4catsMonix, slf4catsCirce, slf4catsJackson) diff --git a/slf4cats-api/src/main/scala/slf4cats/api/slf4cats-api.scala b/slf4cats-api/src/main/scala/slf4cats/api/slf4cats-api.scala index bf7bc7b..b288280 100644 --- a/slf4cats-api/src/main/scala/slf4cats/api/slf4cats-api.scala +++ b/slf4cats-api/src/main/scala/slf4cats/api/slf4cats-api.scala @@ -3,35 +3,24 @@ package slf4cats.api import cats.effect.Sync import org.slf4j.Marker -trait LoggingContext[F[_]] { - type Self <: LoggingContext[F] +trait ArgumentsBuilder[F[_]] { + type Self <: ArgumentsBuilder[F] def withArg[A]( name: String, value: => A, - toJson: Option[A => String] = None, - ): Self + )(implicit logEncoder: LogEncoder[A]): Self def withComputed[A]( name: String, value: F[A], - toJson: Option[A => String] = None, - ): Self - def withArgs[A](map: Map[String, A], toJson: Option[A => String] = None): Self + )(implicit logEncoder: LogEncoder[A]): Self + def withArgs[A](map: Map[String, A])(implicit logEncoder: LogEncoder[A]): Self +} + +trait LoggingContext[F[_]] extends ArgumentsBuilder[F] { def use[A](inner: F[A]): F[A] } -trait Logger[F[_]] { - type Self <: Logger[F] - def withArg[A]( - name: String, - value: => A, - toJson: Option[A => String] = None, - ): Self - def withComputed[A]( - name: String, - value: F[A], - toJson: Option[A => String] = None, - ): Self - def withArgs[A](map: Map[String, A], toJson: Option[A => String] = None): Self +trait Logger[F[_]] extends ArgumentsBuilder[F] { def info: LoggerInfo[F] def warn: LoggerWarn[F] } @@ -40,6 +29,14 @@ trait ContextLogger[F[_]] extends LoggingContext[F] with Logger[F] { type Self <: ContextLogger[F] } +trait LogEncoder[-A] { + def encode(a: A): String +} + +object LogEncoder { + def apply[A](implicit e: LogEncoder[A]): LogEncoder[A] = e +} + trait LoggerCommand[F[_]] { // could be made available if there's interest diff --git a/slf4cats-circe/src/main/scala/slf4cats/encoders/circe/package.scala b/slf4cats-circe/src/main/scala/slf4cats/encoders/circe/package.scala new file mode 100644 index 0000000..b2defe9 --- /dev/null +++ b/slf4cats-circe/src/main/scala/slf4cats/encoders/circe/package.scala @@ -0,0 +1,9 @@ +package slf4cats.encoders + +import io.circe.Printer +import slf4cats.api.LogEncoder + +package object circe { + import io.circe.Encoder + implicit def convertEncoder[A](implicit circeEncoder: Encoder[A]): LogEncoder[A] = (a: A) => Printer.noSpaces.print(circeEncoder(a)) +} diff --git a/slf4cats-example/src/main/scala/slf4cats/example/Main.scala b/slf4cats-example/src/main/scala/slf4cats/example/Main.scala index b4dc708..f6a9df6 100644 --- a/slf4cats-example/src/main/scala/slf4cats/example/Main.scala +++ b/slf4cats-example/src/main/scala/slf4cats/example/Main.scala @@ -30,6 +30,7 @@ object Main extends TaskApp { } yield result def program(logger: ContextLogger[Task]): Task[Unit] = { + import slf4cats.encoders.jackson._ val ex = new InvalidParameterException("BOOOOOM") for { _ <- logger @@ -37,17 +38,33 @@ object Main extends TaskApp { .withArg("o", o) .info("Hello Monix") _ <- logger.warn("Hello MTL", ex) + // test shadowing of arg "x" _ <- logger.withArg("x", 123).withArg("o", o).use { logger.withArg("x", List(1, 2, 3)).info("Hello2 meow") } + // test context passing on child fibers + _ <- logger.withArg("o", o).use { + logger.withArg("x", List("x")).info("Hello in child fiber").start.flatMap { _ => + logger.withArg("y", List("y")).info("Hello back in parent fiber") + } + } + // test circe encoder + _ <- logCirce(logger) + // test when LogEncoder throws an error _ <- logger - .withArg( - "xxxx", - 1, - Some((_: Any) => throw new RuntimeException("asdf")), - ) + .withArg("xxxx",1)((_: Any) => throw new RuntimeException("asdf")) .info("yyyy") } yield () } + private def logCirce(logger: ContextLogger[Task]): Task[Unit] = { + import slf4cats.encoders.circe._ + import io.circe._ + import io.circe.generic.semiauto._ + implicit val byteArrayEncoder: Encoder[Array[Byte]] = (_: Array[Byte]) => Json.Null + implicit val aDecoder: Encoder[A] = deriveEncoder + implicitly[Encoder[Array[Byte]]] // to avoid incorrect error that byteArrayEncoder is never used + logger.withArg("circe", A(1, "b", Array(1, 2))).info("Logging with circe-encoded class") + } + } diff --git a/slf4cats-impl/src/main/scala/slf4cats/impl/ContextLogger.scala b/slf4cats-impl/src/main/scala/slf4cats/impl/ContextLogger.scala index a8dce92..1df9254 100644 --- a/slf4cats-impl/src/main/scala/slf4cats/impl/ContextLogger.scala +++ b/slf4cats-impl/src/main/scala/slf4cats/impl/ContextLogger.scala @@ -4,8 +4,6 @@ import cats._ import cats.effect._ import cats.implicits._ import cats.mtl._ -import com.fasterxml.jackson.databind.ObjectMapper -import com.fasterxml.jackson.module.scala.DefaultScalaModule import net.logstash.logback.marker.Markers import org.slf4j.{LoggerFactory, Marker} import slf4cats.api._ @@ -16,13 +14,6 @@ import scala.util.control.NonFatal object ContextLogger { object JsonInString { - - val defaultToJson: Any => String = { - val jackson = new ObjectMapper() - jackson.registerModule(DefaultScalaModule) - jackson.writeValueAsString - } - private[ContextLogger] def make[F[_], A]( toJson: A => String, )(x: A)(implicit F: Sync[F]): F[String] = { @@ -122,7 +113,6 @@ object ContextLogger { private class ContextLoggerImpl[F[_]]( underlying: org.slf4j.Logger, context: Map[String, F[F[String]]], - toJsonGlobal: Any => String, )( implicit FApplicativeLocal: ApplicativeLocal[F, Context[F]], FAsync: Async[F], @@ -139,47 +129,40 @@ object ContextLogger { override def withArg[A]( name: String, value: => A, - toJson: Option[A => String] = None, - ): ContextLogger[F] = + )(implicit logEncoder: LogEncoder[A]): ContextLogger[F] = withComputed( name, FAsync.delay { value }, - toJson, ) override def withComputed[A]( name: String, value: F[A], - toJson: Option[A => String] = None, - ): ContextLogger[F] = { + )(implicit logEncoder: LogEncoder[A]): ContextLogger[F] = { val memoizedJson = Async.memoize( - value.flatMap(JsonInString.make(toJson.getOrElse(toJsonGlobal))(_)), + value.flatMap(JsonInString.make(logEncoder.encode)(_)), ) new ContextLoggerImpl[F]( underlying, context + ((name, memoizedJson)), - toJsonGlobal, ) } override def withArgs[A]( map: Map[String, A], - toJson: Option[A => String] = None, - ): ContextLogger[F] = { - val toJsonLocal = toJson.getOrElse(toJsonGlobal) + )(implicit logEncoder: LogEncoder[A]): ContextLogger[F] = { new ContextLoggerImpl[F]( underlying, context ++ map .mapValues(v => Async.memoize( JsonInString - .make(toJsonLocal)(v), + .make(logEncoder.encode)(v), ), ), - toJsonGlobal, ) } @@ -192,7 +175,6 @@ object ContextLogger { def fromLogger[F[_]]( logger: org.slf4j.Logger, - toJson: Option[Any => String] = None, )( implicit FAsync: Async[F], FApplicativeLocal: ApplicativeLocal[F, Context[F]], @@ -200,23 +182,22 @@ object ContextLogger { new ContextLoggerImpl[F]( logger, Map.empty, - toJson.getOrElse(JsonInString.defaultToJson), ) } - def fromName[F[_]](name: String, toJson: Option[Any => String] = None)( + def fromName[F[_]](name: String)( implicit FAsync: Async[F], FApplicativeAsk: ApplicativeLocal[F, Context[F]], ): ContextLogger[F] = { - fromLogger(LoggerFactory.getLogger(name), toJson) + fromLogger(LoggerFactory.getLogger(name)) } - def fromClass[F[_], T](toJson: Option[Any => String] = None)( + def fromClass[F[_], T]()( implicit classTag: ClassTag[T], FAsync: Async[F], FApplicativeAsk: ApplicativeLocal[F, Context[F]], ): ContextLogger[F] = { - fromLogger(LoggerFactory.getLogger(classTag.runtimeClass), toJson) + fromLogger(LoggerFactory.getLogger(classTag.runtimeClass)) } } diff --git a/slf4cats-jackson/src/main/scala/slf4cats/encoders/jackson/package.scala b/slf4cats-jackson/src/main/scala/slf4cats/encoders/jackson/package.scala new file mode 100644 index 0000000..e5d2ca4 --- /dev/null +++ b/slf4cats-jackson/src/main/scala/slf4cats/encoders/jackson/package.scala @@ -0,0 +1,13 @@ +package slf4cats.encoders + +import com.fasterxml.jackson.databind.ObjectMapper +import com.fasterxml.jackson.module.scala.DefaultScalaModule +import slf4cats.api.LogEncoder + +package object jackson { + implicit def encoder: LogEncoder[Any] = { + val jackson = new ObjectMapper() + jackson.registerModule(DefaultScalaModule) + jackson.writeValueAsString + } +}