From 30f79f326961bf3c649bf6525f9b42f8d9be9b29 Mon Sep 17 00:00:00 2001 From: Morgen Peschke Date: Thu, 13 Jun 2024 19:09:05 -0700 Subject: [PATCH 01/14] Expand test coverage of Slf4jLogger Checks: - laziness of `msg` parameter - dispatch to log4j Logger messages - MDC setup --- .../log4cats/extras/DeferredLogMessage.scala | 148 +++++++++ .../typelevel/log4cats/extras/LogLevel.scala | 19 +- .../log4cats/slf4j/internal/JTestLogger.java | 159 +++++++++ .../internal/Slf4jLoggerInternalSuite.scala | 303 +++++++++++++++++- 4 files changed, 613 insertions(+), 16 deletions(-) create mode 100644 core/shared/src/main/scala/org/typelevel/log4cats/extras/DeferredLogMessage.scala create mode 100644 slf4j/src/test/scala/org/typelevel/log4cats/slf4j/internal/JTestLogger.java 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/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..fa55ee64 --- /dev/null +++ b/slf4j/src/test/scala/org/typelevel/log4cats/slf4j/internal/JTestLogger.java @@ -0,0 +1,159 @@ +/* + * 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.DeferredLogMessage; +import org.typelevel.log4cats.extras.DeferredLogMessage$; +import scala.collection.immutable.Map; + +import java.util.ArrayList; +import java.util.List; +import java.util.concurrent.atomic.AtomicReference; +import java.util.function.Function; + +public class JTestLogger implements Logger { + 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()); + } + + // Java -> Scala compat helpers + + private final scala.Option none = scala.Option$.MODULE$.empty(); + private scala.Option some(Throwable t) { return scala.Option$.MODULE$.apply(t); } + + private Map captureContext () { + java.util.Map mdc = MDC.getCopyOfContextMap(); + if (mdc == null) { + return scala.collection.immutable.Map$.MODULE$.empty(); + } + return scala.collection.immutable.Map$.MODULE$.from( + scala.jdk.javaapi.CollectionConverters.asScala(MDC.getCopyOfContextMap()) + ); + } + + // Way to long to type the full DeferredLogMessage$.MODULE$ all the time + private DeferredLogMessage$ DLM = DeferredLogMessage$.MODULE$; + + private void save(Function, DeferredLogMessage> 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 -> DLM.trace(ctx, none, () -> msg)); } + @Override public void trace(String msg, Throwable t) { save(ctx -> DLM.trace(ctx, some(t), () -> msg)); } + + @Override public void debug(String msg) { save(ctx -> DLM.debug(ctx, none, () -> msg)); } + @Override public void debug(String msg, Throwable t) { save(ctx -> DLM.debug(ctx, some(t), () -> msg)); } + + @Override public void info(String msg) { save(ctx -> DLM.info(ctx, none, () -> msg)); } + @Override public void info(String msg, Throwable t) { save(ctx -> DLM.info(ctx, some(t), () -> msg)); } + + @Override public void warn(String msg) { save(ctx -> DLM.warn(ctx, none, () -> msg)); } + @Override public void warn(String msg, Throwable t) { save(ctx -> DLM.warn(ctx, some(t), () -> msg)); } + + @Override public void error(String msg) { save(ctx -> DLM.error(ctx, none, () -> msg)); } + @Override public void error(String msg, Throwable t) { save(ctx -> DLM.error(ctx, some(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..699be029 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,13 +17,20 @@ package org.typelevel.log4cats.slf4j package internal -import cats.effect.IO +import cats.arrow.FunctionK +import cats.effect.{IO, Resource, SyncIO} +import cats.syntax.all.* + import java.util.concurrent.Executors import java.util.concurrent.ThreadFactory import org.slf4j.MDC import munit.CatsEffectSuite +import org.typelevel.log4cats.extras.DeferredLogMessage + import scala.concurrent.ExecutionContext import scala.concurrent.ExecutionContextExecutorService +import scala.jdk.CollectionConverters.* +import scala.util.control.NoStackTrace class Slf4jLoggerInternalSuite extends CatsEffectSuite { @@ -36,16 +43,39 @@ 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() + } } } + 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 + ) + ) + ) + ) + test("Slf4jLoggerInternal resets after logging") { val variable = "foo" val initial = "yellow" @@ -57,4 +87,261 @@ class Slf4jLoggerInternalSuite extends CatsEffectSuite { .as(MDC.get(variable)) .assertEquals(initial) } + + testLoggerFixture().test("Slf4jLoggerInternal correctly sets the MDC") { testLogger => + Slf4jLogger + .getLoggerFromSlf4j[IO](testLogger) + .info(Map("foo" -> "bar"))("A log went here") >> + IO(testLogger.logs()) + .map(_.asScala.toList) + .assertEquals( + List( + DeferredLogMessage.info(Map("foo" -> "bar"), none, () => "A log went here") + ) + ) + } + + testLoggerFixture( + traceEnabled = false, + debugEnabled = false, + infoEnabled = false, + warnEnabled = false, + errorEnabled = false + ).test("Slf4jLoggerInternal is suitably lazy") { testLogger => + def die(): String = throw new IllegalStateException() + val slf4jLogger = Slf4jLogger.getLoggerFromSlf4j[IO](testLogger) + val dummyThrowable = new NoSuchElementException() with NoStackTrace + val ctx = Map("foo" -> "bar") + // If these are lazy the way they need to be, the message won't be evaluated until + // after the log level has been checked + slf4jLogger.trace(die()).assert >> + slf4jLogger.debug(die()).assert >> + slf4jLogger.info(die()).assert >> + slf4jLogger.warn(die()).assert >> + slf4jLogger.error(die()).assert >> + slf4jLogger.trace(dummyThrowable)(die()).assert >> + slf4jLogger.debug(dummyThrowable)(die()).assert >> + slf4jLogger.info(dummyThrowable)(die()).assert >> + slf4jLogger.warn(dummyThrowable)(die()).assert >> + slf4jLogger.error(dummyThrowable)(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, dummyThrowable)(die()).assert >> + slf4jLogger.debug(ctx, dummyThrowable)(die()).assert >> + slf4jLogger.info(ctx, dummyThrowable)(die()).assert >> + slf4jLogger.warn(ctx, dummyThrowable)(die()).assert >> + slf4jLogger.error(ctx, dummyThrowable)(die()).assert + } + + testLoggerFixture( + traceEnabled = false, + debugEnabled = false, + infoEnabled = false, + warnEnabled = false, + errorEnabled = false + ).test("Slf4jLoggerInternal.mapK is still lazy") { testLogger => + def die(): String = throw new IllegalStateException() + val slf4jLogger = Slf4jLogger.getLoggerFromSlf4j[IO](testLogger).mapK[IO](FunctionK.id) + val dummyThrowable = new NoSuchElementException() with NoStackTrace + val ctx = Map("foo" -> "bar") + // If these are lazy the way they need to be, the message won't be evaluated until + // after the log level has been checked + slf4jLogger.trace(die()).assert >> + slf4jLogger.debug(die()).assert >> + slf4jLogger.info(die()).assert >> + slf4jLogger.warn(die()).assert >> + slf4jLogger.error(die()).assert >> + slf4jLogger.trace(dummyThrowable)(die()).assert >> + slf4jLogger.debug(dummyThrowable)(die()).assert >> + slf4jLogger.info(dummyThrowable)(die()).assert >> + slf4jLogger.warn(dummyThrowable)(die()).assert >> + slf4jLogger.error(dummyThrowable)(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, dummyThrowable)(die()).assert >> + slf4jLogger.debug(ctx, dummyThrowable)(die()).assert >> + slf4jLogger.info(ctx, dummyThrowable)(die()).assert >> + slf4jLogger.warn(ctx, dummyThrowable)(die()).assert >> + slf4jLogger.error(ctx, dummyThrowable)(die()).assert + } + + testLoggerFixture( + traceEnabled = false, + debugEnabled = false, + infoEnabled = false, + warnEnabled = false, + errorEnabled = false + ).test("Slf4jLoggerInternal.withModifiedString is still lazy") { testLogger => + def die(): String = throw new IllegalStateException() + val slf4jLogger = + Slf4jLogger.getLoggerFromSlf4j[IO](testLogger).withModifiedString(_.toUpperCase) + val dummyThrowable = new NoSuchElementException() with NoStackTrace + val ctx = Map("foo" -> "bar") + // If these are lazy the way they need to be, the message won't be evaluated until + // after the log level has been checked + slf4jLogger.trace(die()).assert >> + slf4jLogger.debug(die()).assert >> + slf4jLogger.info(die()).assert >> + slf4jLogger.warn(die()).assert >> + slf4jLogger.error(die()).assert >> + slf4jLogger.trace(dummyThrowable)(die()).assert >> + slf4jLogger.debug(dummyThrowable)(die()).assert >> + slf4jLogger.info(dummyThrowable)(die()).assert >> + slf4jLogger.warn(dummyThrowable)(die()).assert >> + slf4jLogger.error(dummyThrowable)(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, dummyThrowable)(die()).assert >> + slf4jLogger.debug(ctx, dummyThrowable)(die()).assert >> + slf4jLogger.info(ctx, dummyThrowable)(die()).assert >> + slf4jLogger.warn(ctx, dummyThrowable)(die()).assert >> + slf4jLogger.error(ctx, dummyThrowable)(die()).assert + } + + testLoggerFixture( + traceEnabled = false, + debugEnabled = false, + infoEnabled = false, + warnEnabled = false, + errorEnabled = false + ).test("Slf4jLoggerInternal.addContext is still lazy") { testLogger => + def die(): String = throw new IllegalStateException() + val slf4jLogger = Slf4jLogger.getLoggerFromSlf4j[IO](testLogger).addContext(Map("bar" -> "foo")) + val dummyThrowable = new NoSuchElementException() with NoStackTrace + val ctx = Map("foo" -> "bar") + // If these are lazy the way they need to be, the message won't be evaluated until + // after the log level has been checked + slf4jLogger.trace(die()).assert >> + slf4jLogger.debug(die()).assert >> + slf4jLogger.info(die()).assert >> + slf4jLogger.warn(die()).assert >> + slf4jLogger.error(die()).assert >> + slf4jLogger.trace(dummyThrowable)(die()).assert >> + slf4jLogger.debug(dummyThrowable)(die()).assert >> + slf4jLogger.info(dummyThrowable)(die()).assert >> + slf4jLogger.warn(dummyThrowable)(die()).assert >> + slf4jLogger.error(dummyThrowable)(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, dummyThrowable)(die()).assert >> + slf4jLogger.debug(ctx, dummyThrowable)(die()).assert >> + slf4jLogger.info(ctx, dummyThrowable)(die()).assert >> + slf4jLogger.warn(ctx, dummyThrowable)(die()).assert >> + slf4jLogger.error(ctx, dummyThrowable)(die()).assert + } + + testLoggerFixture().test("Slf4jLoggerInternal gets the dispatching right") { testLogger => + val slf4jLogger = Slf4jLogger.getLoggerFromSlf4j[IO](testLogger) + def throwable(tag: String) = new NoSuchElementException(tag) with NoStackTrace + def ctx(tag: String) = Map("tag" -> tag) + // If these are lazy the way they need to be, the message won't be evaluated until + // after the log level has been checked + slf4jLogger.trace("trace(msg)").assert >> + slf4jLogger.debug("debug(msg)").assert >> + slf4jLogger.info("info(msg)").assert >> + slf4jLogger.warn("warn(msg)").assert >> + slf4jLogger.error("error(msg)").assert >> + IO(testLogger.logs().asScala.toList).assertEquals( + List( + DeferredLogMessage.trace(Map.empty, none, () => "trace(msg)"), + DeferredLogMessage.debug(Map.empty, none, () => "debug(msg)"), + DeferredLogMessage.info(Map.empty, none, () => "info(msg)"), + DeferredLogMessage.warn(Map.empty, none, () => "warn(msg)"), + DeferredLogMessage.error(Map.empty, none, () => "error(msg)") + ) + ) >> + IO(testLogger.reset()) >> + slf4jLogger.trace(throwable("trace(t)(msg)"))("trace(t)(msg)").assert >> + slf4jLogger.debug(throwable("debug(t)(msg)"))("debug(t)(msg)").assert >> + slf4jLogger.info(throwable("info(t)(msg)"))("info(t)(msg)").assert >> + slf4jLogger.warn(throwable("warn(t)(msg)"))("warn(t)(msg)").assert >> + slf4jLogger.error(throwable("error(t)(msg)"))("error(t)(msg)").assert >> + IO(testLogger.logs().asScala.toList).assertEquals( + List( + DeferredLogMessage + .trace(Map.empty, throwable("trace(t)(msg)").some, () => "trace(t)(msg)"), + DeferredLogMessage + .debug(Map.empty, throwable("debug(t)(msg)").some, () => "debug(t)(msg)"), + DeferredLogMessage.info(Map.empty, throwable("info(t)(msg)").some, () => "info(t)(msg)"), + DeferredLogMessage.warn(Map.empty, throwable("warn(t)(msg)").some, () => "warn(t)(msg)"), + DeferredLogMessage.error( + Map.empty, + throwable("error(t)(msg)").some, + () => "error(t)(msg)" + ) + ) + ) >> + IO(testLogger.reset()) >> + slf4jLogger.trace(ctx("trace(ctx)(msg)"))("trace(ctx)(msg)").assert >> + slf4jLogger.debug(ctx("debug(ctx)(msg)"))("debug(ctx)(msg)").assert >> + slf4jLogger.info(ctx("info(ctx)(msg)"))("info(ctx)(msg)").assert >> + slf4jLogger.warn(ctx("warn(ctx)(msg)"))("warn(ctx)(msg)").assert >> + slf4jLogger.error(ctx("error(ctx)(msg)"))("error(ctx)(msg)").assert >> + IO(testLogger.logs().asScala.toList).assertEquals( + List( + DeferredLogMessage.trace(ctx("trace(ctx)(msg)"), none, () => "trace(ctx)(msg)"), + DeferredLogMessage.debug(ctx("debug(ctx)(msg)"), none, () => "debug(ctx)(msg)"), + DeferredLogMessage.info(ctx("info(ctx)(msg)"), none, () => "info(ctx)(msg)"), + DeferredLogMessage.warn(ctx("warn(ctx)(msg)"), none, () => "warn(ctx)(msg)"), + DeferredLogMessage.error(ctx("error(ctx)(msg)"), none, () => "error(ctx)(msg)") + ) + ) >> + IO(testLogger.reset()) >> + slf4jLogger + .trace(ctx("trace(ctx, t)(msg)"), throwable("trace(ctx, t)(msg)"))("trace(ctx, t)(msg)") + .assert >> + slf4jLogger + .debug(ctx("debug(ctx, t)(msg)"), throwable("debug(ctx, t)(msg)"))("debug(ctx, t)(msg)") + .assert >> + slf4jLogger + .info(ctx("info(ctx, t)(msg)"), throwable("info(ctx, t)(msg)"))("info(ctx, t)(msg)") + .assert >> + slf4jLogger + .warn(ctx("warn(ctx, t)(msg)"), throwable("warn(ctx, t)(msg)"))("warn(ctx, t)(msg)") + .assert >> + slf4jLogger + .error(ctx("error(ctx, t)(msg)"), throwable("error(ctx, t)(msg)"))("error(ctx, t)(msg)") + .assert >> + IO(testLogger.logs().asScala.toList).assertEquals( + List( + DeferredLogMessage.trace( + ctx("trace(ctx, t)(msg)"), + throwable("trace(ctx, t)(msg)").some, + () => "trace(ctx, t)(msg)" + ), + DeferredLogMessage.debug( + ctx("debug(ctx, t)(msg)"), + throwable("debug(ctx, t)(msg)").some, + () => "debug(ctx, t)(msg)" + ), + DeferredLogMessage.info( + ctx("info(ctx, t)(msg)"), + throwable("info(ctx, t)(msg)").some, + () => "info(ctx, t)(msg)" + ), + DeferredLogMessage.warn( + ctx("warn(ctx, t)(msg)"), + throwable("warn(ctx, t)(msg)").some, + () => "warn(ctx, t)(msg)" + ), + DeferredLogMessage.error( + ctx("error(ctx, t)(msg)"), + throwable("error(ctx, t)(msg)").some, + () => "error(ctx, t)(msg)" + ) + ) + ) + } } From a808c2c0f4a5930dc1ce7b9283a89fa06072d5a0 Mon Sep 17 00:00:00 2001 From: Morgen Peschke Date: Mon, 17 Jun 2024 16:00:21 -0700 Subject: [PATCH 02/14] Work around the collections change between 2.12 and 2.13 --- .../log4cats/slf4j/internal/JTestLogger.java | 118 ++++++++---- .../internal/Slf4jLoggerInternalSuite.scala | 172 +++++++++++------- 2 files changed, 194 insertions(+), 96 deletions(-) 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 index fa55ee64..7c66fe52 100644 --- a/slf4j/src/test/scala/org/typelevel/log4cats/slf4j/internal/JTestLogger.java +++ b/slf4j/src/test/scala/org/typelevel/log4cats/slf4j/internal/JTestLogger.java @@ -19,23 +19,89 @@ import org.slf4j.Logger; import org.slf4j.MDC; import org.slf4j.Marker; -import org.typelevel.log4cats.extras.DeferredLogMessage; -import org.typelevel.log4cats.extras.DeferredLogMessage$; -import scala.collection.immutable.Map; +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; + private final AtomicReference> loggedMessages; + public JTestLogger(String loggerName, boolean traceEnabled, @@ -49,35 +115,17 @@ public JTestLogger(String loggerName, this.infoEnabled = infoEnabled; this.warnEnabled = warnEnabled; this.errorEnabled = errorEnabled; - loggedMessages = new AtomicReference<>(new ArrayList()); - } - - // Java -> Scala compat helpers - - private final scala.Option none = scala.Option$.MODULE$.empty(); - private scala.Option some(Throwable t) { return scala.Option$.MODULE$.apply(t); } - - private Map captureContext () { - java.util.Map mdc = MDC.getCopyOfContextMap(); - if (mdc == null) { - return scala.collection.immutable.Map$.MODULE$.empty(); - } - return scala.collection.immutable.Map$.MODULE$.from( - scala.jdk.javaapi.CollectionConverters.asScala(MDC.getCopyOfContextMap()) - ); + loggedMessages = new AtomicReference<>(new ArrayList()); } - // Way to long to type the full DeferredLogMessage$.MODULE$ all the time - private DeferredLogMessage$ DLM = DeferredLogMessage$.MODULE$; - - private void save(Function, DeferredLogMessage> mkLogMessage) { + private void save(Function, TestLogMessage> mkLogMessage) { loggedMessages.updateAndGet(ll -> { ll.add(mkLogMessage.apply(captureContext())); return ll; }); } - public List logs() { return loggedMessages.get(); } + public List logs() { return loggedMessages.get(); } public void reset() { loggedMessages.set(new ArrayList<>()); } @Override public String getName() { return loggerName;} @@ -95,20 +143,20 @@ private void save(Function, DeferredLogMessage> mkLogMessage @Override public boolean isWarnEnabled(Marker marker) { return warnEnabled; } @Override public boolean isErrorEnabled(Marker marker) { return errorEnabled; } - @Override public void trace(String msg) { save(ctx -> DLM.trace(ctx, none, () -> msg)); } - @Override public void trace(String msg, Throwable t) { save(ctx -> DLM.trace(ctx, some(t), () -> msg)); } + @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 -> DLM.debug(ctx, none, () -> msg)); } - @Override public void debug(String msg, Throwable t) { save(ctx -> DLM.debug(ctx, some(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 -> DLM.info(ctx, none, () -> msg)); } - @Override public void info(String msg, Throwable t) { save(ctx -> DLM.info(ctx, some(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 -> DLM.warn(ctx, none, () -> msg)); } - @Override public void warn(String msg, Throwable t) { save(ctx -> DLM.warn(ctx, some(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 -> DLM.error(ctx, none, () -> msg)); } - @Override public void error(String msg, Throwable t) { save(ctx -> DLM.error(ctx, some(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 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 699be029..db09ca75 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 @@ -26,10 +26,15 @@ import java.util.concurrent.ThreadFactory import org.slf4j.MDC import munit.CatsEffectSuite 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.jdk.CollectionConverters.* import scala.util.control.NoStackTrace class Slf4jLoggerInternalSuite extends CatsEffectSuite { @@ -88,12 +93,47 @@ class Slf4jLoggerInternalSuite extends CatsEffectSuite { .assertEquals(initial) } + // 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 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 => Slf4jLogger .getLoggerFromSlf4j[IO](testLogger) .info(Map("foo" -> "bar"))("A log went here") >> IO(testLogger.logs()) - .map(_.asScala.toList) + .map(toDeferredLogs) .assertEquals( List( DeferredLogMessage.info(Map("foo" -> "bar"), none, () => "A log went here") @@ -253,51 +293,59 @@ class Slf4jLoggerInternalSuite extends CatsEffectSuite { slf4jLogger.info("info(msg)").assert >> slf4jLogger.warn("warn(msg)").assert >> slf4jLogger.error("error(msg)").assert >> - IO(testLogger.logs().asScala.toList).assertEquals( - List( - DeferredLogMessage.trace(Map.empty, none, () => "trace(msg)"), - DeferredLogMessage.debug(Map.empty, none, () => "debug(msg)"), - DeferredLogMessage.info(Map.empty, none, () => "info(msg)"), - DeferredLogMessage.warn(Map.empty, none, () => "warn(msg)"), - DeferredLogMessage.error(Map.empty, none, () => "error(msg)") - ) - ) >> + IO(testLogger.logs()) + .map(toDeferredLogs) + .assertEquals( + List( + DeferredLogMessage.trace(Map.empty, none, () => "trace(msg)"), + DeferredLogMessage.debug(Map.empty, none, () => "debug(msg)"), + DeferredLogMessage.info(Map.empty, none, () => "info(msg)"), + DeferredLogMessage.warn(Map.empty, none, () => "warn(msg)"), + DeferredLogMessage.error(Map.empty, none, () => "error(msg)") + ) + ) >> IO(testLogger.reset()) >> slf4jLogger.trace(throwable("trace(t)(msg)"))("trace(t)(msg)").assert >> slf4jLogger.debug(throwable("debug(t)(msg)"))("debug(t)(msg)").assert >> slf4jLogger.info(throwable("info(t)(msg)"))("info(t)(msg)").assert >> slf4jLogger.warn(throwable("warn(t)(msg)"))("warn(t)(msg)").assert >> slf4jLogger.error(throwable("error(t)(msg)"))("error(t)(msg)").assert >> - IO(testLogger.logs().asScala.toList).assertEquals( - List( - DeferredLogMessage - .trace(Map.empty, throwable("trace(t)(msg)").some, () => "trace(t)(msg)"), - DeferredLogMessage - .debug(Map.empty, throwable("debug(t)(msg)").some, () => "debug(t)(msg)"), - DeferredLogMessage.info(Map.empty, throwable("info(t)(msg)").some, () => "info(t)(msg)"), - DeferredLogMessage.warn(Map.empty, throwable("warn(t)(msg)").some, () => "warn(t)(msg)"), - DeferredLogMessage.error( - Map.empty, - throwable("error(t)(msg)").some, - () => "error(t)(msg)" + IO(testLogger.logs()) + .map(toDeferredLogs) + .assertEquals( + List( + DeferredLogMessage + .trace(Map.empty, throwable("trace(t)(msg)").some, () => "trace(t)(msg)"), + DeferredLogMessage + .debug(Map.empty, throwable("debug(t)(msg)").some, () => "debug(t)(msg)"), + DeferredLogMessage + .info(Map.empty, throwable("info(t)(msg)").some, () => "info(t)(msg)"), + DeferredLogMessage + .warn(Map.empty, throwable("warn(t)(msg)").some, () => "warn(t)(msg)"), + DeferredLogMessage.error( + Map.empty, + throwable("error(t)(msg)").some, + () => "error(t)(msg)" + ) ) - ) - ) >> + ) >> IO(testLogger.reset()) >> slf4jLogger.trace(ctx("trace(ctx)(msg)"))("trace(ctx)(msg)").assert >> slf4jLogger.debug(ctx("debug(ctx)(msg)"))("debug(ctx)(msg)").assert >> slf4jLogger.info(ctx("info(ctx)(msg)"))("info(ctx)(msg)").assert >> slf4jLogger.warn(ctx("warn(ctx)(msg)"))("warn(ctx)(msg)").assert >> slf4jLogger.error(ctx("error(ctx)(msg)"))("error(ctx)(msg)").assert >> - IO(testLogger.logs().asScala.toList).assertEquals( - List( - DeferredLogMessage.trace(ctx("trace(ctx)(msg)"), none, () => "trace(ctx)(msg)"), - DeferredLogMessage.debug(ctx("debug(ctx)(msg)"), none, () => "debug(ctx)(msg)"), - DeferredLogMessage.info(ctx("info(ctx)(msg)"), none, () => "info(ctx)(msg)"), - DeferredLogMessage.warn(ctx("warn(ctx)(msg)"), none, () => "warn(ctx)(msg)"), - DeferredLogMessage.error(ctx("error(ctx)(msg)"), none, () => "error(ctx)(msg)") - ) - ) >> + IO(testLogger.logs()) + .map(toDeferredLogs) + .assertEquals( + List( + DeferredLogMessage.trace(ctx("trace(ctx)(msg)"), none, () => "trace(ctx)(msg)"), + DeferredLogMessage.debug(ctx("debug(ctx)(msg)"), none, () => "debug(ctx)(msg)"), + DeferredLogMessage.info(ctx("info(ctx)(msg)"), none, () => "info(ctx)(msg)"), + DeferredLogMessage.warn(ctx("warn(ctx)(msg)"), none, () => "warn(ctx)(msg)"), + DeferredLogMessage.error(ctx("error(ctx)(msg)"), none, () => "error(ctx)(msg)") + ) + ) >> IO(testLogger.reset()) >> slf4jLogger .trace(ctx("trace(ctx, t)(msg)"), throwable("trace(ctx, t)(msg)"))("trace(ctx, t)(msg)") @@ -314,34 +362,36 @@ class Slf4jLoggerInternalSuite extends CatsEffectSuite { slf4jLogger .error(ctx("error(ctx, t)(msg)"), throwable("error(ctx, t)(msg)"))("error(ctx, t)(msg)") .assert >> - IO(testLogger.logs().asScala.toList).assertEquals( - List( - DeferredLogMessage.trace( - ctx("trace(ctx, t)(msg)"), - throwable("trace(ctx, t)(msg)").some, - () => "trace(ctx, t)(msg)" - ), - DeferredLogMessage.debug( - ctx("debug(ctx, t)(msg)"), - throwable("debug(ctx, t)(msg)").some, - () => "debug(ctx, t)(msg)" - ), - DeferredLogMessage.info( - ctx("info(ctx, t)(msg)"), - throwable("info(ctx, t)(msg)").some, - () => "info(ctx, t)(msg)" - ), - DeferredLogMessage.warn( - ctx("warn(ctx, t)(msg)"), - throwable("warn(ctx, t)(msg)").some, - () => "warn(ctx, t)(msg)" - ), - DeferredLogMessage.error( - ctx("error(ctx, t)(msg)"), - throwable("error(ctx, t)(msg)").some, - () => "error(ctx, t)(msg)" + IO(testLogger.logs()) + .map(toDeferredLogs) + .assertEquals( + List( + DeferredLogMessage.trace( + ctx("trace(ctx, t)(msg)"), + throwable("trace(ctx, t)(msg)").some, + () => "trace(ctx, t)(msg)" + ), + DeferredLogMessage.debug( + ctx("debug(ctx, t)(msg)"), + throwable("debug(ctx, t)(msg)").some, + () => "debug(ctx, t)(msg)" + ), + DeferredLogMessage.info( + ctx("info(ctx, t)(msg)"), + throwable("info(ctx, t)(msg)").some, + () => "info(ctx, t)(msg)" + ), + DeferredLogMessage.warn( + ctx("warn(ctx, t)(msg)"), + throwable("warn(ctx, t)(msg)").some, + () => "warn(ctx, t)(msg)" + ), + DeferredLogMessage.error( + ctx("error(ctx, t)(msg)"), + throwable("error(ctx, t)(msg)").some, + () => "error(ctx, t)(msg)" + ) ) ) - ) } } From 97ad06697ff0f88771ff1fbf2e9922a2ba54a198 Mon Sep 17 00:00:00 2001 From: Morgen Peschke Date: Tue, 25 Jun 2024 15:12:31 -0700 Subject: [PATCH 03/14] Add test explicitly demonstrating MDC behavior --- .../slf4j/internal/Slf4jLoggerInternalSuite.scala | 13 +++++++++++++ 1 file changed, 13 insertions(+) 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 db09ca75..976dec24 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 @@ -141,6 +141,19 @@ class Slf4jLoggerInternalSuite extends CatsEffectSuite { ) } + testLoggerFixture().test("Slf4jLoggerInternal ignores(?) values already in the MDC") { testLogger => + IO.delay(MDC.put("baz", "bar")) >> + 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") + ), + clue("Context should not include baz->bar") + ) + } + testLoggerFixture( traceEnabled = false, debugEnabled = false, From 2d5bc1c61e3b5fd80ff31dc1e9b599dd564cdf8c Mon Sep 17 00:00:00 2001 From: Morgen Peschke Date: Tue, 25 Jun 2024 15:46:53 -0700 Subject: [PATCH 04/14] Attempt to salvage the log if the MDC is busted --- .../slf4j/internal/Slf4jLoggerInternal.scala | 12 +++++++----- 1 file changed, 7 insertions(+), 5 deletions(-) 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..7e1bcd37 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 @@ -41,11 +41,13 @@ private[slf4j] object Slf4jLoggerInternal { )(implicit F: Sync[F]): F[Unit] = { val ifEnabled = F.delay { - val backup = MDC.getCopyOfContextMap() - - for { - (k, v) <- ctx - } MDC.put(k, v) + val backup = + try MDC.getCopyOfContextMap() + catch { + case _: IllegalStateException => + // Assuming this happens, better to just roll with it and try to get a log out + new util.HashMap[String, String]() + } try logging() finally From 31abf1712fe50c1d9d984adb935e873e3e5e6388 Mon Sep 17 00:00:00 2001 From: Morgen Peschke Date: Tue, 25 Jun 2024 15:47:24 -0700 Subject: [PATCH 05/14] Only log the context, not the MDC contents --- .../log4cats/slf4j/internal/Slf4jLoggerInternal.scala | 10 ++++++++-- 1 file changed, 8 insertions(+), 2 deletions(-) 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 7e1bcd37..0dce3bc8 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 @@ -22,6 +22,8 @@ import cats.effect._ import org.slf4j.{Logger => JLogger} import org.slf4j.MDC +import java.util + private[slf4j] object Slf4jLoggerInternal { final val singletonsByName = true @@ -49,8 +51,12 @@ private[slf4j] object Slf4jLoggerInternal { new util.HashMap[String, String]() } - 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) } From 2085d5d168097b1b949850ce9c410df1a8141c4d Mon Sep 17 00:00:00 2001 From: Morgen Peschke Date: Tue, 25 Jun 2024 15:47:44 -0700 Subject: [PATCH 06/14] Improve the test name --- .../log4cats/slf4j/internal/Slf4jLoggerInternalSuite.scala | 4 +++- 1 file changed, 3 insertions(+), 1 deletion(-) 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 976dec24..4d20249e 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 @@ -141,7 +141,9 @@ class Slf4jLoggerInternalSuite extends CatsEffectSuite { ) } - testLoggerFixture().test("Slf4jLoggerInternal ignores(?) values already in the MDC") { testLogger => + testLoggerFixture().test( + "Slf4jLoggerInternal does not include values previously in the MDC in the log's context" + ) { testLogger => IO.delay(MDC.put("baz", "bar")) >> Slf4jLogger.getLoggerFromSlf4j[IO](testLogger).info(Map("foo" -> "bar"))("A log went here") >> IO(testLogger.logs()) From c7c0d333c67130b5b5e97222a22f435d72653d91 Mon Sep 17 00:00:00 2001 From: Morgen Peschke Date: Wed, 26 Jun 2024 09:35:14 -0700 Subject: [PATCH 07/14] Update tests to capture additional MDC failure mode MDC leaks into context when logging without context, because it doesn't go through the codepath that clears the MDC before logging --- .../internal/Slf4jLoggerInternalSuite.scala | 357 +++++++++--------- 1 file changed, 172 insertions(+), 185 deletions(-) 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 4d20249e..b4ed249c 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 @@ -24,7 +24,7 @@ import cats.syntax.all.* import java.util.concurrent.Executors import java.util.concurrent.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 @@ -59,13 +59,13 @@ class Slf4jLoggerInternalSuite extends CatsEffectSuite { } } - def testLoggerFixture( - traceEnabled: Boolean = true, - debugEnabled: Boolean = true, - infoEnabled: Boolean = true, - warnEnabled: Boolean = true, - errorEnabled: Boolean = true - ): SyncIO[FunFixture[JTestLogger]] = + 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( @@ -81,18 +81,6 @@ class Slf4jLoggerInternalSuite extends CatsEffectSuite { ) ) - 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) - } - // 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 @@ -114,6 +102,38 @@ class Slf4jLoggerInternalSuite extends CatsEffectSuite { 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") { + 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 => @@ -129,31 +149,24 @@ class Slf4jLoggerInternalSuite extends CatsEffectSuite { .collect(toScalaList[DeferredLogMessage]) testLoggerFixture().test("Slf4jLoggerInternal correctly sets the MDC") { testLogger => - 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") - ) - ) + 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 => - IO.delay(MDC.put("baz", "bar")) >> - 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") - ), - clue("Context should not include baz->bar") - ) + 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( @@ -163,32 +176,32 @@ class Slf4jLoggerInternalSuite extends CatsEffectSuite { warnEnabled = false, errorEnabled = false ).test("Slf4jLoggerInternal is suitably lazy") { testLogger => - def die(): String = throw new IllegalStateException() val slf4jLogger = Slf4jLogger.getLoggerFromSlf4j[IO](testLogger) - val dummyThrowable = new NoSuchElementException() with NoStackTrace - val ctx = Map("foo" -> "bar") + 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 - slf4jLogger.trace(die()).assert >> + prepareMDC >> + slf4jLogger.trace(die()).assert >> slf4jLogger.debug(die()).assert >> slf4jLogger.info(die()).assert >> slf4jLogger.warn(die()).assert >> slf4jLogger.error(die()).assert >> - slf4jLogger.trace(dummyThrowable)(die()).assert >> - slf4jLogger.debug(dummyThrowable)(die()).assert >> - slf4jLogger.info(dummyThrowable)(die()).assert >> - slf4jLogger.warn(dummyThrowable)(die()).assert >> - slf4jLogger.error(dummyThrowable)(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, dummyThrowable)(die()).assert >> - slf4jLogger.debug(ctx, dummyThrowable)(die()).assert >> - slf4jLogger.info(ctx, dummyThrowable)(die()).assert >> - slf4jLogger.warn(ctx, dummyThrowable)(die()).assert >> - slf4jLogger.error(ctx, dummyThrowable)(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( @@ -198,32 +211,32 @@ class Slf4jLoggerInternalSuite extends CatsEffectSuite { warnEnabled = false, errorEnabled = false ).test("Slf4jLoggerInternal.mapK is still lazy") { testLogger => - def die(): String = throw new IllegalStateException() val slf4jLogger = Slf4jLogger.getLoggerFromSlf4j[IO](testLogger).mapK[IO](FunctionK.id) - val dummyThrowable = new NoSuchElementException() with NoStackTrace - val ctx = Map("foo" -> "bar") + 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 - slf4jLogger.trace(die()).assert >> + prepareMDC >> + slf4jLogger.trace(die()).assert >> slf4jLogger.debug(die()).assert >> slf4jLogger.info(die()).assert >> slf4jLogger.warn(die()).assert >> slf4jLogger.error(die()).assert >> - slf4jLogger.trace(dummyThrowable)(die()).assert >> - slf4jLogger.debug(dummyThrowable)(die()).assert >> - slf4jLogger.info(dummyThrowable)(die()).assert >> - slf4jLogger.warn(dummyThrowable)(die()).assert >> - slf4jLogger.error(dummyThrowable)(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, dummyThrowable)(die()).assert >> - slf4jLogger.debug(ctx, dummyThrowable)(die()).assert >> - slf4jLogger.info(ctx, dummyThrowable)(die()).assert >> - slf4jLogger.warn(ctx, dummyThrowable)(die()).assert >> - slf4jLogger.error(ctx, dummyThrowable)(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( @@ -233,33 +246,32 @@ class Slf4jLoggerInternalSuite extends CatsEffectSuite { warnEnabled = false, errorEnabled = false ).test("Slf4jLoggerInternal.withModifiedString is still lazy") { testLogger => - def die(): String = throw new IllegalStateException() - val slf4jLogger = - Slf4jLogger.getLoggerFromSlf4j[IO](testLogger).withModifiedString(_.toUpperCase) - val dummyThrowable = new NoSuchElementException() with NoStackTrace - val ctx = Map("foo" -> "bar") + 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 - slf4jLogger.trace(die()).assert >> + prepareMDC >> + slf4jLogger.trace(die()).assert >> slf4jLogger.debug(die()).assert >> slf4jLogger.info(die()).assert >> slf4jLogger.warn(die()).assert >> slf4jLogger.error(die()).assert >> - slf4jLogger.trace(dummyThrowable)(die()).assert >> - slf4jLogger.debug(dummyThrowable)(die()).assert >> - slf4jLogger.info(dummyThrowable)(die()).assert >> - slf4jLogger.warn(dummyThrowable)(die()).assert >> - slf4jLogger.error(dummyThrowable)(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, dummyThrowable)(die()).assert >> - slf4jLogger.debug(ctx, dummyThrowable)(die()).assert >> - slf4jLogger.info(ctx, dummyThrowable)(die()).assert >> - slf4jLogger.warn(ctx, dummyThrowable)(die()).assert >> - slf4jLogger.error(ctx, dummyThrowable)(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( @@ -269,144 +281,119 @@ class Slf4jLoggerInternalSuite extends CatsEffectSuite { warnEnabled = false, errorEnabled = false ).test("Slf4jLoggerInternal.addContext is still lazy") { testLogger => - def die(): String = throw new IllegalStateException() val slf4jLogger = Slf4jLogger.getLoggerFromSlf4j[IO](testLogger).addContext(Map("bar" -> "foo")) - val dummyThrowable = new NoSuchElementException() with NoStackTrace - val ctx = Map("foo" -> "bar") + 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 - slf4jLogger.trace(die()).assert >> + prepareMDC >> + slf4jLogger.trace(die()).assert >> slf4jLogger.debug(die()).assert >> slf4jLogger.info(die()).assert >> slf4jLogger.warn(die()).assert >> slf4jLogger.error(die()).assert >> - slf4jLogger.trace(dummyThrowable)(die()).assert >> - slf4jLogger.debug(dummyThrowable)(die()).assert >> - slf4jLogger.info(dummyThrowable)(die()).assert >> - slf4jLogger.warn(dummyThrowable)(die()).assert >> - slf4jLogger.error(dummyThrowable)(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, dummyThrowable)(die()).assert >> - slf4jLogger.debug(ctx, dummyThrowable)(die()).assert >> - slf4jLogger.info(ctx, dummyThrowable)(die()).assert >> - slf4jLogger.warn(ctx, dummyThrowable)(die()).assert >> - slf4jLogger.error(ctx, dummyThrowable)(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") { testLogger => + testLoggerFixture().test("Slf4jLoggerInternal gets the dispatching right (msg)") { testLogger => val slf4jLogger = Slf4jLogger.getLoggerFromSlf4j[IO](testLogger) - def throwable(tag: String) = new NoSuchElementException(tag) with NoStackTrace - def ctx(tag: String) = Map("tag" -> tag) - // If these are lazy the way they need to be, the message won't be evaluated until - // after the log level has been checked - slf4jLogger.trace("trace(msg)").assert >> - slf4jLogger.debug("debug(msg)").assert >> - slf4jLogger.info("info(msg)").assert >> - slf4jLogger.warn("warn(msg)").assert >> - slf4jLogger.error("error(msg)").assert >> + 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(msg)"), - DeferredLogMessage.debug(Map.empty, none, () => "debug(msg)"), - DeferredLogMessage.info(Map.empty, none, () => "info(msg)"), - DeferredLogMessage.warn(Map.empty, none, () => "warn(msg)"), - DeferredLogMessage.error(Map.empty, none, () => "error(msg)") + 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") ) ) >> - IO(testLogger.reset()) >> - slf4jLogger.trace(throwable("trace(t)(msg)"))("trace(t)(msg)").assert >> - slf4jLogger.debug(throwable("debug(t)(msg)"))("debug(t)(msg)").assert >> - slf4jLogger.info(throwable("info(t)(msg)"))("info(t)(msg)").assert >> - slf4jLogger.warn(throwable("warn(t)(msg)"))("warn(t)(msg)").assert >> - slf4jLogger.error(throwable("error(t)(msg)"))("error(t)(msg)").assert >> + 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("trace(t)(msg)").some, () => "trace(t)(msg)"), - DeferredLogMessage - .debug(Map.empty, throwable("debug(t)(msg)").some, () => "debug(t)(msg)"), - DeferredLogMessage - .info(Map.empty, throwable("info(t)(msg)").some, () => "info(t)(msg)"), - DeferredLogMessage - .warn(Map.empty, throwable("warn(t)(msg)").some, () => "warn(t)(msg)"), - DeferredLogMessage.error( - Map.empty, - throwable("error(t)(msg)").some, - () => "error(t)(msg)" - ) + 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") ) ) >> - IO(testLogger.reset()) >> - slf4jLogger.trace(ctx("trace(ctx)(msg)"))("trace(ctx)(msg)").assert >> - slf4jLogger.debug(ctx("debug(ctx)(msg)"))("debug(ctx)(msg)").assert >> - slf4jLogger.info(ctx("info(ctx)(msg)"))("info(ctx)(msg)").assert >> - slf4jLogger.warn(ctx("warn(ctx)(msg)"))("warn(ctx)(msg)").assert >> - slf4jLogger.error(ctx("error(ctx)(msg)"))("error(ctx)(msg)").assert >> + 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(ctx("trace(ctx)(msg)"), none, () => "trace(ctx)(msg)"), - DeferredLogMessage.debug(ctx("debug(ctx)(msg)"), none, () => "debug(ctx)(msg)"), - DeferredLogMessage.info(ctx("info(ctx)(msg)"), none, () => "info(ctx)(msg)"), - DeferredLogMessage.warn(ctx("warn(ctx)(msg)"), none, () => "warn(ctx)(msg)"), - DeferredLogMessage.error(ctx("error(ctx)(msg)"), none, () => "error(ctx)(msg)") + 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") ) ) >> - IO(testLogger.reset()) >> - slf4jLogger - .trace(ctx("trace(ctx, t)(msg)"), throwable("trace(ctx, t)(msg)"))("trace(ctx, t)(msg)") - .assert >> - slf4jLogger - .debug(ctx("debug(ctx, t)(msg)"), throwable("debug(ctx, t)(msg)"))("debug(ctx, t)(msg)") - .assert >> - slf4jLogger - .info(ctx("info(ctx, t)(msg)"), throwable("info(ctx, t)(msg)"))("info(ctx, t)(msg)") - .assert >> - slf4jLogger - .warn(ctx("warn(ctx, t)(msg)"), throwable("warn(ctx, t)(msg)"))("warn(ctx, t)(msg)") - .assert >> - slf4jLogger - .error(ctx("error(ctx, t)(msg)"), throwable("error(ctx, t)(msg)"))("error(ctx, t)(msg)") - .assert >> + 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( - ctx("trace(ctx, t)(msg)"), - throwable("trace(ctx, t)(msg)").some, - () => "trace(ctx, t)(msg)" - ), - DeferredLogMessage.debug( - ctx("debug(ctx, t)(msg)"), - throwable("debug(ctx, t)(msg)").some, - () => "debug(ctx, t)(msg)" - ), - DeferredLogMessage.info( - ctx("info(ctx, t)(msg)"), - throwable("info(ctx, t)(msg)").some, - () => "info(ctx, t)(msg)" - ), - DeferredLogMessage.warn( - ctx("warn(ctx, t)(msg)"), - throwable("warn(ctx, t)(msg)").some, - () => "warn(ctx, t)(msg)" - ), - DeferredLogMessage.error( - ctx("error(ctx, t)(msg)"), - throwable("error(ctx, t)(msg)").some, - () => "error(ctx, t)(msg)" - ) + 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 } } From 7569e64b8435ece2e5190a51df7255adb6d93b6f Mon Sep 17 00:00:00 2001 From: Morgen Peschke Date: Wed, 26 Jun 2024 09:36:59 -0700 Subject: [PATCH 08/14] Colocate the logging levels in Slf4jLoggerInternal --- .../slf4j/internal/Slf4jLoggerInternal.scala | 20 +++++++++++-------- 1 file changed, 12 insertions(+), 8 deletions(-) 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 0dce3bc8..7f562010 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 @@ -91,6 +91,9 @@ private[slf4j] object Slf4jLoggerInternal { .ifM(F.suspend(sync)(logger.trace(msg)), F.unit) 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) @@ -99,6 +102,9 @@ private[slf4j] object Slf4jLoggerInternal { .ifM(F.suspend(sync)(logger.debug(msg)), F.unit) 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) @@ -107,6 +113,9 @@ private[slf4j] object Slf4jLoggerInternal { .ifM(F.suspend(sync)(logger.info(msg)), F.unit) 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) @@ -115,6 +124,9 @@ private[slf4j] object Slf4jLoggerInternal { .ifM(F.suspend(sync)(logger.warn(msg)), F.unit) 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) @@ -123,14 +135,6 @@ private[slf4j] object Slf4jLoggerInternal { .ifM(F.suspend(sync)(logger.error(msg)), F.unit) 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)) } From e68ce858aa874cf80416c664244016ec1871a4ac Mon Sep 17 00:00:00 2001 From: Morgen Peschke Date: Wed, 26 Jun 2024 09:50:54 -0700 Subject: [PATCH 09/14] More sensible Hail-Mary when MDCAdapter is borked --- .../log4cats/slf4j/internal/Slf4jLoggerInternal.scala | 11 ++++++----- 1 file changed, 6 insertions(+), 5 deletions(-) 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 7f562010..ab54f05e 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 @@ -22,8 +22,6 @@ import cats.effect._ import org.slf4j.{Logger => JLogger} import org.slf4j.MDC -import java.util - private[slf4j] object Slf4jLoggerInternal { final val singletonsByName = true @@ -46,9 +44,12 @@ private[slf4j] object Slf4jLoggerInternal { val backup = try MDC.getCopyOfContextMap() catch { - case _: IllegalStateException => - // Assuming this happens, better to just roll with it and try to get a log out - new util.HashMap[String, String]() + 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 } try { From 3bcbdec6d48ad476672a8d7250dab60c8370a463 Mon Sep 17 00:00:00 2001 From: Morgen Peschke Date: Wed, 26 Jun 2024 09:51:10 -0700 Subject: [PATCH 10/14] Always handle the MDC --- .../slf4j/internal/Slf4jLoggerInternal.scala | 36 +++-- .../internal/Slf4jLoggerInternalSuite.scala | 124 ++++++++++-------- 2 files changed, 84 insertions(+), 76 deletions(-) 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 ab54f05e..c97e2be5 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 @@ -34,6 +34,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], @@ -85,55 +91,45 @@ 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 error(ctx: Map[String, String], t: Throwable)(msg: => String): F[Unit] = 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 b4ed249c..5528edd6 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 @@ -60,12 +60,12 @@ class Slf4jLoggerInternalSuite extends CatsEffectSuite { } private def testLoggerFixture( - traceEnabled: Boolean = true, - debugEnabled: Boolean = true, - infoEnabled: Boolean = true, - warnEnabled: Boolean = true, - errorEnabled: Boolean = true - ): SyncIO[FunFixture[JTestLogger]] = + traceEnabled: Boolean = true, + debugEnabled: Boolean = true, + infoEnabled: Boolean = true, + warnEnabled: Boolean = true, + errorEnabled: Boolean = true + ): SyncIO[FunFixture[JTestLogger]] = ResourceFunFixture( Resource.eval( IO( @@ -128,7 +128,8 @@ class Slf4jLoggerInternalSuite extends CatsEffectSuite { test("Slf4jLoggerInternal resets after exceptions") { prepareMDC >> - Slf4jLogger.getLogger[IO] + Slf4jLogger + .getLogger[IO] .info(Map("foo" -> "bar"))(die()) .interceptMessage[IllegalStateException]("dead") >> validateMDC @@ -151,9 +152,13 @@ class Slf4jLoggerInternalSuite extends CatsEffectSuite { 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") - )) >> + IO(testLogger.logs()) + .map(toDeferredLogs) + .assertEquals( + List( + DeferredLogMessage.info(Map("foo" -> "bar"), none, () => "A log went here") + ) + ) >> validateMDC } @@ -162,10 +167,12 @@ class Slf4jLoggerInternalSuite extends CatsEffectSuite { ) { 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") - ) >> + 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 } @@ -246,7 +253,8 @@ class Slf4jLoggerInternalSuite extends CatsEffectSuite { warnEnabled = false, errorEnabled = false ).test("Slf4jLoggerInternal.withModifiedString is still lazy") { testLogger => - val slf4jLogger = Slf4jLogger.getLoggerFromSlf4j[IO](testLogger).withModifiedString(_.toUpperCase) + 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 @@ -331,51 +339,55 @@ class Slf4jLoggerInternalSuite extends CatsEffectSuite { 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 + 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)") { + 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 => + 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 >> From 412781e04d7eca155eee24804cafe3c44a720098 Mon Sep 17 00:00:00 2001 From: Morgen Peschke Date: Wed, 26 Jun 2024 09:55:21 -0700 Subject: [PATCH 11/14] Suppress unused warning --- .../log4cats/slf4j/internal/Slf4jLoggerInternal.scala | 11 +++++++---- 1 file changed, 7 insertions(+), 4 deletions(-) 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 c97e2be5..eb16e2b7 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 @@ -74,6 +76,7 @@ private[slf4j] object Slf4jLoggerInternal { ) } + @nowarn("msg=never used") final class Slf4jLogger[F[_]](val logger: JLogger, sync: Sync.Type = Sync.Type.Delay)(implicit F: Sync[F] ) extends SelfAwareStructuredLogger[F] { From 72113b1a75b691b48987f57449cd4a3a1f2c28b2 Mon Sep 17 00:00:00 2001 From: Morgen Peschke Date: Wed, 26 Jun 2024 10:38:59 -0700 Subject: [PATCH 12/14] Attempt to balance warn message changes between Scala 2/3 --- .../typelevel/log4cats/slf4j/internal/Slf4jLoggerInternal.scala | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) 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 eb16e2b7..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 @@ -76,7 +76,7 @@ private[slf4j] object Slf4jLoggerInternal { ) } - @nowarn("msg=never used") + @nowarn("msg=used") final class Slf4jLogger[F[_]](val logger: JLogger, sync: Sync.Type = Sync.Type.Delay)(implicit F: Sync[F] ) extends SelfAwareStructuredLogger[F] { From dcb65007e28b36fae71589c6631198fe7c241967 Mon Sep 17 00:00:00 2001 From: Morgen Peschke Date: Wed, 26 Jun 2024 11:12:11 -0700 Subject: [PATCH 13/14] Override IORuntime in test This is used to make sure that the MDC manipulation all happens on the same thread. --- .../internal/Slf4jLoggerInternalSuite.scala | 19 +++++++++++++++++-- 1 file changed, 17 insertions(+), 2 deletions(-) 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 5528edd6..ec92eff9 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 @@ -18,11 +18,11 @@ package org.typelevel.log4cats.slf4j package internal import cats.arrow.FunctionK +import cats.effect.unsafe.IORuntime import cats.effect.{IO, Resource, SyncIO} import cats.syntax.all.* -import java.util.concurrent.Executors -import java.util.concurrent.ThreadFactory +import java.util.concurrent.{ExecutorService, Executors, ThreadFactory} import org.slf4j.MDC import munit.{CatsEffectSuite, Location} import org.typelevel.log4cats.extras.DeferredLogMessage @@ -39,6 +39,21 @@ 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 = From 61ee3e95c260cebe360a80d1fc724c810eed962c Mon Sep 17 00:00:00 2001 From: Morgen Peschke Date: Wed, 26 Jun 2024 11:48:43 -0700 Subject: [PATCH 14/14] Fix unused import --- .../log4cats/slf4j/internal/Slf4jLoggerInternalSuite.scala | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) 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 ec92eff9..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 @@ -22,7 +22,7 @@ import cats.effect.unsafe.IORuntime import cats.effect.{IO, Resource, SyncIO} import cats.syntax.all.* -import java.util.concurrent.{ExecutorService, Executors, ThreadFactory} +import java.util.concurrent.{Executors, ThreadFactory} import org.slf4j.MDC import munit.{CatsEffectSuite, Location} import org.typelevel.log4cats.extras.DeferredLogMessage