diff --git a/akka-actor-tests/src/test/java/akka/event/ActorWithMDC.java b/akka-actor-tests/src/test/java/akka/event/ActorWithMDC.java new file mode 100644 index 0000000000..3728022ed0 --- /dev/null +++ b/akka-actor-tests/src/test/java/akka/event/ActorWithMDC.java @@ -0,0 +1,61 @@ +package akka.event; + +import akka.actor.UntypedActor; + +import java.util.Collections; +import java.util.LinkedHashMap; +import java.util.Map; + +public class ActorWithMDC extends UntypedActor { + + private final DiagnosticLoggingAdapter logger = Logging.getLogger(this); + + @Override + public void onReceive(Object message) throws Exception { + Log log = (Log) message; + + Map mdc; + if(log.message.startsWith("No MDC")) { + mdc = Collections.emptyMap(); + } else if(log.message.equals("Null MDC")) { + mdc = null; + } else { + mdc = new LinkedHashMap(); + mdc.put("messageLength", log.message.length()); + } + logger.setMDC(mdc); + + switch (log.level()) { + case 1: + logger.error(log.message); + break; + case 2: + logger.warning(log.message); + break; + case 3: + logger.info(log.message); + break; + default: + logger.debug(log.message); + break; + } + + logger.clearMDC(); + } + + public static class Log { + private final Object level; + public final String message; + + public Log(Object level, String message) { + this.level = level; + this.message = message; + } + + public int level() { + return (Integer) this.level; + } + } + + +} diff --git a/akka-actor-tests/src/test/java/akka/event/LoggingAdapterTest.java b/akka-actor-tests/src/test/java/akka/event/LoggingAdapterTest.java new file mode 100644 index 0000000000..86de30d159 --- /dev/null +++ b/akka-actor-tests/src/test/java/akka/event/LoggingAdapterTest.java @@ -0,0 +1,142 @@ +package akka.event; + +import akka.actor.ActorRef; +import akka.actor.ActorSystem; +import akka.actor.Props; +import akka.testkit.JavaTestKit; +import akka.event.Logging.Error; +import akka.event.ActorWithMDC.Log; +import static akka.event.Logging.*; + +import com.typesafe.config.Config; +import com.typesafe.config.ConfigFactory; +import org.junit.Test; +import scala.concurrent.duration.Duration; + +import java.util.*; +import java.util.concurrent.TimeUnit; + +import static org.junit.Assert.assertEquals; +import static org.junit.Assert.assertNotNull; +import static org.junit.Assert.assertSame; + + +public class LoggingAdapterTest { + + private static final Config config = ConfigFactory.parseString( + "akka.loglevel = DEBUG\n" + + "akka.actor.serialize-messages = off" + ); + + @Test + public void mustFormatMessage() { + final ActorSystem system = ActorSystem.create("test-system", config); + final LoggingAdapter log = Logging.getLogger(system, this); + new LogJavaTestKit(system) {{ + system.eventStream().subscribe(getRef(), LogEvent.class); + log.error("One arg message: {}", "the arg"); + expectLog(ErrorLevel(), "One arg message: the arg"); + + Throwable cause = new IllegalStateException("This state is illegal"); + log.error(cause, "Two args message: {}, {}", "an arg", "another arg"); + expectLog(ErrorLevel(), "Two args message: an arg, another arg", cause); + + int[] primitiveArgs = {10, 20, 30}; + log.warning("Args as array of primitives: {}, {}, {}", primitiveArgs); + expectLog(WarningLevel(), "Args as array of primitives: 10, 20, 30"); + + Date now = new Date(); + UUID uuid = UUID.randomUUID(); + Object[] objArgs = {"A String", now, uuid}; + log.info("Args as array of objects: {}, {}, {}", objArgs); + expectLog(InfoLevel(), "Args as array of objects: A String, " + now.toString() + ", " + uuid.toString()); + + log.debug("Four args message: {}, {}, {}, {}", 1, 2, 3, 4); + expectLog(DebugLevel(), "Four args message: 1, 2, 3, 4"); + + }}; + } + + @Test + public void mustCallMdcForEveryLog() throws Exception { + final ActorSystem system = ActorSystem.create("test-system", config); + new LogJavaTestKit(system) {{ + system.eventStream().subscribe(getRef(), LogEvent.class); + ActorRef ref = system.actorOf(Props.create(ActorWithMDC.class)); + + ref.tell(new Log(ErrorLevel(), "An Error"), system.deadLetters()); + expectLog(ErrorLevel(), "An Error", "Map(messageLength -> 8)"); + ref.tell(new Log(WarningLevel(), "A Warning"), system.deadLetters()); + expectLog(WarningLevel(), "A Warning", "Map(messageLength -> 9)"); + ref.tell(new Log(InfoLevel(), "Some Info"), system.deadLetters()); + expectLog(InfoLevel(), "Some Info", "Map(messageLength -> 9)"); + ref.tell(new Log(DebugLevel(), "No MDC for 4th call"), system.deadLetters()); + expectLog(DebugLevel(), "No MDC for 4th call"); + ref.tell(new Log(Logging.DebugLevel(), "And now yes, a debug with MDC"), system.deadLetters()); + expectLog(DebugLevel(), "And now yes, a debug with MDC", "Map(messageLength -> 29)"); + }}; + } + + @Test + public void mustSupportMdcNull() throws Exception { + final ActorSystem system = ActorSystem.create("test-system", config); + new LogJavaTestKit(system) {{ + system.eventStream().subscribe(getRef(), LogEvent.class); + ActorRef ref = system.actorOf(Props.create(ActorWithMDC.class)); + + ref.tell(new Log(InfoLevel(), "Null MDC"), system.deadLetters()); + expectLog(InfoLevel(), "Null MDC", "Map()"); + }}; + } + + /* + * #3671: Let the application specify custom MDC values + * Java backward compatibility check + */ + @Test + public void mustBeAbleToCreateLogEventsWithOldConstructor() throws Exception { + assertNotNull(new Error(new Exception(), "logSource", this.getClass(), "The message")); + assertNotNull(new Error("logSource", this.getClass(), "The message")); + assertNotNull(new Warning("logSource", this.getClass(), "The message")); + assertNotNull(new Info("logSource", this.getClass(), "The message")); + assertNotNull(new Debug("logSource", this.getClass(), "The message")); + } + + private static class LogJavaTestKit extends JavaTestKit { + + private static final String emptyMDC = "Map()"; + + public LogJavaTestKit(ActorSystem system) { + super(system); + } + + void expectLog(Object level, String message) { + expectLog(level, message, null, emptyMDC); + } + + void expectLog(Object level, String message, Throwable cause) { + expectLog(level, message, cause, emptyMDC); + } + + void expectLog(Object level, String message, String mdc) { + expectLog(level, message, null, mdc); + } + + void expectLog(final Object level, final String message, final Throwable cause, final String mdc) { + new ExpectMsg(Duration.create(3, TimeUnit.SECONDS), "LogEvent") { + protected Void match(Object event) { + LogEvent log = (LogEvent) event; + assertEquals(message, log.message()); + assertEquals(level, log.level()); + assertEquals(mdc, log.mdc().toString()); + if(cause != null) { + Error error = (Error) log; + assertSame(cause, error.cause()); + } + return null; + } + }; + } + } +} + diff --git a/akka-actor-tests/src/test/scala/akka/event/LoggerSpec.scala b/akka-actor-tests/src/test/scala/akka/event/LoggerSpec.scala index 465a124fd5..d14ae89e43 100644 --- a/akka-actor-tests/src/test/scala/akka/event/LoggerSpec.scala +++ b/akka-actor-tests/src/test/scala/akka/event/LoggerSpec.scala @@ -6,13 +6,16 @@ package akka.event import akka.testkit._ import scala.concurrent.duration._ import com.typesafe.config.{ Config, ConfigFactory } -import akka.actor.{ ActorRef, Actor, ActorSystem } +import akka.actor._ import java.util.{ Date, GregorianCalendar, TimeZone, Calendar } import org.scalatest.WordSpec import org.scalatest.matchers.MustMatchers import akka.serialization.SerializationExtension -import akka.event.Logging.{ Warning, LogEvent, LoggerInitialized, InitializeLogger } +import akka.event.Logging._ import akka.util.Helpers +import akka.event.Logging.InitializeLogger +import scala.Some +import akka.event.Logging.Warning object LoggerSpec { @@ -55,6 +58,17 @@ object LoggerSpec { } """).withFallback(AkkaSpec.testConf) + val ticket3671Config = ConfigFactory.parseString(""" + akka { + stdout-loglevel = "WARNING" + loglevel = "WARNING" + loggers = ["akka.event.LoggerSpec$TestLogger1"] + actor { + serialize-messages = off + } + } + """).withFallback(AkkaSpec.testConf) + case class SetTarget(ref: ActorRef, qualifier: Int) class TestLogger1 extends TestLogger(1) @@ -68,11 +82,33 @@ object LoggerSpec { case SetTarget(ref, `qualifier`) ⇒ target = Some(ref) ref ! ("OK") + case event: LogEvent if !event.mdc.isEmpty ⇒ + print(event) + target foreach { _ ! event } case event: LogEvent ⇒ print(event) target foreach { _ ! event.message } } } + + class ActorWithMDC extends Actor with DiagnosticActorLogging { + var reqId = 0 + + override def mdc(currentMessage: Any): MDC = { + reqId += 1 + val always = Map("requestId" -> reqId) + val perMessage = currentMessage match { + case cm @ "Current Message in MDC" ⇒ Map("currentMsg" -> cm, "currentMsgLength" -> cm.length) + case _ ⇒ Map() + } + always ++ perMessage + } + + def receive: Receive = { + case m: String ⇒ log.warning(m) + } + } + } @org.junit.runner.RunWith(classOf[org.scalatest.junit.JUnitRunner]) @@ -144,6 +180,47 @@ class LoggerSpec extends WordSpec with MustMatchers { } } + "Ticket 3671" must { + + "log message with given MDC values" in { + implicit val system = ActorSystem("ticket-3671", ticket3671Config) + try { + val probe = TestProbe() + system.eventStream.publish(SetTarget(probe.ref, qualifier = 1)) + probe.expectMsg("OK") + + val ref = system.actorOf(Props[ActorWithMDC]) + + ref ! "Processing new Request" + probe.expectMsgPF(max = 3.seconds) { + case w @ Warning(_, _, "Processing new Request") if w.mdc.size == 1 && w.mdc("requestId") == 1 ⇒ + } + + ref ! "Processing another Request" + probe.expectMsgPF(max = 3.seconds) { + case w @ Warning(_, _, "Processing another Request") if w.mdc.size == 1 && w.mdc("requestId") == 2 ⇒ + } + + ref ! "Current Message in MDC" + probe.expectMsgPF(max = 3.seconds) { + case w @ Warning(_, _, "Current Message in MDC") if w.mdc.size == 3 && + w.mdc("requestId") == 3 && + w.mdc("currentMsg") == "Current Message in MDC" && + w.mdc("currentMsgLength") == 22 ⇒ + } + + ref ! "Current Message removed from MDC" + probe.expectMsgPF(max = 3.seconds) { + case w @ Warning(_, _, "Current Message removed from MDC") if w.mdc.size == 1 && w.mdc("requestId") == 4 ⇒ + } + + } finally { + TestKit.shutdownActorSystem(system) + } + } + + } + "Ticket 3080" must { "format currentTimeMillis to a valid UTC String" in { val timestamp = System.currentTimeMillis diff --git a/akka-actor/src/main/scala/akka/actor/Actor.scala b/akka-actor/src/main/scala/akka/actor/Actor.scala index 76f4b7f729..1bfa971285 100644 --- a/akka-actor/src/main/scala/akka/actor/Actor.scala +++ b/akka-actor/src/main/scala/akka/actor/Actor.scala @@ -282,6 +282,37 @@ trait ActorLogging { this: Actor ⇒ val log = akka.event.Logging(context.system, this) } +/** + * Scala API: Mix in DiagnosticActorLogging into your Actor to easily obtain a reference to a logger with MDC support, + * which is available under the name "log". + * In the example bellow "the one who knocks" will be available under the key "iam" for using it in the logback pattern. + * + * {{{ + * class MyActor extends Actor with DiagnosticActorLogging { + * + * override def mdc(currentMessage: Any): MDC = { + * Map("iam", "the one who knocks") + * } + * + * def receive = { + * case "pigdog" => log.info("We've got yet another pigdog on our hands") + * } + * } + * }}} + */ +trait DiagnosticActorLogging extends Actor { + import akka.event.Logging._ + val log = akka.event.Logging(this) + def mdc(currentMessage: Any): MDC = emptyMDC + + override protected[akka] def aroundReceive(receive: Actor.Receive, msg: Any): Unit = try { + log.mdc(mdc(msg)) + super.aroundReceive(receive, msg) + } finally { + log.clearMDC() + } +} + object Actor { /** * Type alias representing a Receive-expression for Akka Actors. diff --git a/akka-actor/src/main/scala/akka/event/Logging.scala b/akka-actor/src/main/scala/akka/event/Logging.scala index f7b5025c8d..eef6d5288a 100644 --- a/akka-actor/src/main/scala/akka/event/Logging.scala +++ b/akka-actor/src/main/scala/akka/event/Logging.scala @@ -8,7 +8,7 @@ import language.existentials import akka.actor._ import akka.{ ConfigurationException, AkkaException } import akka.actor.ActorSystem.Settings -import akka.util.{ Timeout, ReentrantGuard } +import akka.util.ReentrantGuard import java.util.concurrent.atomic.AtomicInteger import java.util.concurrent.TimeoutException import scala.annotation.implicitNotFound @@ -517,6 +517,15 @@ object Logging { new BusLogging(bus, str, clazz) } + /** + * Obtain LoggingAdapter with MDC support for the given actor. + * Don't use it outside its specific Actor as it isn't thread safe + */ + def apply(logSource: Actor): DiagnosticLoggingAdapter = { + val (str, clazz) = LogSource(logSource) + new BusLogging(logSource.context.system.eventStream, str, clazz) with DiagnosticLoggingAdapter + } + /** * Obtain LoggingAdapter for the given actor system and source object. This * will use the system’s event stream and include the system’s address in the @@ -553,6 +562,15 @@ object Logging { new BusLogging(bus, str, clazz) } + /** + * Obtain LoggingAdapter with MDC support for the given actor. + * Don't use it outside its specific Actor as it isn't thread safe + */ + def getLogger(logSource: UntypedActor): DiagnosticLoggingAdapter = { + val (str, clazz) = LogSource.fromAnyRef(logSource) + new BusLogging(logSource.getContext().system.eventStream, str, clazz) with DiagnosticLoggingAdapter + } + /** * Artificial exception injected into Error events if no Throwable is * supplied; used for getting a stack dump of error locations. @@ -601,6 +619,11 @@ object Logging { * The message, may be any object or null. */ def message: Any + + /** + * Extra values for adding to MDC + */ + def mdc: MDC = emptyMDC } /** @@ -608,12 +631,16 @@ object Logging { */ case class Error(cause: Throwable, logSource: String, logClass: Class[_], message: Any = "") extends LogEvent { def this(logSource: String, logClass: Class[_], message: Any) = this(Error.NoCause, logSource, logClass, message) - override def level = ErrorLevel } + class Error2(cause: Throwable, logSource: String, logClass: Class[_], message: Any = "", override val mdc: MDC) extends Error(cause, logSource, logClass, message) { + def this(logSource: String, logClass: Class[_], message: Any, mdc: MDC) = this(Error.NoCause, logSource, logClass, message, mdc) + } object Error { def apply(logSource: String, logClass: Class[_], message: Any) = new Error(NoCause, logSource, logClass, message) + def apply(cause: Throwable, logSource: String, logClass: Class[_], message: Any, mdc: MDC) = new Error2(cause, logSource, logClass, message, mdc) + def apply(logSource: String, logClass: Class[_], message: Any, mdc: MDC) = new Error2(NoCause, logSource, logClass, message, mdc) /** Null Object used for errors without cause Throwable */ object NoCause extends NoStackTrace @@ -626,6 +653,10 @@ object Logging { case class Warning(logSource: String, logClass: Class[_], message: Any = "") extends LogEvent { override def level = WarningLevel } + class Warning2(logSource: String, logClass: Class[_], message: Any, override val mdc: MDC) extends Warning(logSource, logClass, message) + object Warning { + def apply(logSource: String, logClass: Class[_], message: Any, mdc: MDC) = new Warning2(logSource, logClass, message, mdc) + } /** * For INFO Logging @@ -633,6 +664,10 @@ object Logging { case class Info(logSource: String, logClass: Class[_], message: Any = "") extends LogEvent { override def level = InfoLevel } + class Info2(logSource: String, logClass: Class[_], message: Any, override val mdc: MDC) extends Info(logSource, logClass, message) + object Info { + def apply(logSource: String, logClass: Class[_], message: Any, mdc: MDC) = new Info2(logSource, logClass, message, mdc) + } /** * For DEBUG Logging @@ -640,6 +675,10 @@ object Logging { case class Debug(logSource: String, logClass: Class[_], message: Any = "") extends LogEvent { override def level = DebugLevel } + class Debug2(logSource: String, logClass: Class[_], message: Any, override val mdc: MDC) extends Debug(logSource, logClass, message) + object Debug { + def apply(logSource: String, logClass: Class[_], message: Any, mdc: MDC) = new Debug2(logSource, logClass, message, mdc) + } /** * Message which is sent to each default logger (i.e. from configuration file) @@ -777,6 +816,10 @@ object Logging { sw.toString } + type MDC = Map[String, Any] + + val emptyMDC: MDC = Map() + } /** @@ -800,6 +843,9 @@ object Logging { */ trait LoggingAdapter { + type MDC = Logging.MDC + def mdc = Logging.emptyMDC + /* * implement these as precisely as needed/possible: always returning true * just makes the notify... methods be called every time. @@ -1018,7 +1064,70 @@ trait LoggingAdapter { } /** - * [[LoggingAdapter]] that publishes [[akka.event.Logging.LogEvent]] to event stream. + * LoggingAdapter extension which adds MDC support. + * Only recommended to be used within Actors as it isn't thread safe. + */ +trait DiagnosticLoggingAdapter extends LoggingAdapter { + + import Logging._ + import scala.collection.JavaConverters._ + import java.{ util ⇒ ju } + + private var _mdc = emptyMDC + + /** + * Scala API: + * Mapped Diagnostic Context for application defined values + * which can be used in PatternLayout when [[akka.event.slf4j.Slf4jLogger]] is configured. + * Visit Logback Docs: MDC for more information. + * + * @return A Map containing the MDC values added by the application, or empty Map if no value was added. + */ + override def mdc: MDC = _mdc + + /** + * Scala API: + * Sets the values to be added to the MDC (Mapped Diagnostic Context) before the log is appended. + * These values can be used in PatternLayout when [[akka.event.slf4j.Slf4jLogger]] is configured. + * Visit Logback Docs: MDC for more information. + */ + def mdc(mdc: MDC): Unit = _mdc = if (mdc != null) mdc else emptyMDC + + /** + * Java API: + * Mapped Diagnostic Context for application defined values + * which can be used in PatternLayout when [[akka.event.slf4j.Slf4jLogger]] is configured. + * Visit Logback Docs: MDC for more information. + * Note tha it returns a COPY of the actual MDC values. + * You cannot modify any value by changing the returned Map. + * Code like the following won't have any effect unless you set back the modified Map. + * 
+   *   Map mdc = log.getMDC();
+   *   mdc.put("key", value);
+   *   // NEEDED
+   *   log.setMDC(mdc);
+   *
+ * + * @return A copy of the actual MDC values + */ + def getMDC: ju.Map[String, Any] = mdc.asJava + + /** + * Java API: + * Sets the values to be added to the MDC (Mapped Diagnostic Context) before the log is appended. + * These values can be used in PatternLayout when [[akka.event.slf4j.Slf4jLogger]] is configured. + * Visit Logback Docs: MDC for more information. + */ + def setMDC(jMdc: java.util.Map[String, Any]): Unit = mdc(if (jMdc != null) jMdc.asScala.toMap else emptyMDC) + + /** + * Clear all entries in the MDC + */ + def clearMDC(): Unit = mdc(emptyMDC) +} + +/** + * [[akka.event.LoggingAdapter]] that publishes [[akka.event.Logging.LogEvent]] to event stream. */ class BusLogging(val bus: LoggingBus, val logSource: String, val logClass: Class[_]) extends LoggingAdapter { @@ -1029,11 +1138,11 @@ class BusLogging(val bus: LoggingBus, val logSource: String, val logClass: Class def isInfoEnabled = bus.logLevel >= InfoLevel def isDebugEnabled = bus.logLevel >= DebugLevel - protected def notifyError(message: String): Unit = bus.publish(Error(logSource, logClass, message)) - protected def notifyError(cause: Throwable, message: String): Unit = bus.publish(Error(cause, logSource, logClass, message)) - protected def notifyWarning(message: String): Unit = bus.publish(Warning(logSource, logClass, message)) - protected def notifyInfo(message: String): Unit = bus.publish(Info(logSource, logClass, message)) - protected def notifyDebug(message: String): Unit = bus.publish(Debug(logSource, logClass, message)) + protected def notifyError(message: String): Unit = bus.publish(Error(logSource, logClass, message, mdc)) + protected def notifyError(cause: Throwable, message: String): Unit = bus.publish(Error(cause, logSource, logClass, message, mdc)) + protected def notifyWarning(message: String): Unit = bus.publish(Warning(logSource, logClass, message, mdc)) + protected def notifyInfo(message: String): Unit = bus.publish(Info(logSource, logClass, message, mdc)) + protected def notifyDebug(message: String): Unit = bus.publish(Debug(logSource, logClass, message, mdc)) } /** diff --git a/akka-docs/rst/java/code/docs/event/LoggingDocTest.java b/akka-docs/rst/java/code/docs/event/LoggingDocTest.java index cca473befc..59b7693704 100644 --- a/akka-docs/rst/java/code/docs/event/LoggingDocTest.java +++ b/akka-docs/rst/java/code/docs/event/LoggingDocTest.java @@ -22,6 +22,13 @@ import org.junit.Test; import akka.testkit.JavaTestKit; import scala.Option; +//#imports-mdc +import akka.event.Logging; +import akka.event.DiagnosticLoggingAdapter; +import java.util.HashMap; +import java.util.Map; +//#imports-mdc + //#imports-deadletter import akka.actor.Props; import akka.actor.ActorRef; @@ -40,6 +47,14 @@ public class LoggingDocTest { JavaTestKit.shutdownActorSystem(system); } + @Test + public void useLoggingActorWithMDC() { + ActorSystem system = ActorSystem.create("MyDiagnosticSystem"); + ActorRef mdcActor = system.actorOf(Props.create(MdcActor.class, this)); + mdcActor.tell("some request", ActorRef.noSender()); + JavaTestKit.shutdownActorSystem(system); + } + @Test public void subscribeToDeadLetters() { //#deadletters @@ -86,6 +101,27 @@ public class LoggingDocTest { //#my-actor + //#mdc-actor + class MdcActor extends UntypedActor { + + final DiagnosticLoggingAdapter log = Logging.getLogger(this); + + public void onReceive(Object message) { + + Map mdc; + mdc = new HashMap(); + mdc.put("requestId", 1234); + mdc.put("visitorId", 5678); + log.setMDC(mdc); + + log.info("Starting new request"); + + log.clearMDC(); + } + } + + //#mdc-actor + //#my-event-listener class MyEventListener extends UntypedActor { public void onReceive(Object message) { diff --git a/akka-docs/rst/java/logging.rst b/akka-docs/rst/java/logging.rst index 3ef905c120..5eec1f9c31 100644 --- a/akka-docs/rst/java/logging.rst +++ b/akka-docs/rst/java/logging.rst @@ -335,3 +335,43 @@ If you want to more accurately output the timestamp, use the MDC attribute ``akk %X{akkaTimestamp} %-5level %logger{36} %X{akkaSource} - %msg%n + + +MDC values defined by the application +------------------------------------- + +One useful feature available in Slf4j is `MDC `_, +Akka has a way for let the application specify custom values, you just need to get a +specialized :class:`LoggingAdapter`, the :class:`DiagnosticLoggingAdapter`. In order to +get it you will use the factory receiving an UntypedActor as logSource: + +.. code-block:: scala + + // Within your UntypedActor + final DiagnosticLoggingAdapter log = Logging.getLogger(this); + +Once you have the logger, you just need to add the custom values before you log something. +This way, the values will be put in the SLF4J MDC right before appending the log and removed after. + +.. note:: + + The cleanup (removal) should be done in the actor at the end, + otherwise, next message will log with same mdc values, + if it is not set to a new map. Use ``log.clearMDC()``. + +.. includecode:: code/docs/event/LoggingDocTest.java + :include: imports-mdc + +.. includecode:: code/docs/event/LoggingDocTest.java + :include: mdc-actor + +Now, the values will be available in the MDC, so you can use them in the layout pattern:: + + + + + %-5level %logger{36} [req: %X{requestId}, visitor: %X{visitorId}] - %msg%n + + + + diff --git a/akka-docs/rst/scala/code/docs/event/LoggingDocSpec.scala b/akka-docs/rst/scala/code/docs/event/LoggingDocSpec.scala index 7725b62f43..136f4c7f11 100644 --- a/akka-docs/rst/scala/code/docs/event/LoggingDocSpec.scala +++ b/akka-docs/rst/scala/code/docs/event/LoggingDocSpec.scala @@ -28,6 +28,54 @@ object LoggingDocSpec { } //#my-actor + import akka.event.Logging + + class MdcActor extends Actor { + val log = Logging(this) + def receive = { + + case _ ⇒ { + //#mdc + val mdc = Map("requestId" -> 1234, "visitorId" -> 5678) + log.mdc(mdc) + + // Log something + log.info("Starting new request") + + log.clearMDC() + //#mdc + } + } + } + + //#mdc-actor + import Logging.MDC + + case class Req(work: String, visitorId: Int) + + class MdcActorMixin extends Actor with akka.actor.DiagnosticActorLogging { + var reqId = 0 + + override def mdc(currentMessage: Any): MDC = { + reqId += 1 + val always = Map("requestId" -> reqId) + val perMessage = currentMessage match { + case r: Req => Map("visitorId" -> r.visitorId) + case _ => Map() + } + always ++ perMessage + } + + def receive: Receive = { + case r: Req => { + log.info(s"Starting new request: ${r.work}") + } + } + } + + //#mdc-actor + + //#my-event-listener import akka.event.Logging.InitializeLogger import akka.event.Logging.LoggerInitialized @@ -69,13 +117,23 @@ object LoggingDocSpec { class LoggingDocSpec extends AkkaSpec { - import LoggingDocSpec.MyActor + import LoggingDocSpec.{MyActor, MdcActor, MdcActorMixin, Req} "use a logging actor" in { val myActor = system.actorOf(Props[MyActor]) myActor ! "test" } + "use a MDC logging actor" in { + val mdcActor = system.actorOf(Props[MdcActor]) + mdcActor ! "some request" + } + + "use a MDC logging actor by mixin" in { + val mdcActor = system.actorOf(Props[MdcActorMixin]) + mdcActor ! Req("some request", 5678) + } + "allow registration to dead letters" in { new AnyRef { //#deadletters diff --git a/akka-docs/rst/scala/logging.rst b/akka-docs/rst/scala/logging.rst index ddb8faf110..ecec111f23 100644 --- a/akka-docs/rst/scala/logging.rst +++ b/akka-docs/rst/scala/logging.rst @@ -373,4 +373,46 @@ If you want to more accurately output the timestamp, use the MDC attribute ``akk %X{akkaTimestamp} %-5level %logger{36} %X{akkaSource} - %msg%n - \ No newline at end of file + + +MDC values defined by the application +------------------------------------- + +One useful feature available in Slf4j is `MDC `_, +Akka has a way for let the application specify custom values, you just need to get a +specialized :class:`LoggingAdapter`, the :class:`DiagnosticLoggingAdapter`. In order to +get it you will use the factory receiving an Actor as logSource: + +.. code-block:: scala + + // Within your Actor + val log: DiagnosticLoggingAdapter = Logging(this); + +Once you have the logger, you just need to add the custom values before you log something. +This way, the values will be put in the SLF4J MDC right before appending the log and removed after. + +.. note:: + + The cleanup (removal) should be done in the actor at the end, + otherwise, next message will log with same mdc values, + if it is not set to a new map. Use ``log.clearMDC()``. + +.. includecode:: code/docs/event/LoggingDocSpec.scala#mdc + +For convenience you can mixin the ``log`` member into actors, instead of defining it as above. +This trait also lets you override ``def mdc(msg: Any): MDC`` for specifying MDC values +depending on current message and lets you forget about the cleanup as well, since it already does it for you. + +.. includecode:: code/docs/event/LoggingDocSpec.scala + :include: mdc-actor + +Now, the values will be available in the MDC, so you can use them in the layout pattern:: + + + + + %-5level %logger{36} [req: %X{requestId}, visitor: %X{visitorId}] - %msg%n + + + + diff --git a/akka-slf4j/src/main/scala/akka/event/slf4j/Slf4jLogger.scala b/akka-slf4j/src/main/scala/akka/event/slf4j/Slf4jLogger.scala index 7d90e69d71..9ba28fa3de 100644 --- a/akka-slf4j/src/main/scala/akka/event/slf4j/Slf4jLogger.scala +++ b/akka-slf4j/src/main/scala/akka/event/slf4j/Slf4jLogger.scala @@ -63,7 +63,7 @@ class Slf4jLogger extends Actor with SLF4JLogging { withMdc(logSource, event) { cause match { case Error.NoCause | null ⇒ Logger(logClass, logSource).error(if (message != null) message.toString else null) - case cause ⇒ Logger(logClass, logSource).error(if (message != null) message.toString else cause.getLocalizedMessage, cause) + case _ ⇒ Logger(logClass, logSource).error(if (message != null) message.toString else cause.getLocalizedMessage, cause) } } @@ -86,10 +86,12 @@ class Slf4jLogger extends Actor with SLF4JLogging { MDC.put(mdcAkkaSourceAttributeName, logSource) MDC.put(mdcThreadAttributeName, logEvent.thread.getName) MDC.put(mdcAkkaTimestamp, formatTimestamp(logEvent.timestamp)) + logEvent.mdc foreach { case (k, v) ⇒ MDC.put(k, String.valueOf(v)) } try logStatement finally { MDC.remove(mdcAkkaSourceAttributeName) MDC.remove(mdcThreadAttributeName) MDC.remove(mdcAkkaTimestamp) + logEvent.mdc.keys.foreach(k ⇒ MDC.remove(k)) } } diff --git a/akka-slf4j/src/test/resources/logback-test.xml b/akka-slf4j/src/test/resources/logback-test.xml index 3950f793ea..079707e6ef 100644 --- a/akka-slf4j/src/test/resources/logback-test.xml +++ b/akka-slf4j/src/test/resources/logback-test.xml @@ -11,7 +11,7 @@ - %date{ISO8601} level=[%level] logger=[%logger] akkaSource=[%X{akkaSource}] sourceThread=[%X{sourceThread}] - msg=[%msg]%n----%n + %date{ISO8601} level=[%level] logger=[%logger] akkaSource=[%X{akkaSource}] sourceThread=[%X{sourceThread}] mdc=[ticket-#%X{ticketNumber}: %X{ticketDesc}] - msg=[%msg]%n----%n diff --git a/akka-slf4j/src/test/scala/akka/event/slf4j/Slf4jLoggerSpec.scala b/akka-slf4j/src/test/scala/akka/event/slf4j/Slf4jLoggerSpec.scala index 04a305e716..bb525b0d8d 100644 --- a/akka-slf4j/src/test/scala/akka/event/slf4j/Slf4jLoggerSpec.scala +++ b/akka-slf4j/src/test/scala/akka/event/slf4j/Slf4jLoggerSpec.scala @@ -6,11 +6,9 @@ package akka.event.slf4j import language.postfixOps import akka.testkit.AkkaSpec -import akka.actor.Actor -import akka.actor.ActorLogging +import akka.actor.{ DiagnosticActorLogging, Actor, ActorLogging, Props } import scala.concurrent.duration._ import akka.event.Logging -import akka.actor.Props import ch.qos.logback.core.OutputStreamAppender import java.io.StringWriter import java.io.ByteArrayOutputStream @@ -28,12 +26,17 @@ object Slf4jLoggerSpec { } """ - class LogProducer extends Actor with ActorLogging { + class LogProducer extends Actor with DiagnosticActorLogging { + def receive = { case e: Exception ⇒ log.error(e, e.getMessage) case (s: String, x: Int, y: Int) ⇒ log.info(s, x, y) + case (s: String, mdc: Map[String, Any]) ⇒ + log.mdc(mdc) + log.info(s) + log.clearMDC() } } @@ -92,6 +95,32 @@ class Slf4jLoggerSpec extends AkkaSpec(Slf4jLoggerSpec.config) with BeforeAndAft s must include("msg=[test x=3 y=17]") } + "put custom MDC values when specified" in { + producer ! ("Message with custom MDC values", Map("ticketNumber" -> 3671, "ticketDesc" -> "Custom MDC Values")) + + awaitCond(outputString.contains("----"), 5 seconds) + val s = outputString + s must include("akkaSource=[akka://Slf4jLoggerSpec/user/logProducer]") + s must include("level=[INFO]") + s must include("logger=[akka.event.slf4j.Slf4jLoggerSpec$LogProducer]") + s must include regex (sourceThreadRegex) + s must include("mdc=[ticket-#3671: Custom MDC Values]") + s must include("msg=[Message with custom MDC values]") + } + + "Support null values in custom MDC" in { + producer ! ("Message with null custom MDC values", Map("ticketNumber" -> 3671, "ticketDesc" -> null)) + + awaitCond(outputString.contains("----"), 5 seconds) + val s = outputString + s must include("akkaSource=[akka://Slf4jLoggerSpec/user/logProducer]") + s must include("level=[INFO]") + s must include("logger=[akka.event.slf4j.Slf4jLoggerSpec$LogProducer]") + s must include regex (sourceThreadRegex) + s must include("mdc=[ticket-#3671: null]") + s must include("msg=[Message with null custom MDC values]") + } + "include system info in akkaSource when creating Logging with system" in { val log = Logging(system, "akka.event.slf4j.Slf4jLoggerSpec.MyLogSource") log.info("test")