diff --git a/core/shared/src/main/scala/org/typelevel/log4cats/extras/DeferredLogMessage.scala b/core/shared/src/main/scala/org/typelevel/log4cats/extras/DeferredLogMessage.scala new file mode 100644 index 00000000..cca7322a --- /dev/null +++ b/core/shared/src/main/scala/org/typelevel/log4cats/extras/DeferredLogMessage.scala @@ -0,0 +1,148 @@ +/* + * 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.syntax.show.* +import cats.Show +import cats.kernel.Hash +import org.typelevel.log4cats.{Logger, StructuredLogger} +import org.typelevel.log4cats.extras.DeferredLogMessage.{ + deferredStructuredLogMessageHash, + deferredStructuredLogMessageShow +} + +/** + * `StructuredLogMessage` has a bug that can't be fixed without breaking bincompat (because it's a + * `case class`), but it's only used in the `Writer*Logger`s, so it's not a huge deal. + * + * The issue is that the API of the `*Logger` classes has a by-name parameter for the message, and + * `StructuredLogMessage` (and by extension, the `Writer*Logger`) don't lazily compute the message. + * + * At some point, this should be renamed to `StructuredLogMessage` and replace the old class. + */ +sealed trait DeferredLogMessage { + def level: LogLevel + def context: Map[String, String] + def throwableOpt: Option[Throwable] + def message: () => String + + def log[F[_]](logger: Logger[F]): F[Unit] = { + level match { + case LogLevel.Error => + throwableOpt match { + case Some(e) => logger.error(e)(message()) + case None => logger.error(message()) + } + case LogLevel.Warn => + throwableOpt match { + case Some(e) => logger.warn(e)(message()) + case None => logger.warn(message()) + } + case LogLevel.Info => + throwableOpt match { + case Some(e) => logger.info(e)(message()) + case None => logger.info(message()) + } + case LogLevel.Debug => + throwableOpt match { + case Some(e) => logger.debug(e)(message()) + case None => logger.debug(message()) + } + case LogLevel.Trace => + throwableOpt match { + case Some(e) => logger.trace(e)(message()) + case None => logger.trace(message()) + } + } + } + + def logStructured[F[_]](logger: StructuredLogger[F]): F[Unit] = { + level match { + case LogLevel.Error => + throwableOpt match { + case Some(e) => logger.error(context, e)(message()) + case None => logger.error(context)(message()) + } + case LogLevel.Warn => + throwableOpt match { + case Some(e) => logger.warn(context, e)(message()) + case None => logger.warn(context)(message()) + } + case LogLevel.Info => + throwableOpt match { + case Some(e) => logger.info(context, e)(message()) + case None => logger.info(context)(message()) + } + case LogLevel.Debug => + throwableOpt match { + case Some(e) => logger.debug(context, e)(message()) + case None => logger.debug(context)(message()) + } + case LogLevel.Trace => + throwableOpt match { + case Some(e) => logger.trace(context, e)(message()) + case None => logger.trace(context)(message()) + } + } + } + + override def equals(obj: Any): Boolean = obj match { + case other: DeferredLogMessage => deferredStructuredLogMessageHash.eqv(this, other) + case _ => false + } + + override def hashCode(): Int = deferredStructuredLogMessageHash.hash(this) + + override def toString: String = deferredStructuredLogMessageShow.show(this) +} +object DeferredLogMessage { + def apply( + l: LogLevel, + c: Map[String, String], + t: Option[Throwable], + m: () => String + ): DeferredLogMessage = + new DeferredLogMessage { + override val level: LogLevel = l + override val context: Map[String, String] = c + override val throwableOpt: Option[Throwable] = t + override val message: () => String = m + } + + def trace(c: Map[String, String], t: Option[Throwable], m: () => String): DeferredLogMessage = + apply(LogLevel.Trace, c, t, m) + + def debug(c: Map[String, String], t: Option[Throwable], m: () => String): DeferredLogMessage = + apply(LogLevel.Debug, c, t, m) + + def info(c: Map[String, String], t: Option[Throwable], m: () => String): DeferredLogMessage = + apply(LogLevel.Info, c, t, m) + + def warn(c: Map[String, String], t: Option[Throwable], m: () => String): DeferredLogMessage = + apply(LogLevel.Warn, c, t, m) + + def error(c: Map[String, String], t: Option[Throwable], m: () => String): DeferredLogMessage = + apply(LogLevel.Error, c, t, m) + + implicit val deferredStructuredLogMessageHash: Hash[DeferredLogMessage] = Hash.by { l => + (l.level, l.context, l.throwableOpt.map(_.getMessage), l.message()) + } + + implicit val deferredStructuredLogMessageShow: Show[DeferredLogMessage] = Show.show { l => + show"DeferredStructuredLogMessage(${l.level},${l.context},${l.throwableOpt.map(_.getMessage)},${l.message()})" + } +} diff --git a/core/shared/src/main/scala/org/typelevel/log4cats/extras/LogLevel.scala b/core/shared/src/main/scala/org/typelevel/log4cats/extras/LogLevel.scala index dd2ed730..1549416f 100644 --- a/core/shared/src/main/scala/org/typelevel/log4cats/extras/LogLevel.scala +++ b/core/shared/src/main/scala/org/typelevel/log4cats/extras/LogLevel.scala @@ -48,12 +48,15 @@ object LogLevel { case Trace => "LogLevel.Trace" } - implicit final val logLevelOrder: Order[LogLevel] = - Order.by[LogLevel, Int] { - case Error => 5 - case Warn => 4 - case Info => 3 - case Debug => 2 - case Trace => 1 - } + private def toIndex(l: LogLevel): Int = l match { + case Error => 5 + case Warn => 4 + case Info => 3 + case Debug => 2 + case Trace => 1 + } + + implicit final val logLevelOrder: Order[LogLevel] = Order.by[LogLevel, Int](toIndex) + + implicit final val logLevelHash: Hash[LogLevel] = Hash.by(toIndex) } diff --git a/slf4j/src/main/scala/org/typelevel/log4cats/slf4j/internal/Slf4jLoggerInternal.scala b/slf4j/src/main/scala/org/typelevel/log4cats/slf4j/internal/Slf4jLoggerInternal.scala index 03b67ffb..4f652a08 100644 --- a/slf4j/src/main/scala/org/typelevel/log4cats/slf4j/internal/Slf4jLoggerInternal.scala +++ b/slf4j/src/main/scala/org/typelevel/log4cats/slf4j/internal/Slf4jLoggerInternal.scala @@ -16,12 +16,14 @@ package org.typelevel.log4cats.slf4j.internal -import org.typelevel.log4cats._ -import cats.syntax.all._ -import cats.effect._ -import org.slf4j.{Logger => JLogger} +import org.typelevel.log4cats.* +import cats.syntax.all.* +import cats.effect.* +import org.slf4j.Logger as JLogger import org.slf4j.MDC +import scala.annotation.nowarn + private[slf4j] object Slf4jLoggerInternal { final val singletonsByName = true @@ -34,6 +36,12 @@ private[slf4j] object Slf4jLoggerInternal { def apply(t: Throwable)(msg: => String): F[Unit] } + // Need this to make sure MDC is correctly cleared before logging + private[this] def noContextLog[F[_]](isEnabled: F[Boolean], logging: () => Unit)(implicit + F: Sync[F] + ): F[Unit] = + contextLog[F](isEnabled, Map.empty, logging) + private[this] def contextLog[F[_]]( isEnabled: F[Boolean], ctx: Map[String, String], @@ -41,14 +49,23 @@ private[slf4j] object Slf4jLoggerInternal { )(implicit F: Sync[F]): F[Unit] = { val ifEnabled = F.delay { - val backup = MDC.getCopyOfContextMap() + val backup = + try MDC.getCopyOfContextMap() + catch { + case e: IllegalStateException => + // MDCAdapter is missing, no point in doing anything with + // the MDC, so just hope the logging backend can salvage + // something. + logging() + throw e + } - for { - (k, v) <- ctx - } MDC.put(k, v) - - try logging() - finally + try { + // Once 2.12 is no longer supported, change this to MDC.setContextMap(ctx.asJava) + MDC.clear() + ctx.foreach { case (k, v) => MDC.put(k, v) } + logging() + } finally if (backup eq null) MDC.clear() else MDC.setContextMap(backup) } @@ -59,6 +76,7 @@ private[slf4j] object Slf4jLoggerInternal { ) } + @nowarn("msg=used") final class Slf4jLogger[F[_]](val logger: JLogger, sync: Sync.Type = Sync.Type.Delay)(implicit F: Sync[F] ) extends SelfAwareStructuredLogger[F] { @@ -76,53 +94,47 @@ private[slf4j] object Slf4jLoggerInternal { override def isErrorEnabled: F[Boolean] = F.delay(logger.isErrorEnabled) override def trace(t: Throwable)(msg: => String): F[Unit] = - isTraceEnabled - .ifM(F.suspend(sync)(logger.trace(msg, t)), F.unit) + noContextLog(isTraceEnabled, () => logger.trace(msg, t)) override def trace(msg: => String): F[Unit] = - isTraceEnabled - .ifM(F.suspend(sync)(logger.trace(msg)), F.unit) + noContextLog(isTraceEnabled, () => logger.trace(msg)) override def trace(ctx: Map[String, String])(msg: => String): F[Unit] = contextLog(isTraceEnabled, ctx, () => logger.trace(msg)) + override def trace(ctx: Map[String, String], t: Throwable)(msg: => String): F[Unit] = + contextLog(isTraceEnabled, ctx, () => logger.trace(msg, t)) + override def debug(t: Throwable)(msg: => String): F[Unit] = - isDebugEnabled - .ifM(F.suspend(sync)(logger.debug(msg, t)), F.unit) + noContextLog(isDebugEnabled, () => logger.debug(msg, t)) override def debug(msg: => String): F[Unit] = - isDebugEnabled - .ifM(F.suspend(sync)(logger.debug(msg)), F.unit) + noContextLog(isDebugEnabled, () => logger.debug(msg)) override def debug(ctx: Map[String, String])(msg: => String): F[Unit] = contextLog(isDebugEnabled, ctx, () => logger.debug(msg)) + override def debug(ctx: Map[String, String], t: Throwable)(msg: => String): F[Unit] = + contextLog(isDebugEnabled, ctx, () => logger.debug(msg, t)) + override def info(t: Throwable)(msg: => String): F[Unit] = - isInfoEnabled - .ifM(F.suspend(sync)(logger.info(msg, t)), F.unit) + noContextLog(isInfoEnabled, () => logger.info(msg, t)) override def info(msg: => String): F[Unit] = - isInfoEnabled - .ifM(F.suspend(sync)(logger.info(msg)), F.unit) + noContextLog(isInfoEnabled, () => logger.info(msg)) override def info(ctx: Map[String, String])(msg: => String): F[Unit] = contextLog(isInfoEnabled, ctx, () => logger.info(msg)) + override def info(ctx: Map[String, String], t: Throwable)(msg: => String): F[Unit] = + contextLog(isInfoEnabled, ctx, () => logger.info(msg, t)) + override def warn(t: Throwable)(msg: => String): F[Unit] = - isWarnEnabled - .ifM(F.suspend(sync)(logger.warn(msg, t)), F.unit) + noContextLog(isWarnEnabled, () => logger.warn(msg, t)) override def warn(msg: => String): F[Unit] = - isWarnEnabled - .ifM(F.suspend(sync)(logger.warn(msg)), F.unit) + noContextLog(isWarnEnabled, () => logger.warn(msg)) override def warn(ctx: Map[String, String])(msg: => String): F[Unit] = contextLog(isWarnEnabled, ctx, () => logger.warn(msg)) + override def warn(ctx: Map[String, String], t: Throwable)(msg: => String): F[Unit] = + contextLog(isWarnEnabled, ctx, () => logger.warn(msg, t)) + override def error(t: Throwable)(msg: => String): F[Unit] = - isErrorEnabled - .ifM(F.suspend(sync)(logger.error(msg, t)), F.unit) + noContextLog(isErrorEnabled, () => logger.error(msg, t)) override def error(msg: => String): F[Unit] = - isErrorEnabled - .ifM(F.suspend(sync)(logger.error(msg)), F.unit) + noContextLog(isErrorEnabled, () => logger.error(msg)) override def error(ctx: Map[String, String])(msg: => String): F[Unit] = contextLog(isErrorEnabled, ctx, () => logger.error(msg)) - override def trace(ctx: Map[String, String], t: Throwable)(msg: => String): F[Unit] = - contextLog(isTraceEnabled, ctx, () => logger.trace(msg, t)) - override def debug(ctx: Map[String, String], t: Throwable)(msg: => String): F[Unit] = - contextLog(isDebugEnabled, ctx, () => logger.debug(msg, t)) - override def info(ctx: Map[String, String], t: Throwable)(msg: => String): F[Unit] = - contextLog(isInfoEnabled, ctx, () => logger.info(msg, t)) - override def warn(ctx: Map[String, String], t: Throwable)(msg: => String): F[Unit] = - contextLog(isWarnEnabled, ctx, () => logger.warn(msg, t)) override def error(ctx: Map[String, String], t: Throwable)(msg: => String): F[Unit] = contextLog(isErrorEnabled, ctx, () => logger.error(msg, t)) } diff --git a/slf4j/src/test/scala/org/typelevel/log4cats/slf4j/internal/JTestLogger.java b/slf4j/src/test/scala/org/typelevel/log4cats/slf4j/internal/JTestLogger.java new file mode 100644 index 00000000..7c66fe52 --- /dev/null +++ b/slf4j/src/test/scala/org/typelevel/log4cats/slf4j/internal/JTestLogger.java @@ -0,0 +1,207 @@ +/* + * 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.slf4j.internal; + +import org.slf4j.Logger; +import org.slf4j.MDC; +import org.slf4j.Marker; +import org.typelevel.log4cats.extras.LogLevel; +import scala.Option; + +import java.util.ArrayList; +import java.util.HashMap; +import java.util.List; +import java.util.Map; +import java.util.concurrent.atomic.AtomicReference; +import java.util.function.Function; +import java.util.function.Supplier; + +public class JTestLogger implements Logger { + // Java -> Scala compat helpers + + private static final scala.Option none = scala.Option$.MODULE$.empty(); + private static scala.Option some(Throwable t) { return scala.Option$.MODULE$.apply(t); } + private static final LogLevel.Trace$ Trace = LogLevel.Trace$.MODULE$; + private static final LogLevel.Debug$ Debug = LogLevel.Debug$.MODULE$; + private static final LogLevel.Info$ Info = LogLevel.Info$.MODULE$; + private static final LogLevel.Warn$ Warn = LogLevel.Warn$.MODULE$; + private static final LogLevel.Error$ Error = LogLevel.Error$.MODULE$; + + private Map captureContext () { + java.util.Map mdc = MDC.getCopyOfContextMap(); + if (mdc == null) { + return new HashMap<>(); + } + return MDC.getCopyOfContextMap(); + } + + public static class TestLogMessage { + public final LogLevel logLevel; + public final java.util.Map context; + public final Option throwableOpt; + public final Supplier message; + + public TestLogMessage(LogLevel logLevel, + java.util.Map context, + Option throwableOpt, + Supplier message) { + this.logLevel = logLevel; + this.context = context; + this.throwableOpt = throwableOpt; + this.message = message; + } + + @Override + public String toString() { + return new StringBuilder() + .append("TestLogMessage(") + .append("logLevel=").append(logLevel) + .append(", ") + .append("context=").append(context) + .append(", ") + .append("throwableOpt=").append(throwableOpt) + .append(", ") + .append("message=").append(message.get()) + .append(')') + .toString(); + } + + static TestLogMessage of(LogLevel logLevel, + java.util.Map context, + Throwable throwable, + Supplier message) { + return new TestLogMessage(logLevel, context, some(throwable), message); + } + + static TestLogMessage of(LogLevel logLevel, + java.util.Map context, + Supplier message) { + return new TestLogMessage(logLevel, context, none, message); + } + } + + private final String loggerName; + private final boolean traceEnabled; + private final boolean debugEnabled; + private final boolean infoEnabled; + private final boolean warnEnabled; + private final boolean errorEnabled; + private final AtomicReference> loggedMessages; + + + public JTestLogger(String loggerName, + boolean traceEnabled, + boolean debugEnabled, + boolean infoEnabled, + boolean warnEnabled, + boolean errorEnabled) { + this.loggerName = loggerName; + this.traceEnabled = traceEnabled; + this.debugEnabled = debugEnabled; + this.infoEnabled = infoEnabled; + this.warnEnabled = warnEnabled; + this.errorEnabled = errorEnabled; + loggedMessages = new AtomicReference<>(new ArrayList()); + } + + private void save(Function, TestLogMessage> mkLogMessage) { + loggedMessages.updateAndGet(ll -> { + ll.add(mkLogMessage.apply(captureContext())); + return ll; + }); + } + + public List logs() { return loggedMessages.get(); } + public void reset() { loggedMessages.set(new ArrayList<>()); } + + @Override public String getName() { return loggerName;} + + @Override public boolean isTraceEnabled() { return traceEnabled; } + @Override public boolean isDebugEnabled() { return debugEnabled; } + @Override public boolean isInfoEnabled() { return infoEnabled; } + @Override public boolean isWarnEnabled() { return warnEnabled; } + @Override public boolean isErrorEnabled() { return errorEnabled; } + + // We don't use them, so we're going to ignore Markers + @Override public boolean isTraceEnabled(Marker marker) { return traceEnabled; } + @Override public boolean isDebugEnabled(Marker marker) { return debugEnabled; } + @Override public boolean isInfoEnabled(Marker marker) { return infoEnabled; } + @Override public boolean isWarnEnabled(Marker marker) { return warnEnabled; } + @Override public boolean isErrorEnabled(Marker marker) { return errorEnabled; } + + @Override public void trace(String msg) { save(ctx -> TestLogMessage.of(Trace, ctx, () -> msg)); } + @Override public void trace(String msg, Throwable t) { save(ctx -> TestLogMessage.of(Trace, ctx, t, () -> msg)); } + + @Override public void debug(String msg) { save(ctx -> TestLogMessage.of(Debug, ctx, () -> msg)); } + @Override public void debug(String msg, Throwable t) { save(ctx -> TestLogMessage.of(Debug, ctx, t, () -> msg)); } + + @Override public void info(String msg) { save(ctx -> TestLogMessage.of(Info, ctx, () -> msg)); } + @Override public void info(String msg, Throwable t) { save(ctx -> TestLogMessage.of(Info, ctx, t, () -> msg)); } + + @Override public void warn(String msg) { save(ctx -> TestLogMessage.of(Warn, ctx, () -> msg)); } + @Override public void warn(String msg, Throwable t) { save(ctx -> TestLogMessage.of(Warn, ctx, t, () -> msg)); } + + @Override public void error(String msg) { save(ctx -> TestLogMessage.of(Error, ctx, () -> msg)); } + @Override public void error(String msg, Throwable t) { save(ctx -> TestLogMessage.of(Error, ctx, t, () -> msg)); } + + // We shouldn't need these for our tests, so we're treating these variants as if they were the standard method + + @Override public void trace(String format, Object arg) { trace(format); } + @Override public void trace(String format, Object arg1, Object arg2) { trace(format); } + @Override public void trace(String format, Object... arguments) { trace(format); } + @Override public void trace(Marker marker, String msg) { trace(msg); } + @Override public void trace(Marker marker, String format, Object arg) { trace(format); } + @Override public void trace(Marker marker, String format, Object arg1, Object arg2) { trace(format); } + @Override public void trace(Marker marker, String format, Object... argArray) { trace(format); } + @Override public void trace(Marker marker, String msg, Throwable t) { trace(msg, t); } + + @Override public void debug(String format, Object arg) { debug(format); } + @Override public void debug(String format, Object arg1, Object arg2) { debug(format); } + @Override public void debug(String format, Object... arguments) { debug(format); } + @Override public void debug(Marker marker, String msg) { debug(msg); } + @Override public void debug(Marker marker, String format, Object arg) { debug(format); } + @Override public void debug(Marker marker, String format, Object arg1, Object arg2) { debug(format); } + @Override public void debug(Marker marker, String format, Object... arguments) { debug(format); } + @Override public void debug(Marker marker, String msg, Throwable t) { debug(msg, t); } + + @Override public void info(String format, Object arg) { info(format); } + @Override public void info(String format, Object arg1, Object arg2) { info(format); } + @Override public void info(String format, Object... arguments) { info(format); } + @Override public void info(Marker marker, String msg) { info(msg); } + @Override public void info(Marker marker, String format, Object arg) { info(format); } + @Override public void info(Marker marker, String format, Object arg1, Object arg2) { info(format); } + @Override public void info(Marker marker, String format, Object... arguments) { info(format); } + @Override public void info(Marker marker, String msg, Throwable t) { info(msg, t); } + + @Override public void warn(String format, Object arg) { warn(format); } + @Override public void warn(String format, Object... arguments) { warn(format); } + @Override public void warn(String format, Object arg1, Object arg2) { warn(format); } + @Override public void warn(Marker marker, String msg) { warn(msg); } + @Override public void warn(Marker marker, String format, Object arg) { warn(format); } + @Override public void warn(Marker marker, String format, Object arg1, Object arg2) { warn(format); } + @Override public void warn(Marker marker, String format, Object... arguments) { warn(format); } + @Override public void warn(Marker marker, String msg, Throwable t) { warn(msg, t); } + + @Override public void error(String format, Object arg) { error(format); } + @Override public void error(String format, Object arg1, Object arg2) { error(format); } + @Override public void error(String format, Object... arguments) { error(format); } + @Override public void error(Marker marker, String msg) { error(msg); } + @Override public void error(Marker marker, String format, Object arg) { error(format); } + @Override public void error(Marker marker, String format, Object arg1, Object arg2) { error(format); } + @Override public void error(Marker marker, String format, Object... arguments) { error(format); } + @Override public void error(Marker marker, String msg, Throwable t) { error(msg, t); } +} diff --git a/slf4j/src/test/scala/org/typelevel/log4cats/slf4j/internal/Slf4jLoggerInternalSuite.scala b/slf4j/src/test/scala/org/typelevel/log4cats/slf4j/internal/Slf4jLoggerInternalSuite.scala index 9e81d1d7..a5afc569 100644 --- a/slf4j/src/test/scala/org/typelevel/log4cats/slf4j/internal/Slf4jLoggerInternalSuite.scala +++ b/slf4j/src/test/scala/org/typelevel/log4cats/slf4j/internal/Slf4jLoggerInternalSuite.scala @@ -17,16 +17,43 @@ package org.typelevel.log4cats.slf4j package internal -import cats.effect.IO -import java.util.concurrent.Executors -import java.util.concurrent.ThreadFactory +import cats.arrow.FunctionK +import cats.effect.unsafe.IORuntime +import cats.effect.{IO, Resource, SyncIO} +import cats.syntax.all.* + +import java.util.concurrent.{Executors, ThreadFactory} import org.slf4j.MDC -import munit.CatsEffectSuite +import munit.{CatsEffectSuite, Location} +import org.typelevel.log4cats.extras.DeferredLogMessage +import org.typelevel.log4cats.slf4j.internal.JTestLogger.TestLogMessage + +import java.util +import java.util.function +import java.util.function.{BiConsumer, BinaryOperator, Supplier} +import java.util.stream.Collector +import scala.collection.mutable.ListBuffer import scala.concurrent.ExecutionContext import scala.concurrent.ExecutionContextExecutorService +import scala.util.control.NoStackTrace class Slf4jLoggerInternalSuite extends CatsEffectSuite { + private val computeEC = ExecutionContext.fromExecutorService( + Executors.newSingleThreadExecutor(), + t => fail("Uncaught exception on compute thread", t) + ) + private val blockingEC = ExecutionContext.fromExecutorService( + Executors.newSingleThreadExecutor(), + t => fail("Uncaught exception on blocking thread", t) + ) + override implicit def munitIORuntime: IORuntime = + IORuntime + .builder() + .setCompute(computeEC, () => computeEC.shutdown()) + .setBlocking(blockingEC, () => blockingEC.shutdown()) + .build() + object dirtyStuff { def namedSingleThreadExecutionContext(name: String): ExecutionContextExecutorService = @@ -36,25 +63,364 @@ class Slf4jLoggerInternalSuite extends CatsEffectSuite { }) ) - def killThreads(threads: List[ExecutionContextExecutorService]) = threads.foreach { thread => - try thread.shutdownNow() - catch { - case e: Throwable => - Console.err.println("Couldn't shutdown thread") - e.printStackTrace() + def killThreads(threads: List[ExecutionContextExecutorService]): Unit = threads.foreach { + thread => + try thread.shutdownNow() + catch { + case e: Throwable => + Console.err.println("Couldn't shutdown thread") + e.printStackTrace() + } + } + } + + private def testLoggerFixture( + traceEnabled: Boolean = true, + debugEnabled: Boolean = true, + infoEnabled: Boolean = true, + warnEnabled: Boolean = true, + errorEnabled: Boolean = true + ): SyncIO[FunFixture[JTestLogger]] = + ResourceFunFixture( + Resource.eval( + IO( + new JTestLogger( + "Test Logger", + traceEnabled, + debugEnabled, + infoEnabled, + warnEnabled, + errorEnabled + ) + ) + ) + ) + + // Collections compat with Java is really annoying across the 2.12 / 2.13 boundary + // + // If you are reading this and support for 2.12 has been dropped, kindly rip this + // out and call one of the helpers from scala.jdk.javaapi instead. + private def toScalaList[A]: Collector[A, ListBuffer[A], List[A]] = + new Collector[A, ListBuffer[A], List[A]] { + override val characteristics: util.Set[Collector.Characteristics] = + new util.HashSet[Collector.Characteristics]() + + override val supplier: Supplier[ListBuffer[A]] = () => new ListBuffer[A] + + override val accumulator: BiConsumer[ListBuffer[A], A] = (b, e) => b.append(e) + + override val combiner: BinaryOperator[ListBuffer[A]] = (a, b) => { + a.appendAll(b) + a } + + override val finisher: function.Function[ListBuffer[A], List[A]] = _.result() } + + private val prepareMDC: IO[Unit] = IO.delay { + MDC.clear() + MDC.put("foo", "yellow") } + private def validateMDC(implicit loc: Location): IO[Unit] = + IO.delay(MDC.getCopyOfContextMap) + .map(_.entrySet().stream().collect(toScalaList).map(e => e.getKey -> e.getValue).sorted) + .assertEquals( + List("foo" -> "yellow"), + clue("MDC was not properly restored") + ) + + // These are literally just because I'm lazy + private val throwable = new NoSuchElementException("error") with NoStackTrace + private def die(): String = throw new IllegalStateException("dead") + private def tag(t: String): Map[String, String] = Map("tag" -> t) + test("Slf4jLoggerInternal resets after logging") { - val variable = "foo" - val initial = "yellow" - MDC.put(variable, initial) - - Slf4jLogger - .getLogger[IO] - .info(Map(variable -> "bar"))("A log went here") - .as(MDC.get(variable)) - .assertEquals(initial) + prepareMDC >> + Slf4jLogger.getLogger[IO].info(Map("foo" -> "bar"))("A log went here") >> + validateMDC + } + + test("Slf4jLoggerInternal resets after exceptions") { + prepareMDC >> + Slf4jLogger + .getLogger[IO] + .info(Map("foo" -> "bar"))(die()) + .interceptMessage[IllegalStateException]("dead") >> + validateMDC + } + + private def toDeferredLogs(jl: java.util.List[TestLogMessage]): List[DeferredLogMessage] = + jl.stream() + .map[DeferredLogMessage] { tl => + val context = + tl.context + .entrySet() + .stream() + .map[(String, String)](e => e.getKey -> e.getValue) + .collect(toScalaList) + .toMap + DeferredLogMessage(tl.logLevel, context, tl.throwableOpt, () => tl.message.get()) + } + .collect(toScalaList[DeferredLogMessage]) + + testLoggerFixture().test("Slf4jLoggerInternal correctly sets the MDC") { testLogger => + prepareMDC >> + Slf4jLogger.getLoggerFromSlf4j[IO](testLogger).info(Map("foo" -> "bar"))("A log went here") >> + IO(testLogger.logs()) + .map(toDeferredLogs) + .assertEquals( + List( + DeferredLogMessage.info(Map("foo" -> "bar"), none, () => "A log went here") + ) + ) >> + validateMDC + } + + testLoggerFixture().test( + "Slf4jLoggerInternal does not include values previously in the MDC in the log's context" + ) { testLogger => + prepareMDC >> + Slf4jLogger.getLoggerFromSlf4j[IO](testLogger).info(Map("bar" -> "baz"))("A log went here") >> + IO(testLogger.logs()) + .map(toDeferredLogs) + .assertEquals( + List(DeferredLogMessage.info(Map("bar" -> "baz"), none, () => "A log went here")), + clue("Context should not include foo->yellow") + ) >> + validateMDC + } + + testLoggerFixture( + traceEnabled = false, + debugEnabled = false, + infoEnabled = false, + warnEnabled = false, + errorEnabled = false + ).test("Slf4jLoggerInternal is suitably lazy") { testLogger => + val slf4jLogger = Slf4jLogger.getLoggerFromSlf4j[IO](testLogger) + val ctx = tag("lazy") + // If these are lazy the way they need to be, the message won't be evaluated until + // after the log level has been checked + prepareMDC >> + slf4jLogger.trace(die()).assert >> + slf4jLogger.debug(die()).assert >> + slf4jLogger.info(die()).assert >> + slf4jLogger.warn(die()).assert >> + slf4jLogger.error(die()).assert >> + slf4jLogger.trace(throwable)(die()).assert >> + slf4jLogger.debug(throwable)(die()).assert >> + slf4jLogger.info(throwable)(die()).assert >> + slf4jLogger.warn(throwable)(die()).assert >> + slf4jLogger.error(throwable)(die()).assert >> + slf4jLogger.trace(ctx)(die()).assert >> + slf4jLogger.debug(ctx)(die()).assert >> + slf4jLogger.info(ctx)(die()).assert >> + slf4jLogger.warn(ctx)(die()).assert >> + slf4jLogger.error(ctx)(die()).assert >> + slf4jLogger.trace(ctx, throwable)(die()).assert >> + slf4jLogger.debug(ctx, throwable)(die()).assert >> + slf4jLogger.info(ctx, throwable)(die()).assert >> + slf4jLogger.warn(ctx, throwable)(die()).assert >> + slf4jLogger.error(ctx, throwable)(die()).assert >> + validateMDC + } + + testLoggerFixture( + traceEnabled = false, + debugEnabled = false, + infoEnabled = false, + warnEnabled = false, + errorEnabled = false + ).test("Slf4jLoggerInternal.mapK is still lazy") { testLogger => + val slf4jLogger = Slf4jLogger.getLoggerFromSlf4j[IO](testLogger).mapK[IO](FunctionK.id) + val ctx = tag("lazy") + // If these are lazy the way they need to be, the message won't be evaluated until + // after the log level has been checked + prepareMDC >> + slf4jLogger.trace(die()).assert >> + slf4jLogger.debug(die()).assert >> + slf4jLogger.info(die()).assert >> + slf4jLogger.warn(die()).assert >> + slf4jLogger.error(die()).assert >> + slf4jLogger.trace(throwable)(die()).assert >> + slf4jLogger.debug(throwable)(die()).assert >> + slf4jLogger.info(throwable)(die()).assert >> + slf4jLogger.warn(throwable)(die()).assert >> + slf4jLogger.error(throwable)(die()).assert >> + slf4jLogger.trace(ctx)(die()).assert >> + slf4jLogger.debug(ctx)(die()).assert >> + slf4jLogger.info(ctx)(die()).assert >> + slf4jLogger.warn(ctx)(die()).assert >> + slf4jLogger.error(ctx)(die()).assert >> + slf4jLogger.trace(ctx, throwable)(die()).assert >> + slf4jLogger.debug(ctx, throwable)(die()).assert >> + slf4jLogger.info(ctx, throwable)(die()).assert >> + slf4jLogger.warn(ctx, throwable)(die()).assert >> + slf4jLogger.error(ctx, throwable)(die()).assert >> + validateMDC + } + + testLoggerFixture( + traceEnabled = false, + debugEnabled = false, + infoEnabled = false, + warnEnabled = false, + errorEnabled = false + ).test("Slf4jLoggerInternal.withModifiedString is still lazy") { testLogger => + val slf4jLogger = + Slf4jLogger.getLoggerFromSlf4j[IO](testLogger).withModifiedString(_.toUpperCase) + val ctx = tag("lazy") + // If these are lazy the way they need to be, the message won't be evaluated until + // after the log level has been checked + prepareMDC >> + slf4jLogger.trace(die()).assert >> + slf4jLogger.debug(die()).assert >> + slf4jLogger.info(die()).assert >> + slf4jLogger.warn(die()).assert >> + slf4jLogger.error(die()).assert >> + slf4jLogger.trace(throwable)(die()).assert >> + slf4jLogger.debug(throwable)(die()).assert >> + slf4jLogger.info(throwable)(die()).assert >> + slf4jLogger.warn(throwable)(die()).assert >> + slf4jLogger.error(throwable)(die()).assert >> + slf4jLogger.trace(ctx)(die()).assert >> + slf4jLogger.debug(ctx)(die()).assert >> + slf4jLogger.info(ctx)(die()).assert >> + slf4jLogger.warn(ctx)(die()).assert >> + slf4jLogger.error(ctx)(die()).assert >> + slf4jLogger.trace(ctx, throwable)(die()).assert >> + slf4jLogger.debug(ctx, throwable)(die()).assert >> + slf4jLogger.info(ctx, throwable)(die()).assert >> + slf4jLogger.warn(ctx, throwable)(die()).assert >> + slf4jLogger.error(ctx, throwable)(die()).assert >> + validateMDC + } + + testLoggerFixture( + traceEnabled = false, + debugEnabled = false, + infoEnabled = false, + warnEnabled = false, + errorEnabled = false + ).test("Slf4jLoggerInternal.addContext is still lazy") { testLogger => + val slf4jLogger = Slf4jLogger.getLoggerFromSlf4j[IO](testLogger).addContext(Map("bar" -> "foo")) + val ctx = tag("lazy") + // If these are lazy the way they need to be, the message won't be evaluated until + // after the log level has been checked + prepareMDC >> + slf4jLogger.trace(die()).assert >> + slf4jLogger.debug(die()).assert >> + slf4jLogger.info(die()).assert >> + slf4jLogger.warn(die()).assert >> + slf4jLogger.error(die()).assert >> + slf4jLogger.trace(throwable)(die()).assert >> + slf4jLogger.debug(throwable)(die()).assert >> + slf4jLogger.info(throwable)(die()).assert >> + slf4jLogger.warn(throwable)(die()).assert >> + slf4jLogger.error(throwable)(die()).assert >> + slf4jLogger.trace(ctx)(die()).assert >> + slf4jLogger.debug(ctx)(die()).assert >> + slf4jLogger.info(ctx)(die()).assert >> + slf4jLogger.warn(ctx)(die()).assert >> + slf4jLogger.error(ctx)(die()).assert >> + slf4jLogger.trace(ctx, throwable)(die()).assert >> + slf4jLogger.debug(ctx, throwable)(die()).assert >> + slf4jLogger.info(ctx, throwable)(die()).assert >> + slf4jLogger.warn(ctx, throwable)(die()).assert >> + slf4jLogger.error(ctx, throwable)(die()).assert >> + validateMDC + } + + testLoggerFixture().test("Slf4jLoggerInternal gets the dispatching right (msg)") { testLogger => + val slf4jLogger = Slf4jLogger.getLoggerFromSlf4j[IO](testLogger) + prepareMDC >> + slf4jLogger.trace("trace").assert >> + slf4jLogger.debug("debug").assert >> + slf4jLogger.info("info").assert >> + slf4jLogger.warn("warn").assert >> + slf4jLogger.error("error").assert >> + IO(testLogger.logs()) + .map(toDeferredLogs) + .assertEquals( + List( + DeferredLogMessage.trace(Map.empty, none, () => "trace"), + DeferredLogMessage.debug(Map.empty, none, () => "debug"), + DeferredLogMessage.info(Map.empty, none, () => "info"), + DeferredLogMessage.warn(Map.empty, none, () => "warn"), + DeferredLogMessage.error(Map.empty, none, () => "error") + ) + ) >> + validateMDC + } + + testLoggerFixture().test("Slf4jLoggerInternal gets the dispatching right (msg + error)") { + testLogger => + val slf4jLogger = Slf4jLogger.getLoggerFromSlf4j[IO](testLogger) + prepareMDC >> + slf4jLogger.trace(throwable)("trace").assert >> + slf4jLogger.debug(throwable)("debug").assert >> + slf4jLogger.info(throwable)("info").assert >> + slf4jLogger.warn(throwable)("warn").assert >> + slf4jLogger.error(throwable)("error").assert >> + IO(testLogger.logs()) + .map(toDeferredLogs) + .assertEquals( + List( + DeferredLogMessage.trace(Map.empty, throwable.some, () => "trace"), + DeferredLogMessage.debug(Map.empty, throwable.some, () => "debug"), + DeferredLogMessage.info(Map.empty, throwable.some, () => "info"), + DeferredLogMessage.warn(Map.empty, throwable.some, () => "warn"), + DeferredLogMessage.error(Map.empty, throwable.some, () => "error") + ) + ) >> + validateMDC + } + + testLoggerFixture().test("Slf4jLoggerInternal gets the dispatching right (msg + context)") { + testLogger => + val slf4jLogger = Slf4jLogger.getLoggerFromSlf4j[IO](testLogger) + prepareMDC >> + slf4jLogger.trace(tag("trace"))("trace").assert >> + slf4jLogger.debug(tag("debug"))("debug").assert >> + slf4jLogger.info(tag("info"))("info").assert >> + slf4jLogger.warn(tag("warn"))("warn").assert >> + slf4jLogger.error(tag("error"))("error").assert >> + IO(testLogger.logs()) + .map(toDeferredLogs) + .assertEquals( + List( + DeferredLogMessage.trace(tag("trace"), none, () => "trace"), + DeferredLogMessage.debug(tag("debug"), none, () => "debug"), + DeferredLogMessage.info(tag("info"), none, () => "info"), + DeferredLogMessage.warn(tag("warn"), none, () => "warn"), + DeferredLogMessage.error(tag("error"), none, () => "error") + ) + ) >> + validateMDC + } + + testLoggerFixture().test( + "Slf4jLoggerInternal gets the dispatching right (msg + context + error" + ) { testLogger => + val slf4jLogger = Slf4jLogger.getLoggerFromSlf4j[IO](testLogger) + prepareMDC >> + slf4jLogger.trace(tag("trace"), throwable)("trace").assert >> + slf4jLogger.debug(tag("debug"), throwable)("debug").assert >> + slf4jLogger.info(tag("info"), throwable)("info").assert >> + slf4jLogger.warn(tag("warn"), throwable)("warn").assert >> + slf4jLogger.error(tag("error"), throwable)("error").assert >> + IO(testLogger.logs()) + .map(toDeferredLogs) + .assertEquals( + List( + DeferredLogMessage.trace(tag("trace"), throwable.some, () => "trace"), + DeferredLogMessage.debug(tag("debug"), throwable.some, () => "debug"), + DeferredLogMessage.info(tag("info"), throwable.some, () => "info"), + DeferredLogMessage.warn(tag("warn"), throwable.some, () => "warn"), + DeferredLogMessage.error(tag("error"), throwable.some, () => "error") + ) + ) >> + validateMDC } }