diff --git a/README.md b/README.md index f20727f9..ba906255 100644 --- a/README.md +++ b/README.md @@ -167,6 +167,10 @@ class LoggerUsingService[F[_]: LoggerFactory: Monad] { new LoggerUsingService[IO].use("foo") ``` +## Using log4cats in tests + +See [here](testing/README.md) for details + ## CVE-2021-44228 ("log4shell") log4cats is not directly susceptible to CVS-2021-44228. The diff --git a/core/shared/src/main/scala/org/typelevel/log4cats/extras/LogMessage.scala b/core/shared/src/main/scala/org/typelevel/log4cats/extras/LogMessage.scala index c8f7ebb3..9d549766 100644 --- a/core/shared/src/main/scala/org/typelevel/log4cats/extras/LogMessage.scala +++ b/core/shared/src/main/scala/org/typelevel/log4cats/extras/LogMessage.scala @@ -18,11 +18,27 @@ package org.typelevel.log4cats.extras import cats._ import cats.syntax.all._ +import org.typelevel.log4cats.Logger final case class LogMessage(level: LogLevel, t: Option[Throwable], message: String) - object LogMessage { implicit val logMessageShow: Show[LogMessage] = Show.show[LogMessage](l => show"LogMessage(${l.level},${l.t.map(_.getMessage)},${l.message})") + def log[F[_]](sm: LogMessage, l: Logger[F]): F[Unit] = sm match { + case LogMessage(LogLevel.Trace, Some(t), m) => l.trace(t)(m) + case LogMessage(LogLevel.Trace, None, m) => l.trace(m) + + case LogMessage(LogLevel.Debug, Some(t), m) => l.debug(t)(m) + case LogMessage(LogLevel.Debug, None, m) => l.debug(m) + + case LogMessage(LogLevel.Info, Some(t), m) => l.info(t)(m) + case LogMessage(LogLevel.Info, None, m) => l.info(m) + + case LogMessage(LogLevel.Warn, Some(t), m) => l.warn(t)(m) + case LogMessage(LogLevel.Warn, None, m) => l.warn(m) + + case LogMessage(LogLevel.Error, Some(t), m) => l.error(t)(m) + case LogMessage(LogLevel.Error, None, m) => l.error(m) + } } diff --git a/core/shared/src/main/scala/org/typelevel/log4cats/extras/README.md b/core/shared/src/main/scala/org/typelevel/log4cats/extras/README.md new file mode 100644 index 00000000..ad50ed74 --- /dev/null +++ b/core/shared/src/main/scala/org/typelevel/log4cats/extras/README.md @@ -0,0 +1,48 @@ +Important notes about `Writer*Logger`s +====================================== + +The loggers provided here backed by `Writer` and `WriterT` come with some important caveats that +you should be aware of before using. + +General Notes +------------- + +> **Note** +> These loggers tie their logs to the lifecycle of the return value, so they're generally only useful +when the logs have a similar lifecycle. + +> **Warning** +> These loggers should not be used in situations where the logs would be needed if an error occurs (including timeouts). + +Basically, they're a way to use `Writer` or `WriterT` with the `log4cats` API. No additional guarantees +are provided. Annotating the happy path is one example of a good use-case for these loggers. + +Better alternatives are provided by the `testing` module: +- If a `SelfAwareLogger` is needed for test code, consider +`org.typelevel.log4cats.testing.TestingLogger` over `WriterLogger` + +- If a `SelfAwareStructuredLogger` is needed for test code, consider +`org.typelevel.log4cats.testing.StructuredTestingLogger` over `WriterStructuredLogger` + +`WriterLogger` / `WriterStructureLogger` +---------------------------------------- + +> **Warning** +> Expect to lose logs if an exception occurs + +These are built using `Writer`, which does not directly interact with effects, so expect to do a +non-trivial amount of plumbing if you're planning on using them. Otherwise, if the logs don't matter +in the presence of errors in the context you're using them, they're fine. + +`WriterTLogger` / `WriterTStructuredLogger` +------------------------------------------- + +These are built using `WriterT`, and are much easier to use with effects. Running the `WriterT` +instance will yield a value of type `F[(G[LogMessage], A)]`. + +> **Warning** +> Logged messages can be materialized if *and only if* `F succeeds` + +Unfortunately, because of the way that cancellation (and thus timeouts) is handled by +`cats.effect.IO`, in practice `WriterT` isn't a great fit for anything which can timeout. + diff --git a/core/shared/src/main/scala/org/typelevel/log4cats/extras/StructuredLogMessage.scala b/core/shared/src/main/scala/org/typelevel/log4cats/extras/StructuredLogMessage.scala new file mode 100644 index 00000000..df62898e --- /dev/null +++ b/core/shared/src/main/scala/org/typelevel/log4cats/extras/StructuredLogMessage.scala @@ -0,0 +1,51 @@ +/* + * Copyright 2018 Typelevel + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + +package org.typelevel.log4cats.extras + +import cats.Show +import cats.syntax.all._ +import org.typelevel.log4cats.StructuredLogger + +final case class StructuredLogMessage( + level: LogLevel, + context: Map[String, String], + throwableOpt: Option[Throwable], + message: String +) +object StructuredLogMessage { + def log[F[_]](sm: StructuredLogMessage, l: StructuredLogger[F]): F[Unit] = sm match { + case StructuredLogMessage(LogLevel.Trace, ctx, Some(t), m) => l.trace(ctx, t)(m) + case StructuredLogMessage(LogLevel.Trace, ctx, None, m) => l.trace(ctx)(m) + + case StructuredLogMessage(LogLevel.Debug, ctx, Some(t), m) => l.debug(ctx, t)(m) + case StructuredLogMessage(LogLevel.Debug, ctx, None, m) => l.debug(ctx)(m) + + case StructuredLogMessage(LogLevel.Info, ctx, Some(t), m) => l.info(ctx, t)(m) + case StructuredLogMessage(LogLevel.Info, ctx, None, m) => l.info(ctx)(m) + + case StructuredLogMessage(LogLevel.Warn, ctx, Some(t), m) => l.warn(ctx, t)(m) + case StructuredLogMessage(LogLevel.Warn, ctx, None, m) => l.warn(ctx)(m) + + case StructuredLogMessage(LogLevel.Error, ctx, Some(t), m) => l.error(ctx, t)(m) + case StructuredLogMessage(LogLevel.Error, ctx, None, m) => l.error(ctx)(m) + } + + implicit val structuredLogMessageShow: Show[StructuredLogMessage] = + Show.show[StructuredLogMessage] { l => + show"StructuredLogMessage(${l.level},${l.context},${l.throwableOpt.map(_.getMessage)},${l.message})" + } +} diff --git a/core/shared/src/main/scala/org/typelevel/log4cats/extras/WriterLogger.scala b/core/shared/src/main/scala/org/typelevel/log4cats/extras/WriterLogger.scala index 7d94b927..8fc79b76 100644 --- a/core/shared/src/main/scala/org/typelevel/log4cats/extras/WriterLogger.scala +++ b/core/shared/src/main/scala/org/typelevel/log4cats/extras/WriterLogger.scala @@ -21,6 +21,16 @@ import cats.data._ import cats.syntax.all._ import org.typelevel.log4cats._ +/** + * A `SelfAwareLogger` implemented using `cats.data.Writer`. + * + * >>> WARNING: READ BEFORE USAGE! <<< + * /~https://github.com/typelevel/log4cats/blob/main/core/shared/src/main/scala/org/typelevel/log4cats/extras/README.md + * >>> WARNING: READ BEFORE USAGE! <<< + * + * If a `SelfAwareLogger` is needed for test code, the `testing` module provides a better option: + * `org.typelevel.log4cats.testing.TestingLogger` + */ object WriterLogger { def apply[G[_]: Alternative]( @@ -29,89 +39,14 @@ object WriterLogger { infoEnabled: Boolean = true, warnEnabled: Boolean = true, errorEnabled: Boolean = true - ): SelfAwareLogger[Writer[G[LogMessage], *]] = { - implicit val monoidGLogMessage: Monoid[G[LogMessage]] = Alternative[G].algebra[LogMessage] - new SelfAwareLogger[Writer[G[LogMessage], *]] { - def isTraceEnabled: Writer[G[LogMessage], Boolean] = - Writer.value[G[LogMessage], Boolean](traceEnabled) - def isDebugEnabled: Writer[G[LogMessage], Boolean] = - Writer.value[G[LogMessage], Boolean](debugEnabled) - def isInfoEnabled: Writer[G[LogMessage], Boolean] = - Writer.value[G[LogMessage], Boolean](infoEnabled) - def isWarnEnabled: Writer[G[LogMessage], Boolean] = - Writer.value[G[LogMessage], Boolean](warnEnabled) - def isErrorEnabled: Writer[G[LogMessage], Boolean] = - Writer.value[G[LogMessage], Boolean](errorEnabled) - - def debug(t: Throwable)(message: => String): Writer[G[LogMessage], Unit] = - if (debugEnabled) - Writer.tell(Alternative[G].pure(LogMessage(LogLevel.Debug, t.some, message))) - else Writer.value[G[LogMessage], Unit](()) - def error(t: Throwable)(message: => String): Writer[G[LogMessage], Unit] = - if (errorEnabled) - Writer.tell(Alternative[G].pure(LogMessage(LogLevel.Error, t.some, message))) - else Writer.value[G[LogMessage], Unit](()) - def info(t: Throwable)(message: => String): Writer[G[LogMessage], Unit] = - if (infoEnabled) - Writer.tell(Alternative[G].pure(LogMessage(LogLevel.Info, t.some, message))) - else Writer.value[G[LogMessage], Unit](()) - def trace(t: Throwable)(message: => String): Writer[G[LogMessage], Unit] = - if (traceEnabled) - Writer.tell(Alternative[G].pure(LogMessage(LogLevel.Trace, t.some, message))) - else Writer.value[G[LogMessage], Unit](()) - def warn(t: Throwable)(message: => String): Writer[G[LogMessage], Unit] = - if (warnEnabled) - Writer.tell(Alternative[G].pure(LogMessage(LogLevel.Warn, t.some, message))) - else Writer.value[G[LogMessage], Unit](()) - def debug(message: => String): Writer[G[LogMessage], Unit] = - if (debugEnabled) - Writer.tell(Alternative[G].pure(LogMessage(LogLevel.Debug, None, message))) - else Writer.value[G[LogMessage], Unit](()) - def error(message: => String): Writer[G[LogMessage], Unit] = - if (errorEnabled) - Writer.tell(Alternative[G].pure(LogMessage(LogLevel.Error, None, message))) - else Writer.value[G[LogMessage], Unit](()) - def info(message: => String): Writer[G[LogMessage], Unit] = - if (infoEnabled) Writer.tell(Alternative[G].pure(LogMessage(LogLevel.Info, None, message))) - else Writer.value[G[LogMessage], Unit](()) - def trace(message: => String): Writer[G[LogMessage], Unit] = - if (traceEnabled) - Writer.tell(Alternative[G].pure(LogMessage(LogLevel.Trace, None, message))) - else Writer.value[G[LogMessage], Unit](()) - def warn(message: => String): Writer[G[LogMessage], Unit] = - if (warnEnabled) Writer.tell(Alternative[G].pure(LogMessage(LogLevel.Warn, None, message))) - else Writer.value[G[LogMessage], Unit](()) - } - } + ): SelfAwareLogger[Writer[G[LogMessage], *]] = + WriterTLogger[cats.Id, G](traceEnabled, debugEnabled, infoEnabled, warnEnabled, errorEnabled) def run[F[_]: Applicative, G[_]: Foldable](l: Logger[F]): Writer[G[LogMessage], *] ~> F = - new ~>[Writer[G[LogMessage], *], F] { - def logMessage(logMessage: LogMessage): F[Unit] = logMessage match { - case LogMessage(LogLevel.Error, Some(t), m) => - l.error(t)(m) - case LogMessage(LogLevel.Error, None, m) => - l.error(m) - case LogMessage(LogLevel.Warn, Some(t), m) => - l.warn(t)(m) - case LogMessage(LogLevel.Warn, None, m) => - l.warn(m) - case LogMessage(LogLevel.Info, Some(t), m) => - l.info(t)(m) - case LogMessage(LogLevel.Info, None, m) => - l.info(m) - case LogMessage(LogLevel.Debug, Some(t), m) => - l.debug(t)(m) - case LogMessage(LogLevel.Debug, None, m) => - l.debug(m) - case LogMessage(LogLevel.Trace, Some(t), m) => - l.trace(t)(m) - case LogMessage(LogLevel.Trace, None, m) => - l.trace(m) - } - + new (Writer[G[LogMessage], *] ~> F) { def apply[A](fa: Writer[G[LogMessage], A]): F[A] = { val (toLog, out) = fa.run - toLog.traverse_(logMessage).as(out) + toLog.traverse_(LogMessage.log(_, l)).as(out) } } } diff --git a/core/shared/src/main/scala/org/typelevel/log4cats/extras/WriterStructuredLogger.scala b/core/shared/src/main/scala/org/typelevel/log4cats/extras/WriterStructuredLogger.scala new file mode 100644 index 00000000..91f6db29 --- /dev/null +++ b/core/shared/src/main/scala/org/typelevel/log4cats/extras/WriterStructuredLogger.scala @@ -0,0 +1,59 @@ +/* + * Copyright 2018 Typelevel + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + +package org.typelevel.log4cats.extras + +import cats.data.Writer +import cats.syntax.all._ +import cats.{~>, Alternative, Applicative, Foldable, Id} +import org.typelevel.log4cats.{SelfAwareStructuredLogger, StructuredLogger} + +/** + * A `SelfAwareStructuredLogger` implemented using `cats.data.Writer`. + * + * >>> WARNING: READ BEFORE USAGE! <<< + * /~https://github.com/typelevel/log4cats/blob/main/core/shared/src/main/scala/org/typelevel/log4cats/extras/README.md + * >>> WARNING: READ BEFORE USAGE! <<< + * + * If a `SelfAwareStructuredLogger` is needed for test code, the `testing` module provides a better + * option: `org.typelevel.log4cats.testing.StructuredTestingLogger` + */ +object WriterStructuredLogger { + def apply[G[_]: Alternative]( + traceEnabled: Boolean = true, + debugEnabled: Boolean = true, + infoEnabled: Boolean = true, + warnEnabled: Boolean = true, + errorEnabled: Boolean = true + ): SelfAwareStructuredLogger[Writer[G[StructuredLogMessage], *]] = + WriterTStructuredLogger[Id, G]( + traceEnabled, + debugEnabled, + infoEnabled, + warnEnabled, + errorEnabled + ) + + def run[F[_]: Applicative, G[_]: Foldable]( + l: StructuredLogger[F] + ): Writer[G[StructuredLogMessage], *] ~> F = + new (Writer[G[StructuredLogMessage], *] ~> F) { + def apply[A](fa: Writer[G[StructuredLogMessage], A]): F[A] = { + val (toLog, out) = fa.run + toLog.traverse_(StructuredLogMessage.log(_, l)).as(out) + } + } +} diff --git a/core/shared/src/main/scala/org/typelevel/log4cats/extras/WriterTLogger.scala b/core/shared/src/main/scala/org/typelevel/log4cats/extras/WriterTLogger.scala index d7077d0d..6452e6a2 100644 --- a/core/shared/src/main/scala/org/typelevel/log4cats/extras/WriterTLogger.scala +++ b/core/shared/src/main/scala/org/typelevel/log4cats/extras/WriterTLogger.scala @@ -22,10 +22,14 @@ import cats.syntax.all._ import org.typelevel.log4cats._ /** - * >>> WARNING READ BEFORE USAGE! <<< This logger will NOT log anything if `F` fails! + * A `SelfAwareLogger` implemented using `cats.data.WriterT`. * - * Running the `WriterT` instance will yield a value of type `F[(G[LogMessage], A)]`. As a result, - * the logged messages can be materialized if and only `F` succeeds. + * >>> WARNING: READ BEFORE USAGE! <<< + * /~https://github.com/typelevel/log4cats/blob/main/core/shared/src/main/scala/org/typelevel/log4cats/extras/README.md + * >>> WARNING: READ BEFORE USAGE! <<< + * + * If a `SelfAwareLogger` is needed for test code, the `testing` module provides a better option: + * `org.typelevel.log4cats.testing.TestingLogger` */ object WriterTLogger { def apply[F[_]: Applicative, G[_]: Alternative]( @@ -85,28 +89,10 @@ object WriterTLogger { } def run[F[_]: Monad, G[_]: Foldable](l: Logger[F]): WriterT[F, G[LogMessage], *] ~> F = - new ~>[WriterT[F, G[LogMessage], *], F] { - override def apply[A](fa: WriterT[F, G[LogMessage], A]): F[A] = { - def logMessage(logMessage: LogMessage): F[Unit] = logMessage match { - case LogMessage(LogLevel.Trace, Some(t), m) => l.trace(t)(m) - case LogMessage(LogLevel.Trace, None, m) => l.trace(m) - - case LogMessage(LogLevel.Debug, Some(t), m) => l.debug(t)(m) - case LogMessage(LogLevel.Debug, None, m) => l.debug(m) - - case LogMessage(LogLevel.Info, Some(t), m) => l.info(t)(m) - case LogMessage(LogLevel.Info, None, m) => l.info(m) - - case LogMessage(LogLevel.Warn, Some(t), m) => l.warn(t)(m) - case LogMessage(LogLevel.Warn, None, m) => l.warn(m) - - case LogMessage(LogLevel.Error, Some(t), m) => l.error(t)(m) - case LogMessage(LogLevel.Error, None, m) => l.error(m) - } - + new (WriterT[F, G[LogMessage], *] ~> F) { + override def apply[A](fa: WriterT[F, G[LogMessage], A]): F[A] = fa.run.flatMap { case (toLog, out) => - toLog.traverse_(logMessage).as(out) + toLog.traverse_(LogMessage.log(_, l)).as(out) } - } } } diff --git a/core/shared/src/main/scala/org/typelevel/log4cats/extras/WriterTStructuredLogger.scala b/core/shared/src/main/scala/org/typelevel/log4cats/extras/WriterTStructuredLogger.scala new file mode 100644 index 00000000..5403653e --- /dev/null +++ b/core/shared/src/main/scala/org/typelevel/log4cats/extras/WriterTStructuredLogger.scala @@ -0,0 +1,151 @@ +/* + * Copyright 2018 Typelevel + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + +package org.typelevel.log4cats.extras + +import cats.data.WriterT +import cats.kernel.Monoid +import cats.syntax.all._ +import cats.{~>, Alternative, Applicative, Foldable, Monad} +import org.typelevel.log4cats.{SelfAwareStructuredLogger, StructuredLogger} + +/** + * A `SelfAwareStructuredLogger` implemented using `cats.data.WriterT`. + * + * >>> WARNING: READ BEFORE USAGE! <<< + * /~https://github.com/typelevel/log4cats/blob/main/core/shared/src/main/scala/org/typelevel/log4cats/extras/README.md + * >>> WARNING: READ BEFORE USAGE! <<< + * + * If a `SelfAwareStructuredLogger` is needed for test code, the `testing` module provides a better + * option: `org.typelevel.log4cats.testing.StructuredTestingLogger` + */ +object WriterTStructuredLogger { + def apply[F[_]: Applicative, G[_]: Alternative]( + traceEnabled: Boolean = true, + debugEnabled: Boolean = true, + infoEnabled: Boolean = true, + warnEnabled: Boolean = true, + errorEnabled: Boolean = true + ): SelfAwareStructuredLogger[WriterT[F, G[StructuredLogMessage], *]] = + new SelfAwareStructuredLogger[WriterT[F, G[StructuredLogMessage], *]] { + type LoggerF[A] = WriterT[F, G[StructuredLogMessage], A] + + override def isTraceEnabled: LoggerF[Boolean] = isEnabled(traceEnabled) + + override def isDebugEnabled: LoggerF[Boolean] = isEnabled(debugEnabled) + + override def isInfoEnabled: LoggerF[Boolean] = isEnabled(infoEnabled) + + override def isWarnEnabled: LoggerF[Boolean] = isEnabled(warnEnabled) + + override def isErrorEnabled: LoggerF[Boolean] = isEnabled(errorEnabled) + + override def trace(t: Throwable)(message: => String): LoggerF[Unit] = + build(Map.empty, traceEnabled, LogLevel.Trace, t.some, message) + + override def trace(message: => String): LoggerF[Unit] = + build(Map.empty, traceEnabled, LogLevel.Trace, None, message) + + override def debug(t: Throwable)(message: => String): LoggerF[Unit] = + build(Map.empty, debugEnabled, LogLevel.Debug, t.some, message) + + override def debug(message: => String): LoggerF[Unit] = + build(Map.empty, debugEnabled, LogLevel.Debug, None, message) + + override def info(t: Throwable)(message: => String): LoggerF[Unit] = + build(Map.empty, infoEnabled, LogLevel.Info, t.some, message) + + override def info(message: => String): LoggerF[Unit] = + build(Map.empty, infoEnabled, LogLevel.Info, None, message) + + override def warn(t: Throwable)(message: => String): LoggerF[Unit] = + build(Map.empty, warnEnabled, LogLevel.Warn, t.some, message) + + override def warn(message: => String): LoggerF[Unit] = + build(Map.empty, warnEnabled, LogLevel.Warn, None, message) + + override def error(t: Throwable)(message: => String): LoggerF[Unit] = + build(Map.empty, errorEnabled, LogLevel.Error, t.some, message) + + override def error(message: => String): LoggerF[Unit] = + build(Map.empty, errorEnabled, LogLevel.Error, None, message) + + private def isEnabled(enabled: Boolean): LoggerF[Boolean] = + WriterT.liftF[F, G[StructuredLogMessage], Boolean](Applicative[F].pure(enabled)) + + private def build( + ctx: Map[String, String], + enabled: Boolean, + level: LogLevel, + t: Option[Throwable], + message: => String + ): LoggerF[Unit] = + if (enabled) + WriterT.tell[F, G[StructuredLogMessage]](Applicative[G].pure { + StructuredLogMessage(level, ctx, t, message) + }) + else WriterT.value[F, G[StructuredLogMessage], Unit](()) + + private implicit val monoidGLogMessage: Monoid[G[StructuredLogMessage]] = + Alternative[G].algebra[StructuredLogMessage] + + override def trace(ctx: Map[String, String])(message: => String): LoggerF[Unit] = + build(ctx, traceEnabled, LogLevel.Trace, None, message) + + override def trace(ctx: Map[String, String], t: Throwable)( + message: => String + ): LoggerF[Unit] = + build(ctx, traceEnabled, LogLevel.Trace, t.some, message) + + override def debug(ctx: Map[String, String])(message: => String): LoggerF[Unit] = + build(ctx, debugEnabled, LogLevel.Debug, None, message) + + override def debug(ctx: Map[String, String], t: Throwable)( + message: => String + ): LoggerF[Unit] = + build(ctx, debugEnabled, LogLevel.Debug, t.some, message) + + override def info(ctx: Map[String, String])(message: => String): LoggerF[Unit] = + build(ctx, infoEnabled, LogLevel.Info, None, message) + + override def info(ctx: Map[String, String], t: Throwable)(message: => String): LoggerF[Unit] = + build(ctx, infoEnabled, LogLevel.Info, t.some, message) + + override def warn(ctx: Map[String, String])(message: => String): LoggerF[Unit] = + build(ctx, warnEnabled, LogLevel.Warn, None, message) + + override def warn(ctx: Map[String, String], t: Throwable)(message: => String): LoggerF[Unit] = + build(ctx, warnEnabled, LogLevel.Warn, t.some, message) + + override def error(ctx: Map[String, String])(message: => String): LoggerF[Unit] = + build(ctx, errorEnabled, LogLevel.Error, None, message) + + override def error(ctx: Map[String, String], t: Throwable)( + message: => String + ): LoggerF[Unit] = + build(ctx, errorEnabled, LogLevel.Error, t.some, message) + } + + def run[F[_]: Monad, G[_]: Foldable]( + l: StructuredLogger[F] + ): WriterT[F, G[StructuredLogMessage], *] ~> F = + new ~>[WriterT[F, G[StructuredLogMessage], *], F] { + override def apply[A](fa: WriterT[F, G[StructuredLogMessage], A]): F[A] = + fa.run.flatMap { case (toLog, out) => + toLog.traverse_(StructuredLogMessage.log(_, l)).as(out) + } + } +} diff --git a/testing/README.md b/testing/README.md new file mode 100644 index 00000000..a0766dd0 --- /dev/null +++ b/testing/README.md @@ -0,0 +1,177 @@ +# Testing with Log4Cats + +## Why not just use [`NoOpLogger`](../noop/shared/src/main/scala/org/typelevel/log4cats/noop/NoOpLogger.scala)? + +While an error in production is unquestionably the most important time to have good logging, a more common time when +having logs is really useful is figuring out why a test is failing. Unfortunately, logging and test reporting often +aren't synchronized in a useful manner, and the output becomes difficult to decipher. + +A common response to this is simply to disable logging in the tests generally, and open it back up locally when +debugging. `NoOpLogger` will certainly do that for you, however there is a better way - integrating log message into +the output of _only_ failing tests. + +## How can [`org.typelevel.log4cats.testing`](shared/src/main/scala/org/typelevel/log4cats/testing/) help? + +How log4cats will be integrated into test output looks different depending on the test framework. An example of +how to do this for `munit` could look like this: + +```scala +package org.log4cats.example + +import cats.MonadThrow +import cats.effect.unsafe.IORuntime +import cats.effect.{IO, Resource} +import cats.syntax.all._ +import munit.internal.console.Printers +import munit.{CatsEffectSuite, Printer, TestOptions} +import org.typelevel.log4cats.{LoggerFactory, SelfAwareStructuredLogger} +import org.typelevel.log4cats.testing.StructuredTestingLogger +import org.typelevel.log4cats.testing.StructuredTestingLogger.{DEBUG, ERROR, INFO, TRACE, WARN} + +import java.io.{PrintWriter, StringWriter} + +class ExampleTest extends CatsEffectSuite { + private val loggerFixture = ResourceFunFixture[LoggingHelper]((options: TestOptions) => + Resource.make(IO.delay { + val logger = StructuredTestingLogger.impl[IO]() + LoggingHelper(logger, logger.addContext(Map("TestName" -> options.name))) + })(_ => IO.unit) + ) + + private val loggerPrinter = new Printer { + override def print(value: Any, out: StringBuilder, indent: Int): Boolean = + value match { + case loggingHelper: LoggingHelper => + out.appendAll("Logs:") + val indentation = " " * (indent + 2) + val innerIndentation = " " * (indent + 8) + loggingHelper.logged.foreach { log => + out + .append('\n') + .append(indentation) + .appendAll(log match { + case _: TRACE => "TRACE " + case _: DEBUG => "DEBUG " + case _: INFO => "INFO " + case _: WARN => "WARN " + case _: ERROR => "ERROR " + }) + .appendAll(log.message) + + log.ctx.foreach { + case (k, v) => out.append('\n').appendAll(innerIndentation).appendAll(k).appendAll(" -> ").appendAll(v) + } + + log.throwOpt.foreach { throwable => + val stringWriter = new StringWriter + throwable.printStackTrace(new PrintWriter(stringWriter)) + stringWriter.toString.split('\n').foreach { line => + out.append('\n').appendAll(innerIndentation).appendAll(line) + } + } + } + true + + case _ => false + } + } + + override def munitPrint(clue: => Any): String = + clue match { + case message: String => message + case value => Printers.print(value, loggerPrinter) + } + + loggerFixture.test("avoid logging for successful tests") { loggingHelper => + import loggingHelper.loggerFactory + CodeUnderTest.logAndDouble[IO]("5").assertEquals(10, loggingHelper) + } + + loggerFixture.test("output logging for failing tests") { loggingHelper => + import loggingHelper.loggerFactory + CodeUnderTest.logAndDouble[IO]("5.").assertEquals(10, loggingHelper) + } +} + +/** + * Simple class to reduce some of the boilerplate, and fix the type argument of + * `StructuredTestingLogger` and avoid an unchecked type cast in `loggerPrinter` + */ +final case class LoggingHelper(underlyingLogger: StructuredTestingLogger[IO], + loggerWithContext: SelfAwareStructuredLogger[IO]) { + implicit val loggerFactory: LoggerFactory[IO] = new LoggerFactory[IO] { + override def getLoggerFromName(name: String): SelfAwareStructuredLogger[IO] = loggerWithContext + override def fromName(name: String): IO[SelfAwareStructuredLogger[IO]] = loggerWithContext.pure[IO] + } + + def logged(implicit runtime:IORuntime): Vector[StructuredTestingLogger.LogMessage] = + underlyingLogger.logged.unsafeRunSync() +} + +object CodeUnderTest { + def logAndDouble[F[_]: LoggerFactory: MonadThrow](input: String): F[Int] = { + val logger = LoggerFactory[F].getLogger + for { + _ <- logger.info(s"Input $input") + intVal <- MonadThrow[F].catchNonFatal(input.toInt).recoverWith { + case ex: NumberFormatException => logger.warn(ex)("Recovering to 0").as(0) + } + doubled = intVal * 2 + _ <- logger.info(s"Result: $doubled") + } yield doubled + } +} +``` + +Running this test should produce something close this output: +``` +sbt:log4cats-testing> testOnly org.log4cats.example.ExampleTest +[info] compiling 1 Scala source to /log4cats/testing/jvm/target/scala-2.13/test-classes ... +org.log4cats.example.ExampleTest: + + avoid logging for successful tests 0.073s +==> X org.log4cats.example.ExampleTest.output logging for failing tests 0.093s munit.ComparisonFailException: /log4cats/testing/shared/src/test/scala/org/typelevel/log4cats/ExampleTest.scala:74 +73: import loggingHelper.loggerFactory +74: CodeUnderTest.logAndDouble[IO]("5.").assertEquals(10, loggingHelper) +75: } +Logs: + INFO Input 5. + TestName -> output logging for failing tests + WARN Recovering to 0 + TestName -> output logging for failing tests + java.lang.NumberFormatException: For input string: "5." + at java.base/java.lang.NumberFormatException.forInputString(NumberFormatException.java:67) + at java.base/java.lang.Integer.parseInt(Integer.java:668) + at java.base/java.lang.Integer.parseInt(Integer.java:786) + at scala.collection.StringOps$.toInt$extension(StringOps.scala:908) + at org.log4cats.example.CodeUnderTest$.$anonfun$logAndDouble$3(ExampleTest.scala:98) + at recoverWith$extension @ org.log4cats.example.CodeUnderTest$.$anonfun$logAndDouble$2(ExampleTest.scala:98) + at flatMap @ org.log4cats.example.CodeUnderTest$.$anonfun$logAndDouble$2(ExampleTest.scala:98) + at delay @ org.typelevel.log4cats.testing.StructuredTestingLogger$.org$typelevel$log4cats$testing$StructuredTestingLogger$$appendLogMessage$1(StructuredTestingLogger.scala:73) + at flatMap @ org.log4cats.example.CodeUnderTest$.logAndDouble(ExampleTest.scala:97) + at flatMap @ munit.CatsEffectAssertions.assertIO(CatsEffectAssertions.scala:52) + at flatMap @ munit.internal.NestingChecks$.checkNestingIO(internal.scala:38) + INFO Result: 0 + TestName -> output logging for failing tests +=> Obtained +0 +=> Diff (- obtained, + expected) +-0 ++10 + at munit.Assertions.failComparison(Assertions.scala:274) + at apply @ munit.CatsEffectAssertions.$anonfun$assertIO$1(CatsEffectAssertions.scala:52) + at delay @ org.typelevel.log4cats.testing.StructuredTestingLogger$.org$typelevel$log4cats$testing$StructuredTestingLogger$$appendLogMessage$1(StructuredTestingLogger.scala:73) + at map @ org.log4cats.example.CodeUnderTest$.$anonfun$logAndDouble$4(ExampleTest.scala:102) + at delay @ org.typelevel.log4cats.testing.StructuredTestingLogger$.org$typelevel$log4cats$testing$StructuredTestingLogger$$appendLogMessage$1(StructuredTestingLogger.scala:73) + at as @ munit.CatsEffectFunFixtures$ResourceFunFixture$.$anonfun$apply$8(CatsEffectFunFixtures.scala:55) + at recoverWith$extension @ org.log4cats.example.CodeUnderTest$.$anonfun$logAndDouble$2(ExampleTest.scala:98) + at flatMap @ org.log4cats.example.CodeUnderTest$.$anonfun$logAndDouble$2(ExampleTest.scala:98) + at delay @ org.typelevel.log4cats.testing.StructuredTestingLogger$.org$typelevel$log4cats$testing$StructuredTestingLogger$$appendLogMessage$1(StructuredTestingLogger.scala:73) + at flatMap @ org.log4cats.example.CodeUnderTest$.logAndDouble(ExampleTest.scala:97) + at flatMap @ munit.CatsEffectAssertions.assertIO(CatsEffectAssertions.scala:52) + at flatMap @ munit.internal.NestingChecks$.checkNestingIO(internal.scala:38) +[error] Failed: Total 2, Failed 1, Errors 0, Passed 1 +[error] Failed tests: +[error] org.log4cats.example.ExampleTest +[error] (Test / testOnly) sbt.TestsFailedException: Tests unsuccessful +[error] Total time: 2 s, completed Jan 31, 2023, 9:45:03 PM +``` \ No newline at end of file