+ core: refactor MDC facilities and closes #100

8 files changed, 137 insertions, 58 deletions

diff --git a/kamon-core/src/main/scala/kamon/instrumentation/akka/ActorLoggingInstrumentation.scala b/kamon-core/src/main/scala/kamon/instrumentation/akka/ActorLoggingInstrumentation.scala
index 6b90a81e..e0e5d316 100644
--- a/kamon-core/src/main/scala/kamon/instrumentation/akka/ActorLoggingInstrumentation.scala
+++ b/kamon-core/src/main/scala/kamon/instrumentation/akka/ActorLoggingInstrumentation.scala
@@ -16,12 +16,13 @@
 
 package akka.kamon.instrumentation
 
+import kamon.trace.logging.MdcKeysSupport
 import kamon.trace.{ TraceContextAware, TraceRecorder }
 import org.aspectj.lang.ProceedingJoinPoint
 import org.aspectj.lang.annotation._
 
 @Aspect
-class ActorLoggingInstrumentation {
+class ActorLoggingInstrumentation extends MdcKeysSupport {
 
   @DeclareMixin("akka.event.Logging.LogEvent+")
   def mixinTraceContextAwareToLogEvent: TraceContextAware = TraceContextAware.default
@@ -41,7 +42,9 @@ class ActorLoggingInstrumentation {
   @Around("withMdcInvocation(logSource, logEvent, logStatement)")
   def aroundWithMdcInvocation(pjp: ProceedingJoinPoint, logSource: String, logEvent: TraceContextAware, logStatement: () ⇒ _): Unit = {
     TraceRecorder.withInlineTraceContextReplacement(logEvent.traceContext) {
-      pjp.proceed()
+      withMdc {
+        pjp.proceed()
+      }
     }
   }
 }
diff --git a/kamon-core/src/main/scala/kamon/trace/TraceLocal.scala b/kamon-core/src/main/scala/kamon/trace/TraceLocal.scala
index 0766af74..a7296c31 100644
--- a/kamon-core/src/main/scala/kamon/trace/TraceLocal.scala
+++ b/kamon-core/src/main/scala/kamon/trace/TraceLocal.scala
@@ -16,14 +16,28 @@
 
 package kamon.trace
 
-import scala.collection.concurrent.TrieMap
 import kamon.trace.TraceLocal.TraceLocalKey
 
+import scala.collection.concurrent.TrieMap
+
 object TraceLocal {
+
   trait TraceLocalKey {
     type ValueType
   }
 
+  trait AvailableToMdc extends TraceLocalKey {
+    override type ValueType = String
+    def mdcKey: String
+  }
+
+  object AvailableToMdc {
+    case class DefaultKeyAvailableToMdc(mdcKey: String) extends AvailableToMdc
+
+    def fromKey(mdcKey: String): AvailableToMdc = DefaultKeyAvailableToMdc(mdcKey)
+    def apply(mdcKey: String): AvailableToMdc = fromKey(mdcKey)
+  }
+
   def store(key: TraceLocalKey)(value: key.ValueType): Unit = TraceRecorder.currentContext match {
     case ctx: DefaultTraceContext ⇒ ctx.traceLocalStorage.store(key)(value)
     case EmptyTraceContext        ⇒ // Can't store in the empty context.
@@ -33,6 +47,8 @@ object TraceLocal {
     case ctx: DefaultTraceContext ⇒ ctx.traceLocalStorage.retrieve(key)
     case EmptyTraceContext        ⇒ None // Can't retrieve anything from the empty context.
   }
+
+  def storeForMdc(key: String, value: String): Unit = store(AvailableToMdc.fromKey(key))(value)
 }
 
 class TraceLocalStorage {
diff --git a/kamon-core/src/main/scala/kamon/trace/logging/MdcKeysSupport.scala b/kamon-core/src/main/scala/kamon/trace/logging/MdcKeysSupport.scala
new file mode 100644
index 00000000..d79a3ab6
--- /dev/null
+++ b/kamon-core/src/main/scala/kamon/trace/logging/MdcKeysSupport.scala
@@ -0,0 +1,39 @@
+/*
+ * =========================================================================================
+ * Copyright © 2013-2014 the kamon project <http://kamon.io/>
+ *
+ * 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 kamon.trace.logging
+
+import kamon.trace.TraceLocal.AvailableToMdc
+import kamon.trace.{ EmptyTraceContext, DefaultTraceContext, TraceContext, TraceRecorder }
+
+import org.slf4j.MDC
+
+trait MdcKeysSupport {
+
+  def withMdc[A](thunk: ⇒ A): A = {
+    val keys = copyToMdc(TraceRecorder.currentContext)
+    try thunk finally keys.foreach(key ⇒ MDC.remove(key))
+  }
+
+  private[this] def copyToMdc(traceContext: TraceContext): Iterable[String] = traceContext match {
+    case ctx: DefaultTraceContext ⇒
+      ctx.traceLocalStorage.underlyingStorage.collect {
+        case (available: AvailableToMdc, value) ⇒ Map(available.mdcKey -> String.valueOf(value))
+      }.map { value ⇒ value.map { case (k, v) ⇒ MDC.put(k, v); k } }.flatten
+
+    case EmptyTraceContext ⇒ Iterable.empty[String]
+  }
+}
diff --git a/kamon-core/src/test/scala/kamon/instrumentation/akka/ActorLoggingInstrumentationSpec.scala b/kamon-core/src/test/scala/kamon/instrumentation/akka/ActorLoggingInstrumentationSpec.scala
index 3dab44bc..cef335e0 100644
--- a/kamon-core/src/test/scala/kamon/instrumentation/akka/ActorLoggingInstrumentationSpec.scala
+++ b/kamon-core/src/test/scala/kamon/instrumentation/akka/ActorLoggingInstrumentationSpec.scala
@@ -18,11 +18,14 @@ package kamon.instrumentation.akka
 import akka.actor.{ Actor, ActorLogging, ActorSystem, Props }
 import akka.event.Logging.LogEvent
 import akka.testkit.TestKit
-import kamon.trace.{ TraceContextAware, TraceRecorder }
+import kamon.trace.TraceLocal.AvailableToMdc
+import kamon.trace.logging.MdcKeysSupport
+import kamon.trace.{TraceLocal, TraceContextAware, TraceRecorder}
 import org.scalatest.{ Inspectors, Matchers, WordSpecLike }
+import org.slf4j.MDC
 
 class ActorLoggingInstrumentationSpec extends TestKit(ActorSystem("actor-logging-instrumentation-spec")) with WordSpecLike
-    with Matchers with Inspectors {
+    with Matchers with Inspectors with MdcKeysSupport {
 
   "the ActorLogging instrumentation" should {
     "attach the TraceContext (if available) to log events" in {
@@ -42,6 +45,24 @@ class ActorLoggingInstrumentationSpec extends TestKit(ActorSystem("actor-logging
         case event: LogEvent ⇒ false
       }
     }
+
+    "allow retrieve a value from the MDC when was created a key of type AvailableToMdc" in {
+      val testString = "Hello World"
+      val SampleTraceLocalKeyAvailableToMDC = AvailableToMdc("some-cool-key")
+
+      val loggerActor = system.actorOf(Props[LoggerActor])
+      system.eventStream.subscribe(testActor, classOf[LogEvent])
+
+      TraceRecorder.withNewTraceContext("logging-with-mdc") {
+        TraceLocal.store(SampleTraceLocalKeyAvailableToMDC)(testString)
+
+        loggerActor ! "info"
+
+        withMdc {
+          MDC.get("some-cool-key") should equal(testString)
+        }
+      }
+    }
   }
 }
 
diff --git a/kamon-core/src/test/scala/kamon/trace/TraceLocalSpec.scala b/kamon-core/src/test/scala/kamon/trace/TraceLocalSpec.scala
index 927573c2..b23c1c03 100644
--- a/kamon-core/src/test/scala/kamon/trace/TraceLocalSpec.scala
+++ b/kamon-core/src/test/scala/kamon/trace/TraceLocalSpec.scala
@@ -16,13 +16,18 @@
 
 package kamon.trace
 
-import akka.testkit.TestKit
 import akka.actor.ActorSystem
-import org.scalatest.{ OptionValues, Matchers, WordSpecLike }
+import akka.testkit.TestKit
+import kamon.trace.TraceLocal.AvailableToMdc
+import kamon.trace.logging.MdcKeysSupport
 import org.scalatest.concurrent.PatienceConfiguration
+import org.scalatest.{Matchers, OptionValues, WordSpecLike}
+import org.slf4j.MDC
 
 class TraceLocalSpec extends TestKit(ActorSystem("trace-local-spec")) with WordSpecLike with Matchers
-    with PatienceConfiguration with OptionValues {
+    with PatienceConfiguration with OptionValues with MdcKeysSupport {
+
+  val SampleTraceLocalKeyAvailableToMDC = AvailableToMdc("someKey")
 
   object SampleTraceLocalKey extends TraceLocal.TraceLocalKey { type ValueType = String }
 
@@ -61,5 +66,31 @@ class TraceLocalSpec extends TestKit(ActorSystem("trace-local-spec")) with WordS
         TraceLocal.retrieve(SampleTraceLocalKey).value should equal(testString)
       }
     }
+
+    "allow retrieve a value from the MDC when was created a key with AvailableToMdc(cool-key)" in {
+      TraceRecorder.withNewTraceContext("store-and-retrieve-trace-local-and-copy-to-mdc") {
+        val testString = "Hello MDC"
+
+        TraceLocal.store(SampleTraceLocalKeyAvailableToMDC)(testString)
+        TraceLocal.retrieve(SampleTraceLocalKeyAvailableToMDC).value should equal(testString)
+
+        withMdc {
+          MDC.get("someKey") should equal(testString)
+        }
+      }
+    }
+
+    "allow retrieve a value from the MDC when was created a key with AvailableToMdc.storeForMdc(String, String)" in {
+      TraceRecorder.withNewTraceContext("store-and-retrieve-trace-local-and-copy-to-mdc") {
+        val testString = "Hello MDC"
+
+        TraceLocal.storeForMdc("someKey", testString)
+        TraceLocal.retrieve(SampleTraceLocalKeyAvailableToMDC).value should equal(testString)
+
+        withMdc {
+          MDC.get("someKey") should equal(testString)
+        }
+      }
+    }
   }
 }
diff --git a/kamon-play/src/main/scala/kamon/play/instrumentation/LoggerLikeInstrumentation.scala b/kamon-play/src/main/scala/kamon/play/instrumentation/LoggerLikeInstrumentation.scala
index e2ffd3f9..3c79fae4 100644
--- a/kamon-play/src/main/scala/kamon/play/instrumentation/LoggerLikeInstrumentation.scala
+++ b/kamon-play/src/main/scala/kamon/play/instrumentation/LoggerLikeInstrumentation.scala
@@ -15,19 +15,12 @@
 
 package kamon.play.instrumentation
 
-import kamon.trace._
+import kamon.trace.logging.MdcKeysSupport
 import org.aspectj.lang.ProceedingJoinPoint
 import org.aspectj.lang.annotation._
-import org.slf4j.MDC
-import play.api.LoggerLike
 
 @Aspect
-class LoggerLikeInstrumentation {
-
-  import kamon.play.instrumentation.LoggerLikeInstrumentation._
-
-  @DeclareMixin("play.api.LoggerLike+")
-  def mixinContextAwareToLoggerLike: TraceContextAware = TraceContextAware.default
+class LoggerLikeInstrumentation extends MdcKeysSupport {
 
   @Pointcut("execution(* play.api.LoggerLike+.info(..))")
   def infoPointcut(): Unit = {}
@@ -41,35 +34,9 @@ class LoggerLikeInstrumentation {
   @Pointcut("execution(* play.api.LoggerLike+.trace(..))")
   def tracePointcut(): Unit = {}
 
-  @Around("(infoPointcut() || warnPointcut() || errorPointcut() || tracePointcut()) && this(logger)")
-  def aroundLog(pjp: ProceedingJoinPoint, logger: LoggerLike): Any = {
-    withMDC {
-      pjp.proceed()
-    }
-  }
-}
-
-object LoggerLikeInstrumentation {
-
-  @inline final def withMDC[A](block: ⇒ A): A = {
-    val keys = putAndExtractKeys(extractProperties(TraceRecorder.currentContext))
-
-    try block finally keys.foreach(k ⇒ MDC.remove(k))
-  }
-
-  def putAndExtractKeys(values: Iterable[Map[String, Any]]): Iterable[String] = values.map {
-    value ⇒ value.map { case (key, value) ⇒ MDC.put(key, value.toString); key }
-  }.flatten
-
-  def extractProperties(traceContext: TraceContext): Iterable[Map[String, Any]] = traceContext match {
-    case ctx: DefaultTraceContext ⇒
-      ctx.traceLocalStorage.underlyingStorage.values.collect {
-        case traceLocalValue @ (p: Product) ⇒ {
-          val properties = p.productIterator
-          traceLocalValue.getClass.getDeclaredFields.filter(field ⇒ field.getName != "$outer").map(_.getName -> properties.next).toMap
-        }
-      }
-    case EmptyTraceContext ⇒ Iterable.empty[Map[String, Any]]
+  @Around("(infoPointcut() || warnPointcut() || errorPointcut() || tracePointcut())")
+  def aroundLog(pjp: ProceedingJoinPoint): Any = withMdc {
+    pjp.proceed()
   }
 }
 
diff --git a/kamon-play/src/test/scala/kamon/play/LoggerLikeInstrumentationSpec.scala b/kamon-play/src/test/scala/kamon/play/LoggerLikeInstrumentationSpec.scala
index c41f7004..04ae9729 100644
--- a/kamon-play/src/test/scala/kamon/play/LoggerLikeInstrumentationSpec.scala
+++ b/kamon-play/src/test/scala/kamon/play/LoggerLikeInstrumentationSpec.scala
@@ -16,10 +16,11 @@
 package kamon.play
 
 import ch.qos.logback.classic.spi.ILoggingEvent
-import ch.qos.logback.classic.{ AsyncAppender, LoggerContext }
+import ch.qos.logback.classic.{AsyncAppender, LoggerContext}
 import ch.qos.logback.core.read.ListAppender
 import ch.qos.logback.core.status.NopStatusListener
 import kamon.trace.TraceLocal
+import kamon.trace.TraceLocal.AvailableToMdc
 import org.scalatest.BeforeAndAfter
 import org.scalatestplus.play._
 import org.slf4j
@@ -28,8 +29,9 @@ import play.api.mvc.Results.Ok
 import play.api.mvc._
 import play.api.test.Helpers._
 import play.api.test._
+import scala.concurrent.duration._
 
-import scala.concurrent.Future
+import scala.concurrent.{Await, Future}
 
 class LoggerLikeInstrumentationSpec extends PlaySpec with OneServerPerSuite with BeforeAndAfter {
 
@@ -41,11 +43,8 @@ class LoggerLikeInstrumentationSpec extends PlaySpec with OneServerPerSuite with
   val headerValue = "My header value"
   val otherValue = "My other value"
 
-  case class LocalStorageValue(header: String, other: String)
-
-  object TraceLocalKey extends TraceLocal.TraceLocalKey {
-    type ValueType = LocalStorageValue
-  }
+  val TraceLocalHeaderKey = AvailableToMdc("header")
+  val TraceLocalOtherKey = AvailableToMdc("other")
 
   before {
     LoggingHandler.startLogging()
@@ -60,7 +59,8 @@ class LoggerLikeInstrumentationSpec extends PlaySpec with OneServerPerSuite with
     case ("GET", "/logging") ⇒
       Action.async {
         Future {
-          TraceLocal.store(TraceLocalKey)(LocalStorageValue(headerValue, otherValue))
+          TraceLocal.store(TraceLocalHeaderKey)(headerValue)
+          TraceLocal.store(TraceLocalOtherKey)(otherValue)
           LoggingHandler.info(infoMessage)
           Ok("OK")
         }(executor)
@@ -68,12 +68,13 @@ class LoggerLikeInstrumentationSpec extends PlaySpec with OneServerPerSuite with
   })
 
   "the LoggerLike instrumentation" should {
-    "be put the properties of TraceLocal into the MDC as key -> value in a request" in {
+    "allow retrieve a value from the MDC when was created a key of type AvailableToMdc in the current request" in {
       LoggingHandler.appenderStart()
 
-      val Some(result) = route(FakeRequest(GET, "/logging"))
-      Thread.sleep(500) // wait to complete the future
-      TraceLocal.retrieve(TraceLocalKey) must be(Some(LocalStorageValue(headerValue, otherValue)))
+      Await.result(route(FakeRequest(GET, "/logging")).get, 500 millis)
+
+      TraceLocal.retrieve(TraceLocalHeaderKey) must be(Some(headerValue))
+      TraceLocal.retrieve(TraceLocalOtherKey) must be(Some(otherValue))
 
       LoggingHandler.appenderStop()
 
diff --git a/project/Settings.scala b/project/Settings.scala
index 484640b7..de8e4998 100644
--- a/project/Settings.scala
+++ b/project/Settings.scala
@@ -35,6 +35,7 @@ object Settings {
       "-target:jvm-1.6",
       "-language:postfixOps",
       "-language:implicitConversions",
+      "-Yinline-warnings",
       "-Xlog-reflective-calls"
     )) ++ publishSettings ++ releaseSettings ++ graphSettings