diff --git a/README.md b/README.md index a224ab2..1269f70 100644 --- a/README.md +++ b/README.md @@ -23,7 +23,7 @@ if (logger.isDebugEnabled) logger.debug(s"Some $expensive message!") A compatible logging backend is [Logback](http://logback.qos.ch), add it to your sbt build definition: ```scala -libraryDependencies += "ch.qos.logback" % "logback-classic" % "1.1.7" +libraryDependencies += "ch.qos.logback" % "logback-classic" % "1.2.3" ``` If you are looking for a version compatible with Scala 2.10, check out Scala Logging 2.x. @@ -94,6 +94,28 @@ class MyClass extends LazyLogging { - SLF4J loggers and our Logger now survive serialization. By survive serialization, we mean that the deserialized logger instances are fully functional. +## String Interpolation +It is idiomatic to use Scala's string interpolation `logger.error(s"log $value")` instead of SLF4J string interpolation `logger.error("log {}", value)`. +However there are some tools (such as [Sentry](https://sentry.io)) that use the log message format as grouping key. Therefore they do not work well with +Scala's string interpolation. + +Scala Logging replaces simple string interpolations with their SLF4J counterparts like this: + +```scala +logger.error(s"my log message: $arg1 $arg2 $arg3") +``` + +```scala +logger.error("my log message: {} {} {}", arg1, arg2, arg3) +``` + +This has no effect on behavior and performace should be comparable (depends on the underlying logging library). + +### Limitations + - Works only when string interpolation is directly used inside the logging statement. That is when the log message is static (available at compile time). + - Works only for the `logger.(message)` and `logger.(marker, message)` logging methods. It does not work if you want to log an exception and + use string interpolation too (this is a limitation of the SLF4J API). + ## Line numbers in log message? Using the [sourcecode](https://github.com/lihaoyi/sourcecode#logging) library, it's possible to add line number diff --git a/src/main/scala/com/typesafe/scalalogging/LoggerMacro.scala b/src/main/scala/com/typesafe/scalalogging/LoggerMacro.scala index b091869..5725e67 100644 --- a/src/main/scala/com/typesafe/scalalogging/LoggerMacro.scala +++ b/src/main/scala/com/typesafe/scalalogging/LoggerMacro.scala @@ -21,14 +21,15 @@ import scala.reflect.macros.blackbox.Context private object LoggerMacro { + private final val ArgumentMarker = "{}" + type LoggerContext = Context { type PrefixType = Logger } // Error def errorMessage(c: LoggerContext)(message: c.Expr[String]) = { - import c.universe._ - val underlying = q"${c.prefix}.underlying" - q"if ($underlying.isErrorEnabled) $underlying.error($message)" + val (messageFormat, args) = deconstructInterpolatedMessage(c)(message) + errorMessageArgs(c)(messageFormat, args: _*) } def errorMessageCause(c: LoggerContext)(message: c.Expr[String], cause: c.Expr[Throwable]) = { @@ -47,9 +48,8 @@ private object LoggerMacro { } def errorMessageMarker(c: LoggerContext)(marker: c.Expr[Marker], message: c.Expr[String]) = { - import c.universe._ - val underlying = q"${c.prefix}.underlying" - q"if ($underlying.isErrorEnabled) $underlying.error($marker, $message)" + val (messageFormat, args) = deconstructInterpolatedMessage(c)(message) + errorMessageArgsMarker(c)(marker, messageFormat, args: _*) } def errorMessageCauseMarker(c: LoggerContext)(marker: c.Expr[Marker], message: c.Expr[String], cause: c.Expr[Throwable]) = { @@ -70,9 +70,8 @@ private object LoggerMacro { // Warn def warnMessage(c: LoggerContext)(message: c.Expr[String]) = { - import c.universe._ - val underlying = q"${c.prefix}.underlying" - q"if ($underlying.isWarnEnabled) $underlying.warn($message)" + val (messageFormat, args) = deconstructInterpolatedMessage(c)(message) + warnMessageArgs(c)(messageFormat, args: _*) } def warnMessageCause(c: LoggerContext)(message: c.Expr[String], cause: c.Expr[Throwable]) = { @@ -91,9 +90,8 @@ private object LoggerMacro { } def warnMessageMarker(c: LoggerContext)(marker: c.Expr[Marker], message: c.Expr[String]) = { - import c.universe._ - val underlying = q"${c.prefix}.underlying" - q"if ($underlying.isWarnEnabled) $underlying.warn($marker, $message)" + val (messageFormat, args) = deconstructInterpolatedMessage(c)(message) + warnMessageArgsMarker(c)(marker, messageFormat, args: _*) } def warnMessageCauseMarker(c: LoggerContext)(marker: c.Expr[Marker], message: c.Expr[String], cause: c.Expr[Throwable]) = { @@ -114,9 +112,8 @@ private object LoggerMacro { // Info def infoMessage(c: LoggerContext)(message: c.Expr[String]) = { - import c.universe._ - val underlying = q"${c.prefix}.underlying" - q"if ($underlying.isInfoEnabled) $underlying.info($message)" + val (messageFormat, args) = deconstructInterpolatedMessage(c)(message) + infoMessageArgs(c)(messageFormat, args: _*) } def infoMessageCause(c: LoggerContext)(message: c.Expr[String], cause: c.Expr[Throwable]) = { @@ -135,9 +132,8 @@ private object LoggerMacro { } def infoMessageMarker(c: LoggerContext)(marker: c.Expr[Marker], message: c.Expr[String]) = { - import c.universe._ - val underlying = q"${c.prefix}.underlying" - q"if ($underlying.isInfoEnabled) $underlying.info($marker, $message)" + val (messageFormat, args) = deconstructInterpolatedMessage(c)(message) + infoMessageArgsMarker(c)(marker, messageFormat, args: _*) } def infoMessageCauseMarker(c: LoggerContext)(marker: c.Expr[Marker], message: c.Expr[String], cause: c.Expr[Throwable]) = { @@ -158,9 +154,8 @@ private object LoggerMacro { // Debug def debugMessage(c: LoggerContext)(message: c.Expr[String]) = { - import c.universe._ - val underlying = q"${c.prefix}.underlying" - q"if ($underlying.isDebugEnabled) $underlying.debug($message)" + val (messageFormat, args) = deconstructInterpolatedMessage(c)(message) + debugMessageArgs(c)(messageFormat, args: _*) } def debugMessageCause(c: LoggerContext)(message: c.Expr[String], cause: c.Expr[Throwable]) = { @@ -179,9 +174,8 @@ private object LoggerMacro { } def debugMessageMarker(c: LoggerContext)(marker: c.Expr[Marker], message: c.Expr[String]) = { - import c.universe._ - val underlying = q"${c.prefix}.underlying" - q"if ($underlying.isDebugEnabled) $underlying.debug($marker, $message)" + val (messageFormat, args) = deconstructInterpolatedMessage(c)(message) + debugMessageArgsMarker(c)(marker, messageFormat, args: _*) } def debugMessageCauseMarker(c: LoggerContext)(marker: c.Expr[Marker], message: c.Expr[String], cause: c.Expr[Throwable]) = { @@ -202,9 +196,8 @@ private object LoggerMacro { // Trace def traceMessage(c: LoggerContext)(message: c.Expr[String]) = { - import c.universe._ - val underlying = q"${c.prefix}.underlying" - q"if ($underlying.isTraceEnabled) $underlying.trace($message)" + val (messageFormat, args) = deconstructInterpolatedMessage(c)(message) + traceMessageArgs(c)(messageFormat, args: _*) } def traceMessageCause(c: LoggerContext)(message: c.Expr[String], cause: c.Expr[Throwable]) = { @@ -223,9 +216,8 @@ private object LoggerMacro { } def traceMessageMarker(c: LoggerContext)(marker: c.Expr[Marker], message: c.Expr[String]) = { - import c.universe._ - val underlying = q"${c.prefix}.underlying" - q"if ($underlying.isTraceEnabled) $underlying.trace($marker, $message)" + val (messageFormat, args) = deconstructInterpolatedMessage(c)(message) + traceMessageArgsMarker(c)(marker, messageFormat, args: _*) } def traceMessageCauseMarker(c: LoggerContext)(marker: c.Expr[Marker], message: c.Expr[String], cause: c.Expr[Throwable]) = { @@ -243,4 +235,18 @@ private object LoggerMacro { q"if ($underlying.isTraceEnabled) $underlying.trace($marker, $message, ..$args)" } + /** Checks whether `messsage` is an interpolated string and transforms it into SLF4J string interpolation. */ + private def deconstructInterpolatedMessage(c: LoggerContext)(message: c.Expr[String]) = { + import c.universe._ + + message.tree match { + case q"scala.StringContext.apply(..$parts).s(..$args)" => + val strings = parts.collect { case Literal(Constant(s: String)) => s } + val messageFormat = strings.mkString(ArgumentMarker) + (c.Expr(q"$messageFormat"), args.map(arg => q"$arg").map(c.Expr[Any](_))) + + case _ => (message, Seq.empty) + } + } + } diff --git a/src/test/scala/com/typesafe/scalalogging/LoggerSpec.scala b/src/test/scala/com/typesafe/scalalogging/LoggerSpec.scala index 2e6f5ea..c8d443b 100644 --- a/src/test/scala/com/typesafe/scalalogging/LoggerSpec.scala +++ b/src/test/scala/com/typesafe/scalalogging/LoggerSpec.scala @@ -43,6 +43,20 @@ class LoggerSpec extends WordSpec with Matchers with MockitoSugar { logger.error(msg) verify(underlying, never).error(anyString) } + + "call the underlying logger's error method with arguments if the error level is enabled and string is interpolated" in { + val f = fixture(_.isErrorEnabled, true) + import f._ + logger.error(s"msg $arg1 $arg2 $arg3") + verify(underlying).error("msg {} {} {}", arg1, arg2, arg3) + } + + "call the underlying logger's error method with two arguments if the error level is enabled and string is interpolated" in { + val f = fixture(_.isErrorEnabled, true) + import f._ + logger.error(s"msg $arg1 $arg2") + verify(underlying).error("msg {} {}", List(arg1, arg2): _*) + } } "Calling error with a message and cause" should { @@ -104,6 +118,13 @@ class LoggerSpec extends WordSpec with Matchers with MockitoSugar { logger.warn(msg) verify(underlying, never).warn(anyString) } + + "call the underlying logger's warn method if the warn level is enabled and string is interpolated" in { + val f = fixture(_.isWarnEnabled, true) + import f._ + logger.warn(s"msg $arg1 $arg2 $arg3") + verify(underlying).warn("msg {} {} {}", arg1, arg2, arg3) + } } "Calling warn with a message and cause" should { @@ -165,6 +186,13 @@ class LoggerSpec extends WordSpec with Matchers with MockitoSugar { logger.info(msg) verify(underlying, never).info(anyString) } + + "call the underlying logger's info method if the info level is enabled and string is interpolated" in { + val f = fixture(_.isInfoEnabled, true) + import f._ + logger.info(s"msg $arg1 $arg2 $arg3") + verify(underlying).info("msg {} {} {}", arg1, arg2, arg3) + } } "Calling info with a message and cause" should { @@ -226,6 +254,13 @@ class LoggerSpec extends WordSpec with Matchers with MockitoSugar { logger.debug(msg) verify(underlying, never).debug(anyString) } + + "call the underlying logger's debug method if the debug level is enabled and string is interpolated" in { + val f = fixture(_.isDebugEnabled, true) + import f._ + logger.debug(s"msg $arg1 $arg2 $arg3") + verify(underlying).debug("msg {} {} {}", arg1, arg2, arg3) + } } "Calling debug with a message and cause" should { @@ -287,6 +322,13 @@ class LoggerSpec extends WordSpec with Matchers with MockitoSugar { logger.trace(msg) verify(underlying, never).trace(anyString) } + + "call the underlying logger's trace method if the trace level is enabled and string is interpolated" in { + val f = fixture(_.isTraceEnabled, true) + import f._ + logger.trace(s"msg $arg1 $arg2 $arg3") + verify(underlying).trace("msg {} {} {}", arg1, arg2, arg3) + } } "Calling trace with a message and cause" should { diff --git a/src/test/scala/com/typesafe/scalalogging/LoggerWithMarkerSpec.scala b/src/test/scala/com/typesafe/scalalogging/LoggerWithMarkerSpec.scala index 52ea4b0..d787aaf 100644 --- a/src/test/scala/com/typesafe/scalalogging/LoggerWithMarkerSpec.scala +++ b/src/test/scala/com/typesafe/scalalogging/LoggerWithMarkerSpec.scala @@ -58,6 +58,13 @@ class LoggerWithMarkerSpec extends WordSpec with Matchers with MockitoSugar { logger.error(marker, msg) verify(underlying, never).error(refEq(DummyMarker), anyString) } + + "call the underlying logger's error method if the error level is enabled and string is interpolated" in { + val f = fixture(_.isErrorEnabled, true) + import f._ + logger.error(marker, s"msg $arg1 $arg2 $arg3") + verify(underlying).error(marker, "msg {} {} {}", arg1, arg2, arg3) + } } "Calling error with a marker and a message and cause" should { @@ -119,6 +126,13 @@ class LoggerWithMarkerSpec extends WordSpec with Matchers with MockitoSugar { logger.warn(marker, msg) verify(underlying, never).warn(refEq(DummyMarker), anyString) } + + "call the underlying logger's warn method if the warn level is enabled and string is interpolated" in { + val f = fixture(_.isWarnEnabled, true) + import f._ + logger.warn(marker, s"msg $arg1 $arg2 $arg3") + verify(underlying).warn(marker, "msg {} {} {}", arg1, arg2, arg3) + } } "Calling warn with a marker and a message and cause" should { @@ -180,6 +194,13 @@ class LoggerWithMarkerSpec extends WordSpec with Matchers with MockitoSugar { logger.info(marker, msg) verify(underlying, never).info(refEq(DummyMarker), anyString) } + + "call the underlying logger's info method if the info level is enabled and string is interpolated" in { + val f = fixture(_.isInfoEnabled, true) + import f._ + logger.info(marker, s"msg $arg1 $arg2 $arg3") + verify(underlying).info(marker, "msg {} {} {}", arg1, arg2, arg3) + } } "Calling info with a marker and a message and cause" should { @@ -241,6 +262,13 @@ class LoggerWithMarkerSpec extends WordSpec with Matchers with MockitoSugar { logger.debug(marker, msg) verify(underlying, never).debug(refEq(DummyMarker), anyString) } + + "call the underlying logger's debug method if the debug level is enabled and string is interpolated" in { + val f = fixture(_.isDebugEnabled, true) + import f._ + logger.debug(marker, s"msg $arg1 $arg2 $arg3") + verify(underlying).debug(marker, "msg {} {} {}", arg1, arg2, arg3) + } } "Calling debug with a marker and a message and cause" should { @@ -302,6 +330,13 @@ class LoggerWithMarkerSpec extends WordSpec with Matchers with MockitoSugar { logger.trace(marker, msg) verify(underlying, never).trace(refEq(DummyMarker), anyString) } + + "call the underlying logger's trace method if the trace level is enabled and string is interpolated" in { + val f = fixture(_.isTraceEnabled, true) + import f._ + logger.trace(marker, s"msg $arg1 $arg2 $arg3") + verify(underlying).trace(marker, "msg {} {} {}", arg1, arg2, arg3) + } } "Calling trace with a marker and a message and cause" should {