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/test/scala/org/typelevel/log4cats/slf4j/internal/JTestLogger.java

@@ -0,0 +1,207 @@
+/*
+ * Copyright 2018 Typelevel
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ *     http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+
+package org.typelevel.log4cats.slf4j.internal;
+
+import org.slf4j.Logger;
+import org.slf4j.MDC;
+import org.slf4j.Marker;
+import org.typelevel.log4cats.extras.LogLevel;
+import scala.Option;
+
+import java.util.ArrayList;
+import java.util.HashMap;
+import java.util.List;
+import java.util.Map;
+import java.util.concurrent.atomic.AtomicReference;
+import java.util.function.Function;
+import java.util.function.Supplier;
+
+public class JTestLogger implements Logger {
+    // Java -> Scala compat helpers
+
+    private static final scala.Option<Throwable> none = scala.Option$.MODULE$.empty();
+    private static scala.Option<Throwable> 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<String, String> captureContext () {
+        java.util.Map<String, String> 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<String, String> context;
+        public final Option<Throwable> throwableOpt;
+        public final Supplier<String> message;
+
+        public TestLogMessage(LogLevel logLevel,
+                              java.util.Map<String, String> context,
+                              Option<Throwable> throwableOpt,
+                              Supplier<String> 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<String, String> context,
+                                 Throwable throwable,
+                                 Supplier<String> message) {
+            return new TestLogMessage(logLevel, context, some(throwable), message);
+        }
+
+        static TestLogMessage of(LogLevel logLevel,
+                                 java.util.Map<String, String> context,
+                                 Supplier<String> 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<List<TestLogMessage>> 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<TestLogMessage>());
+    }
+
+    private void save(Function<Map<String, String>, TestLogMessage> mkLogMessage) {
+        loggedMessages.updateAndGet(ll -> {
+            ll.add(mkLogMessage.apply(captureContext()));
+            return ll;
+        });
+    }
+
+    public List<TestLogMessage> logs() { return loggedMessages.get(); }
+    public void reset() { loggedMessages.set(new ArrayList<>()); }
+
+    @Override public String getName() { return loggerName;}
+
+    @Override public boolean isTraceEnabled() { return traceEnabled; }
+    @Override public boolean isDebugEnabled() { return debugEnabled; }
+    @Override public boolean isInfoEnabled() { return infoEnabled; }
+    @Override public boolean isWarnEnabled() { return warnEnabled; }
+    @Override public boolean isErrorEnabled() { return errorEnabled; }
+
+    // We don't use them, so we're going to ignore Markers
+    @Override public boolean isTraceEnabled(Marker marker) { return traceEnabled; }
+    @Override public boolean isDebugEnabled(Marker marker) { return debugEnabled; }
+    @Override public boolean isInfoEnabled(Marker marker) { return infoEnabled; }
+    @Override public boolean isWarnEnabled(Marker marker) { return warnEnabled; }
+    @Override public boolean isErrorEnabled(Marker marker) { return errorEnabled; }
+
+    @Override public void trace(String msg) { save(ctx -> TestLogMessage.of(Trace, ctx, () -> msg)); }
+    @Override public void trace(String msg, Throwable t) { save(ctx -> TestLogMessage.of(Trace, ctx, t, () -> msg)); }
+
+    @Override public void debug(String msg) { save(ctx -> TestLogMessage.of(Debug, ctx, () -> msg)); }
+    @Override public void debug(String msg, Throwable t) { save(ctx -> TestLogMessage.of(Debug, ctx, t, () -> msg)); }
+
+    @Override public void info(String msg) { save(ctx -> TestLogMessage.of(Info, ctx, () -> msg)); }
+    @Override public void info(String msg, Throwable t) { save(ctx -> TestLogMessage.of(Info, ctx, t, () -> msg)); }
+
+    @Override public void warn(String msg) { save(ctx -> TestLogMessage.of(Warn, ctx, () -> msg)); }
+    @Override public void warn(String msg, Throwable t) { save(ctx -> TestLogMessage.of(Warn, ctx, t, () -> msg)); }
+
+    @Override public void error(String msg) { save(ctx -> TestLogMessage.of(Error, ctx, () -> msg)); }
+    @Override public void error(String msg, Throwable t) { save(ctx -> TestLogMessage.of(Error, ctx, t, () -> msg)); }
+
+    // We shouldn't need these for our tests, so we're treating these variants as if they were the standard method
+
+    @Override public void trace(String format, Object arg)                              { trace(format); }
+    @Override public void trace(String format, Object arg1, Object arg2)                { trace(format); }
+    @Override public void trace(String format, Object... arguments)                     { trace(format); }
+    @Override public void trace(Marker marker, String msg)                              { trace(msg);    }
+    @Override public void trace(Marker marker, String format, Object arg)               { trace(format); }
+    @Override public void trace(Marker marker, String format, Object arg1, Object arg2) { trace(format); }
+    @Override public void trace(Marker marker, String format, Object... argArray)       { trace(format); }
+    @Override public void trace(Marker marker, String msg, Throwable t)                 { trace(msg, t); }
+
+    @Override public void debug(String format, Object arg)                              { debug(format); }
+    @Override public void debug(String format, Object arg1, Object arg2)                { debug(format); }
+    @Override public void debug(String format, Object... arguments)                     { debug(format); }
+    @Override public void debug(Marker marker, String msg)                              { debug(msg);    }
+    @Override public void debug(Marker marker, String format, Object arg)               { debug(format); }
+    @Override public void debug(Marker marker, String format, Object arg1, Object arg2) { debug(format); }
+    @Override public void debug(Marker marker, String format, Object... arguments) { debug(format); }
+    @Override public void debug(Marker marker, String msg, Throwable t) { debug(msg, t); }
+
+    @Override public void info(String format, Object arg)                               { info(format); }
+    @Override public void info(String format, Object arg1, Object arg2)                 { info(format); }
+    @Override public void info(String format, Object... arguments)                      { info(format); }
+    @Override public void info(Marker marker, String msg)                               { info(msg);    }
+    @Override public void info(Marker marker, String format, Object arg)                { info(format); }
+    @Override public void info(Marker marker, String format, Object arg1, Object arg2)  { info(format); }
+    @Override public void info(Marker marker, String format, Object... arguments)       { info(format); }
+    @Override public void info(Marker marker, String msg, Throwable t)                  { info(msg, t); }
+
+    @Override public void warn(String format, Object arg)                               { warn(format); }
+    @Override public void warn(String format, Object... arguments)                      { warn(format); }
+    @Override public void warn(String format, Object arg1, Object arg2)                 { warn(format); }
+    @Override public void warn(Marker marker, String msg)                               { warn(msg);    }
+    @Override public void warn(Marker marker, String format, Object arg)                { warn(format); }
+    @Override public void warn(Marker marker, String format, Object arg1, Object arg2)  { warn(format); }
+    @Override public void warn(Marker marker, String format, Object... arguments)       { warn(format); }
+    @Override public void warn(Marker marker, String msg, Throwable t)                  { warn(msg, t); }
+
+    @Override public void error(String format, Object arg)                              { error(format); }
+    @Override public void error(String format, Object arg1, Object arg2)                { error(format); }
+    @Override public void error(String format, Object... arguments)                     { error(format); }
+    @Override public void error(Marker marker, String msg)                              { error(msg);    }
+    @Override public void error(Marker marker, String format, Object arg)               { error(format); }
+    @Override public void error(Marker marker, String format, Object arg1, Object arg2) { error(format); }
+    @Override public void error(Marker marker, String format, Object... arguments)      { error(format); }
+    @Override public void error(Marker marker, String msg, Throwable t)                 { error(msg, t); }
+}