Fix MDC handling in Slf4jLogger

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()})"
+  }
+}

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)
 }

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,21 +36,36 @@ 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],
       logging: () => Unit
   )(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))
   }