From 8cb2721c33aaa4a30de56229bb7e87411a3f95e3 Mon Sep 17 00:00:00 2001 From: Patrik Nordwall Date: Tue, 17 Sep 2019 17:26:13 +0200 Subject: [PATCH] Reference docs for SL4J logging in Typed, #27648 (#27696) * Reference docs for SL4J logging in Typed, #27648 * mention package implicit for LoggerOps * reference docs of log testing utilities * cleanup classic logging.md * most of it is still relevant, and different enough from typed/logging.md to keep it separate * use ThresholdFilter instead of LevelFilter Co-Authored-By: Will Sargent --- .../javadsl/JunitIntegrationExampleTest.java | 8 +- .../javadsl/LogCapturingExampleTest.java | 32 ++ .../src/test/resources/logback-test.xml | 5 +- .../ScalaTestIntegrationExampleSpec.scala | 18 + .../jdocs/akka/typed/LoggingDocExamples.java | 191 +++++++++ .../src/test/resources/logback-doc-dev.xml | 30 ++ .../src/test/resources/logback-doc-prod.xml | 24 ++ .../src/test/resources/logback-doc-test.xml | 32 ++ .../src/test/resources/logback-test.xml | 5 +- .../docs/akka/typed/LoggingDocExamples.scala | 144 +++++++ .../scala/docs/akka/typed/myapp/package.scala | 18 + .../src/main/resources/logback-test.xml | 5 +- .../src/test/resources/logback-test.xml | 5 +- .../src/test/resources/logback-test.xml | 5 +- akka-docs/src/main/paradox/index-utilities.md | 2 +- akka-docs/src/main/paradox/logging.md | 36 +- akka-docs/src/main/paradox/typed/logging.md | 393 ++++++++++++++++++ akka-docs/src/main/paradox/typed/testing.md | 59 +++ akka-docs/src/test/resources/logback-test.xml | 5 +- .../src/test/resources/logback-test.xml | 5 +- project/Dependencies.scala | 3 +- project/Paradox.scala | 3 +- 22 files changed, 998 insertions(+), 30 deletions(-) create mode 100644 akka-actor-testkit-typed/src/test/java/jdocs/akka/actor/testkit/typed/javadsl/LogCapturingExampleTest.java create mode 100644 akka-actor-typed-tests/src/test/java/jdocs/akka/typed/LoggingDocExamples.java create mode 100644 akka-actor-typed-tests/src/test/resources/logback-doc-dev.xml create mode 100644 akka-actor-typed-tests/src/test/resources/logback-doc-prod.xml create mode 100644 akka-actor-typed-tests/src/test/resources/logback-doc-test.xml create mode 100644 akka-actor-typed-tests/src/test/scala/docs/akka/typed/LoggingDocExamples.scala create mode 100644 akka-actor-typed-tests/src/test/scala/docs/akka/typed/myapp/package.scala create mode 100644 akka-docs/src/main/paradox/typed/logging.md diff --git a/akka-actor-testkit-typed/src/test/java/jdocs/akka/actor/testkit/typed/javadsl/JunitIntegrationExampleTest.java b/akka-actor-testkit-typed/src/test/java/jdocs/akka/actor/testkit/typed/javadsl/JunitIntegrationExampleTest.java index 707ee7ddde..0cbd8b76a1 100644 --- a/akka-actor-testkit-typed/src/test/java/jdocs/akka/actor/testkit/typed/javadsl/JunitIntegrationExampleTest.java +++ b/akka-actor-testkit-typed/src/test/java/jdocs/akka/actor/testkit/typed/javadsl/JunitIntegrationExampleTest.java @@ -8,20 +8,24 @@ import static jdocs.akka.actor.testkit.typed.javadsl.AsyncTestingExampleTest.Pin import static jdocs.akka.actor.testkit.typed.javadsl.AsyncTestingExampleTest.Pong; import static jdocs.akka.actor.testkit.typed.javadsl.AsyncTestingExampleTest.echoActor; -// #junit-integration import akka.actor.testkit.typed.javadsl.LogCapturing; +import org.junit.Rule; + +// #junit-integration import akka.actor.testkit.typed.javadsl.TestKitJunitResource; import akka.actor.testkit.typed.javadsl.TestProbe; import akka.actor.typed.ActorRef; import org.junit.ClassRule; -import org.junit.Rule; import org.junit.Test; public class JunitIntegrationExampleTest { @ClassRule public static final TestKitJunitResource testKit = new TestKitJunitResource(); + // #junit-integration + // this is shown in LogCapturingExampleTest @Rule public final LogCapturing logCapturing = new LogCapturing(); + // #junit-integration @Test public void testSomething() { diff --git a/akka-actor-testkit-typed/src/test/java/jdocs/akka/actor/testkit/typed/javadsl/LogCapturingExampleTest.java b/akka-actor-testkit-typed/src/test/java/jdocs/akka/actor/testkit/typed/javadsl/LogCapturingExampleTest.java new file mode 100644 index 0000000000..b8d8f9ef1d --- /dev/null +++ b/akka-actor-testkit-typed/src/test/java/jdocs/akka/actor/testkit/typed/javadsl/LogCapturingExampleTest.java @@ -0,0 +1,32 @@ +/* + * Copyright (C) 2009-2019 Lightbend Inc. + */ + +package jdocs.akka.actor.testkit.typed.javadsl; + +import static jdocs.akka.actor.testkit.typed.javadsl.AsyncTestingExampleTest.*; + +// #log-capturing +import akka.actor.testkit.typed.javadsl.LogCapturing; +import akka.actor.testkit.typed.javadsl.TestKitJunitResource; +import akka.actor.testkit.typed.javadsl.TestProbe; +import akka.actor.typed.ActorRef; +import org.junit.ClassRule; +import org.junit.Rule; +import org.junit.Test; + +public class LogCapturingExampleTest { + + @ClassRule public static final TestKitJunitResource testKit = new TestKitJunitResource(); + + @Rule public final LogCapturing logCapturing = new LogCapturing(); + + @Test + public void testSomething() { + ActorRef pinger = testKit.spawn(echoActor(), "ping"); + TestProbe probe = testKit.createTestProbe(); + pinger.tell(new Ping("hello", probe.ref())); + probe.expectMessage(new Pong("hello")); + } +} +// #log-capturing diff --git a/akka-actor-testkit-typed/src/test/resources/logback-test.xml b/akka-actor-testkit-typed/src/test/resources/logback-test.xml index e90cc999d2..db91164e39 100644 --- a/akka-actor-testkit-typed/src/test/resources/logback-test.xml +++ b/akka-actor-testkit-typed/src/test/resources/logback-test.xml @@ -4,9 +4,8 @@ - - DEBUG - DENY + + INFO %date{ISO8601} %-5level %logger %X{akkaSource} %X{sourceThread} - %msg%n diff --git a/akka-actor-testkit-typed/src/test/scala/docs/akka/actor/testkit/typed/scaladsl/ScalaTestIntegrationExampleSpec.scala b/akka-actor-testkit-typed/src/test/scala/docs/akka/actor/testkit/typed/scaladsl/ScalaTestIntegrationExampleSpec.scala index 36a166c516..e3db53ebd0 100644 --- a/akka-actor-testkit-typed/src/test/scala/docs/akka/actor/testkit/typed/scaladsl/ScalaTestIntegrationExampleSpec.scala +++ b/akka-actor-testkit-typed/src/test/scala/docs/akka/actor/testkit/typed/scaladsl/ScalaTestIntegrationExampleSpec.scala @@ -7,11 +7,15 @@ package docs.akka.actor.testkit.typed.scaladsl import com.github.ghik.silencer.silent import docs.akka.actor.testkit.typed.scaladsl.AsyncTestingExampleSpec.{ echoActor, Ping, Pong } +//#log-capturing +import akka.actor.testkit.typed.scaladsl.LogCapturing //#scalatest-integration import akka.actor.testkit.typed.scaladsl.ScalaTestWithActorTestKit import org.scalatest.WordSpecLike //#scalatest-integration +//#log-capturing + @silent //#scalatest-integration class ScalaTestIntegrationExampleSpec extends ScalaTestWithActorTestKit with WordSpecLike { @@ -26,3 +30,17 @@ class ScalaTestIntegrationExampleSpec extends ScalaTestWithActorTestKit with Wor } } //#scalatest-integration + +//#log-capturing +class LogCapturingExampleSpec extends ScalaTestWithActorTestKit with WordSpecLike with LogCapturing { + + "Something" must { + "behave correctly" in { + val pinger = testKit.spawn(echoActor, "ping") + val probe = testKit.createTestProbe[Pong]() + pinger ! Ping("hello", probe.ref) + probe.expectMessage(Pong("hello")) + } + } +} +//#log-capturing diff --git a/akka-actor-typed-tests/src/test/java/jdocs/akka/typed/LoggingDocExamples.java b/akka-actor-typed-tests/src/test/java/jdocs/akka/typed/LoggingDocExamples.java new file mode 100644 index 0000000000..a449d28d69 --- /dev/null +++ b/akka-actor-typed-tests/src/test/java/jdocs/akka/typed/LoggingDocExamples.java @@ -0,0 +1,191 @@ +/* + * Copyright (C) 2019 Lightbend Inc. + */ + +package jdocs.akka.typed; + +import java.util.HashMap; +import java.util.Map; +import java.util.concurrent.CompletableFuture; + +import akka.actor.typed.ActorRef; +import akka.actor.typed.ActorSystem; +import akka.actor.typed.Behavior; +import akka.actor.typed.javadsl.AbstractBehavior; +import akka.actor.typed.javadsl.ActorContext; +import akka.actor.typed.javadsl.Behaviors; +import akka.actor.typed.javadsl.Receive; +import org.slf4j.Logger; +import org.slf4j.LoggerFactory; + +// #logMessages +import akka.actor.typed.LogOptions; +import org.slf4j.event.Level; + +// #logMessages + +// #test-logging +import akka.actor.testkit.typed.javadsl.LoggingEventFilter; + +// #test-logging + +public interface LoggingDocExamples { + + // #context-log + public class MyLoggingBehavior extends AbstractBehavior { + + public static Behavior create() { + return Behaviors.setup(MyLoggingBehavior::new); + } + + private final ActorContext context; + + private MyLoggingBehavior(ActorContext context) { + this.context = context; + } + + @Override + public Receive createReceive() { + return newReceiveBuilder().onMessage(String.class, this::onReceive).build(); + } + + private Behavior onReceive(String message) { + context.getLog().info("Received message: {}", message); + return this; + } + } + // #context-log + + // #logger-name + public class BackendManager extends AbstractBehavior { + + public static Behavior create() { + return Behaviors.setup( + context -> { + context.setLoggerName(BackendManager.class); + context.getLog().info("Starting up"); + return new BackendManager(context); + }); + } + + private final ActorContext context; + + private BackendManager(ActorContext context) { + this.context = context; + } + + @Override + public Receive createReceive() { + return newReceiveBuilder().onMessage(String.class, this::onReceive).build(); + } + + private Behavior onReceive(String message) { + context.getLog().debug("Received message: {}", message); + return this; + } + } + // #logger-name + + // #logger-factory + class BackendTask { + private final Logger log = LoggerFactory.getLogger(getClass()); + + void run() { + CompletableFuture task = + CompletableFuture.supplyAsync( + () -> { + // some work + return "result"; + }); + task.whenComplete( + (result, exc) -> { + if (exc == null) log.error("Task failed", exc); + else log.info("Task completed: {}", result); + }); + } + } + // #logger-factory + + static void logMessages() { + // #logMessages + Behaviors.logMessages(LogOptions.create().withLevel(Level.TRACE), BackendManager.create()); + // #logMessages + } + + public class BackendManager2 extends AbstractBehavior { + + interface Command { + String identifier(); + } + + public static Behavior create() { + return Behaviors.empty(); + } + + @Override + public Receive createReceive() { + return newReceiveBuilder().build(); + } + } + + static void withMdc() { + ActorSystem system = ActorSystem.create(Behaviors.empty(), "notUsed"); + + // #withMdc + Map staticMdc = new HashMap<>(); + staticMdc.put("startTime", String.valueOf(system.startTime())); + + Behaviors.withMdc( + BackendManager2.Command.class, + staticMdc, + message -> { + Map msgMdc = new HashMap<>(); + msgMdc.put("identifier", message.identifier()); + msgMdc.put("upTime", String.valueOf(system.uptime())); + return msgMdc; + }, + BackendManager2.create()); + // #withMdc + } + + static class Message { + final String s; + + public Message(String s) { + this.s = s; + } + } + + static void logging() { + ActorSystem system = ActorSystem.create(Behaviors.empty(), "notUsed"); + ActorRef ref = null; + + // #test-logging + LoggingEventFilter.info("Received message") + .intercept( + system, + () -> { + ref.tell(new Message("hello")); + return null; + }); + // #test-logging + + // #test-logging-criteria + LoggingEventFilter.error(IllegalArgumentException.class) + .withMessageRegex(".*was rejected.*expecting ascii input.*") + .withCustom( + event -> + event.getMarker().isPresent() + && event.getMarker().get().getName().equals("validation")) + .withOccurrences(2) + .intercept( + system, + () -> { + ref.tell(new Message("hellö")); + ref.tell(new Message("hejdå")); + return null; + }); + // #test-logging-criteria + + } +} diff --git a/akka-actor-typed-tests/src/test/resources/logback-doc-dev.xml b/akka-actor-typed-tests/src/test/resources/logback-doc-dev.xml new file mode 100644 index 0000000000..35ff80c571 --- /dev/null +++ b/akka-actor-typed-tests/src/test/resources/logback-doc-dev.xml @@ -0,0 +1,30 @@ + + + + + + INFO + + + [%date{ISO8601}] [%-5level] [%logger] [%thread] [%X{akkaSource}] - %msg%n + + + + + target/myapp-dev.log + + [%date{ISO8601}] [%-5level] [%logger] [%thread] [%X{akkaSource}] - %msg%n + + + + + 1024 + true + + + + + + + + diff --git a/akka-actor-typed-tests/src/test/resources/logback-doc-prod.xml b/akka-actor-typed-tests/src/test/resources/logback-doc-prod.xml new file mode 100644 index 0000000000..e09421d149 --- /dev/null +++ b/akka-actor-typed-tests/src/test/resources/logback-doc-prod.xml @@ -0,0 +1,24 @@ + + + + + myapp.log + false + + myapp_%d{yyyy-MM-dd}.log + + + [%date{ISO8601}] [%-5level] [%logger] [%thread] [%X{akkaSource}] - %msg%n + + + + + 1024 + true + + + + + + + diff --git a/akka-actor-typed-tests/src/test/resources/logback-doc-test.xml b/akka-actor-typed-tests/src/test/resources/logback-doc-test.xml new file mode 100644 index 0000000000..c0d4c1b699 --- /dev/null +++ b/akka-actor-typed-tests/src/test/resources/logback-doc-test.xml @@ -0,0 +1,32 @@ + + + + + + INFO + + + [%date{ISO8601}] [%-5level] [%logger] [%thread] [%X{akkaSource}] - %msg%n + + + + + + + + + + + + + + + diff --git a/akka-actor-typed-tests/src/test/resources/logback-test.xml b/akka-actor-typed-tests/src/test/resources/logback-test.xml index 9e4d05a8dd..d492d46ed9 100644 --- a/akka-actor-typed-tests/src/test/resources/logback-test.xml +++ b/akka-actor-typed-tests/src/test/resources/logback-test.xml @@ -4,9 +4,8 @@ - - DEBUG - DENY + + INFO %date{ISO8601} %-5level %logger %X{akkaSource} %X{sourceThread} - %msg%n diff --git a/akka-actor-typed-tests/src/test/scala/docs/akka/typed/LoggingDocExamples.scala b/akka-actor-typed-tests/src/test/scala/docs/akka/typed/LoggingDocExamples.scala new file mode 100644 index 0000000000..bca4ec8a42 --- /dev/null +++ b/akka-actor-typed-tests/src/test/scala/docs/akka/typed/LoggingDocExamples.scala @@ -0,0 +1,144 @@ +/* + * Copyright (C) 2019 Lightbend Inc. + */ + +package docs.akka.typed + +import scala.concurrent.ExecutionContext.Implicits.global +import scala.concurrent.Future +import scala.util.Failure +import scala.util.Success + +import akka.actor.typed.ActorRef +import akka.actor.typed.ActorSystem +import akka.actor.typed.Behavior +import akka.actor.typed.scaladsl.Behaviors +import org.slf4j.LoggerFactory + +object LoggingDocExamples { + + object BackendManager { + sealed trait Command { + def identifier: String + } + def apply(): Behavior[Command] = Behaviors.empty + } + + def howToUse(): Unit = { + + //#context-log + Behaviors.receive[String] { (context, message) => + context.log.info("Received message: {}", message) + Behaviors.same + } + //#context-log + + //#logger-name + Behaviors.setup[String] { context => + context.setLoggerName("com.myservice.BackendManager") + context.log.info("Starting up") + + Behaviors.receiveMessage { message => + context.log.debug("Received message: {}", message) + Behaviors.same + } + } + //#logger-name + + //#logger-factory + val log = LoggerFactory.getLogger("com.myservice.BackendTask") + + Future { + // some work + "result" + }.onComplete { + case Success(result) => log.info("Task completed: {}", result) + case Failure(exc) => log.error("Task failed", exc) + } + //#logger-factory + + } + + def placeholders(): Unit = { + //#info2 + import akka.actor.typed.scaladsl.LoggerOps + + Behaviors.receive[String] { (context, message) => + context.log.info2("{} received message: {}", context.self.path.name, message) + Behaviors.same + } + //#info2 + + //#infoN + import akka.actor.typed.scaladsl.LoggerOps + + Behaviors.receive[String] { (context, message) => + context.log.infoN( + "{} received message of size {} starting with: {}", + context.self.path.name, + message.length, + message.take(10)) + Behaviors.same + } + //#infoN + + } + + def logMessages(): Unit = { + //#logMessages + import akka.actor.typed.LogOptions + import org.slf4j.event.Level + + Behaviors.logMessages(LogOptions().withLevel(Level.TRACE), BackendManager()) + //#logMessages + } + + def withMdc(): Unit = { + val system: ActorSystem[_] = ??? + + //#withMdc + val staticMdc = Map("startTime" -> system.startTime.toString) + Behaviors.withMdc[BackendManager.Command]( + staticMdc, + mdcForMessage = + (msg: BackendManager.Command) => Map("identifier" -> msg.identifier, "upTime" -> system.uptime.toString)) { + BackendManager() + } + //#withMdc + } + + def logging(): Unit = { + implicit val system: ActorSystem[_] = ??? + final case class Message(s: String) + val ref: ActorRef[Message] = ??? + + //#test-logging + import akka.actor.testkit.typed.scaladsl.LoggingEventFilter + + // implicit ActorSystem is needed, but that is given by ScalaTestWithActorTestKit + //implicit val system: ActorSystem[_] + + LoggingEventFilter.info("Received message").intercept { + ref ! Message("hello") + } + //#test-logging + + //#test-logging-criteria + LoggingEventFilter + .error[IllegalArgumentException] + .withMessageRegex(".*was rejected.*expecting ascii input.*") + .withCustom { event => + event.marker match { + case Some(m) => m.getName == "validation" + case None => false + } + } + .withOccurrences(2) + .intercept { + ref ! Message("hellö") + ref ! Message("hejdå") + } + //#test-logging-criteria + } + +} diff --git a/akka-actor-typed-tests/src/test/scala/docs/akka/typed/myapp/package.scala b/akka-actor-typed-tests/src/test/scala/docs/akka/typed/myapp/package.scala new file mode 100644 index 0000000000..5190c3ef9b --- /dev/null +++ b/akka-actor-typed-tests/src/test/scala/docs/akka/typed/myapp/package.scala @@ -0,0 +1,18 @@ +/* + * Copyright (C) 2019 Lightbend Inc. + */ + +package docs.akka.typed + +//#loggerops-package-implicit +import scala.language.implicitConversions +import akka.actor.typed.scaladsl.LoggerOps +import org.slf4j.Logger + +package object myapp { + + implicit def loggerOps(logger: Logger): LoggerOps = + LoggerOps(logger) + +} +//#loggerops-package-implicit diff --git a/akka-bench-jmh-typed/src/main/resources/logback-test.xml b/akka-bench-jmh-typed/src/main/resources/logback-test.xml index 10814d5a0c..ab25b19f2e 100644 --- a/akka-bench-jmh-typed/src/main/resources/logback-test.xml +++ b/akka-bench-jmh-typed/src/main/resources/logback-test.xml @@ -4,9 +4,8 @@ - - DEBUG - DENY + + INFO %date{ISO8601} %-5level %logger %X{akkaSource} %X{sourceThread} - %msg%n diff --git a/akka-cluster-sharding-typed/src/test/resources/logback-test.xml b/akka-cluster-sharding-typed/src/test/resources/logback-test.xml index 5e80aa8ee0..254c2d1af2 100644 --- a/akka-cluster-sharding-typed/src/test/resources/logback-test.xml +++ b/akka-cluster-sharding-typed/src/test/resources/logback-test.xml @@ -4,9 +4,8 @@ - - DEBUG - DENY + + INFO %date{ISO8601} %-5level %logger %X{akkaSource} %X{sourceThread} { "persistenceId": "%X{persistenceId}", "persistencePhase": "%X{persistencePhase}" } - %msg%n diff --git a/akka-cluster-typed/src/test/resources/logback-test.xml b/akka-cluster-typed/src/test/resources/logback-test.xml index f7f657efd7..7c037e2347 100644 --- a/akka-cluster-typed/src/test/resources/logback-test.xml +++ b/akka-cluster-typed/src/test/resources/logback-test.xml @@ -4,9 +4,8 @@ - - DEBUG - DENY + + INFO %date{ISO8601} %-5level %logger %X{akkaSource} %X{sourceThread} - %msg%n diff --git a/akka-docs/src/main/paradox/index-utilities.md b/akka-docs/src/main/paradox/index-utilities.md index 3ea155cee4..3ddaa310ee 100644 --- a/akka-docs/src/main/paradox/index-utilities.md +++ b/akka-docs/src/main/paradox/index-utilities.md @@ -4,7 +4,7 @@ @@@ index -* [logging](logging.md) +* [logging](typed/logging.md) * [common/circuitbreaker](common/circuitbreaker.md) @@@ diff --git a/akka-docs/src/main/paradox/logging.md b/akka-docs/src/main/paradox/logging.md index 683415975d..bf1fb6f660 100644 --- a/akka-docs/src/main/paradox/logging.md +++ b/akka-docs/src/main/paradox/logging.md @@ -1,4 +1,7 @@ -# Logging +# Classic Logging + +@@include[includes.md](includes.md) { #actor-api } +For the new API see @ref[Logging](typed/logging.md). ## Dependency @@ -336,7 +339,7 @@ It has a single dependency: the slf4j-api jar. In your runtime, you also need a version="$akka.version$" group2="ch.qos.logback" artifact2="logback-classic" - version2="1.2.3" + version2="$logback_version$" } You need to enable the Slf4jLogger in the `loggers` element in @@ -352,6 +355,9 @@ If you set the `loglevel` to a higher level than "DEBUG", any DEBUG events will out already at the source and will never reach the logging backend, regardless of how the backend is configured. +You can enable `DEBUG` level for `akka.loglevel` and control the actual level in the SLF4J backend +without any significant overhead, also for production. + @@@ ```ruby @@ -397,9 +403,31 @@ while the underlying infrastructure writes the log statements. This can be avoided by configuring the logging implementation to use a non-blocking appender. Logback provides [AsyncAppender](http://logback.qos.ch/manual/appenders.html#AsyncAppender) -that does this. It also contains a feature which will drop `INFO` and `DEBUG` messages if the logging +that does this. + +### Logback configuration + +Logback has flexible configuration options and details can be found in the +[Logback manual](https://logback.qos.ch/manual/configuration.html) and other external resources. + +One part that is important to highlight is the importance of configuring an [AsyncAppender](http://logback.qos.ch/manual/appenders.html#AsyncAppender), +because it offloads rendering of logging events to a background thread, increasing performance. It doesn't block +the threads of the `ActorSystem` while the underlying infrastructure writes the log messages to disk or other configured +destination. It also contains a feature which will drop `INFO` and `DEBUG` messages if the logging load is high. +A starting point for configuration of `logback.xml` for production: + +@@snip [logback.xml](/akka-actor-typed-tests/src/test/resources/logback-doc-prod.xml) + +For development you might want to log to standard out, but also have all debug level logging to file, like +in this example: + +@@snip [logback.xml](/akka-actor-typed-tests/src/test/resources/logback-doc-dev.xml) + +Place the `logback.xml` file in `src/main/resources/logback.xml`. For tests you can define different +logging configuration in `src/test/resources/logback-test.xml`. + ### Logging Thread, Akka Source and Actor System in MDC Since the logging is done asynchronously the thread in which the logging was performed is captured in @@ -458,7 +486,7 @@ If you want to more accurately output the timestamp, use the MDC attribute `akka ``` - %X{akkaTimestamp} %-5level %logger{36} %X{akkaSource} - %msg%n + %X{akkaTimestamp} %-5level %logger{36} %X{akkaTimestamp} - %msg%n ``` diff --git a/akka-docs/src/main/paradox/typed/logging.md b/akka-docs/src/main/paradox/typed/logging.md new file mode 100644 index 0000000000..4cd5059a22 --- /dev/null +++ b/akka-docs/src/main/paradox/typed/logging.md @@ -0,0 +1,393 @@ +# Logging + +## Dependency + +To use Logging, you must at least use the Akka actors dependency in your project, and configure logging +via the SLF4J backend, such as Logback configuration. + +@@dependency[sbt,Maven,Gradle] { + group="com.typesafe.akka" + artifact="akka-actor-typed_$scala.binary_version$" + version="$akka.version$" +} + +## Introduction + +[SLF4J](http://www.slf4j.org/) is used for logging and Akka provides access to an `org.slf4j.Logger` for a specific +actor via the `ActorContext`. You may also retrieve a `Logger` with the ordinary `org.slf4j.LoggerFactory`. + +To ensure that logging has minimal performance impact it's important that you configure an +asynchronous appender for the SLF4J backend. Logging generally means IO and locks, +which can slow down the operations of your code if it was performed synchronously. + +## How to log + +The `ActorContext` provides access to an `org.slf4j.Logger` for a specific actor. + +Scala +: @@snip [LoggingDocExamples.scala](/akka-actor-typed-tests/src/test/scala/docs/akka/typed/LoggingDocExamples.scala) { #context-log } + +Java +: @@snip [LoggingDocExamples.java](/akka-actor-typed-tests/src/test/java/jdocs/akka/typed/LoggingDocExamples.java) { #context-log } + +The `Logger` via the `ActorContext` will automatically have a name that corresponds to the `Behavior` of the +actor when the log is accessed the first time. The class name when using `AbstractBehavior` or the class @scala[or object] +name where the `Behavior` is defined when using the functional style. You can set a custom logger name +with the `setLoggerName` of the `ActorContext`. + +Scala +: @@snip [LoggingDocExamples.scala](/akka-actor-typed-tests/src/test/scala/docs/akka/typed/LoggingDocExamples.scala) { #logger-name } + +Java +: @@snip [LoggingDocExamples.java](/akka-actor-typed-tests/src/test/java/jdocs/akka/typed/LoggingDocExamples.java) { #logger-name } + +The convention is to use logger names like fully qualified class names. The parameter to `setLoggerName` +can be a `String` or a `Class`, where the latter is convenience for the class name. + +When logging via the `ActorContext` the path of the actor will automatically be added as `akkaSource` +Mapped Diagnostic Context (MDC) value. MDC is typically implemented with a `ThreadLocal` by the SLF4J backend. +To reduce performance impact this MDC value is set when you access the @scala[`log`]@java[`getLog`] method so +you shouldn't cache the returned `Logger` in your own field. That is handled by `ActorContext` and retrieving +the `Logger` repeatedly with the @scala[`log`]@java[`getLog`] method has low overhead. +The MDC is cleared automatically after processing of current message has finished. + +@@@ note + +The `Logger` is thread-safe but the @scala[`log`]@java[`getLog`] method in `ActorContext` is not +thread-safe and should not be accessed from threads other than the ordinary actor message processing +thread, such as @scala[`Future`]@java[`CompletionStage`] callbacks. + +@@@ + +It's also perfectly fine to use a `Logger` retrieved via `org.slf4j.LoggerFactory`, but then the logging +events will not include the `akkaSource` MDC value. This is the recommend way when logging outside +of an actor, including logging from @scala[`Future`]@java[`CompletionStage`] callbacks. + +Scala +: @@snip [LoggingDocExamples.scala](/akka-actor-typed-tests/src/test/scala/docs/akka/typed/LoggingDocExamples.scala) { #logger-factory } + +Java +: @@snip [LoggingDocExamples.java](/akka-actor-typed-tests/src/test/java/jdocs/akka/typed/LoggingDocExamples.java) { #logger-factory } + +### Placeholder arguments + +The log message may contain argument placeholders `{}`, which will be substituted if the log level is enabled. +Compared to constructing a full string for the log message this has the advantage of avoiding superfluous +string concatenation and object allocations when the log level is disabled. Some logging backends +may also use these message templates before argument substitution to group and filter logging events. + +It can be good to know that 3 or more arguments will result in the relatively small cost of allocating +an array (vararg parameter) also when the log level is disabled. The methods with 1 or 2 arguments +don't allocate the vararg array. + +@@@ div { .group-scala } + +When using the methods for 2 argument placeholders the compiler will often not be able to select the +right method and report compiler error "ambiguous reference to overloaded definition". To work around this +problem you can use the `trace2`, `debug2`, `info2`, `warn2` or `error2` extension methods that are added +by `import akka.actor.typed.scaladsl.LoggerOps` or `import akka.actor.typed.scaladsl._`. + +Scala +: @@snip [LoggingDocExamples.scala](/akka-actor-typed-tests/src/test/scala/docs/akka/typed/LoggingDocExamples.scala) { #info2 } + +When using the methods for 3 or more argument placeholders, the compiler will not be able to convert +the method parameters to the vararg array when they contain primitive values such as `Int`, +and report compiler error "overloaded method value info with alternatives". +To work around this problem you can use the `traceN`, `debugN`, `infoN`, `warnN` or `errorN` extension +methods that are added by the same `LoggerOps` import. + +Scala +: @@snip [LoggingDocExamples.scala](/akka-actor-typed-tests/src/test/scala/docs/akka/typed/LoggingDocExamples.scala) { #infoN } + +If you find it tedious to add the import of `LoggerOps` at many places you can make those additional methods +available with a single implicit conversion placed in a root package object of your code: + +Scala +: @@snip [package.scala](/akka-actor-typed-tests/src/test/scala/docs/akka/typed/myapp/package.scala) { #loggerops-package-implicit } + +@@@ + +### Behaviors.logMessages + +If you want very detailed logging of messages and signals you can decorate a `Behavior` +with `Behaviors.logMessages`. + +Scala +: @@snip [LoggingDocExamples.scala](/akka-actor-typed-tests/src/test/scala/docs/akka/typed/LoggingDocExamples.scala) { #logMessages } + +Java +: @@snip [LoggingDocExamples.java](/akka-actor-typed-tests/src/test/java/jdocs/akka/typed/LoggingDocExamples.java) { #logMessages } + + +## Behaviors.withMdc + +To include [MDC](http://logback.qos.ch/manual/mdc.html) attributes in logging events from an actor +you can decorate a `Behavior` with `Behaviors.withMdc` or use the `org.slf4j.MDC` API directly. + +The `Behaviors.withMdc` decorator has two parts. A static `Map` of MDC attributes that are not changed, +and a dynamic `Map` that can be constructed for each message. + +Scala +: @@snip [LoggingDocExamples.scala](/akka-actor-typed-tests/src/test/scala/docs/akka/typed/LoggingDocExamples.scala) { #withMdc } + +Java +: @@snip [LoggingDocExamples.java](/akka-actor-typed-tests/src/test/java/jdocs/akka/typed/LoggingDocExamples.java) { #withMdc } + +If you use the MDC API directly, be aware of that MDC is typically implemented with a `ThreadLocal` by the SLF4J backend. +Akka clears the MDC if logging is performed via the @scala[`log`]@java[`getLog`] of the `ActorContext` the MDC is cleared +automatically after processing of current message has finished, but only if you accessed @scala[`log`]@java[`getLog`]. +The entire MDC is cleared, including attributes that you add yourself to the MDC. +MDC is not cleared automatically if you use a `Logger` via `LoggerFactory` or not touch @scala[`log`]@java[`getLog`] +in the `ActorContext`. + +## SLF4J backend + +To ensure that logging has minimal performance impact it's important that you configure an +asynchronous appender for the SLF4J backend. Logging generally means IO and locks, +which can slow down the operations of your code if it was performed synchronously. + +@@@ warning + +For production the SLF4J backend should be configured with an asynchronous appender as described here. +Otherwise there is a risk of reduced performance and thread starvation problems of the dispatchers +that are running actors and other tasks. + +@@@ + +### Logback + +`akka-actor-typed` includes a dependency to the `slf4j-api`. In your runtime, you also need a SLF4J backend. +We recommend [Logback](http://logback.qos.ch/): + +@@dependency[sbt,Maven,Gradle] { + group="ch.qos.logback" + artifact="logback-classic" + version="$logback_version$" +} + +Logback has flexible configuration options and details can be found in the +[Logback manual](https://logback.qos.ch/manual/configuration.html) and other external resources. + +One part that is important to highlight is the importance of configuring an [AsyncAppender](http://logback.qos.ch/manual/appenders.html#AsyncAppender), +because it offloads rendering of logging events to a background thread, increasing performance. It doesn't block +the threads of the `ActorSystem` while the underlying infrastructure writes the log messages to disk or other configured +destination. It also contains a feature which will drop `INFO` and `DEBUG` messages if the logging +load is high. + +A starting point for configuration of `logback.xml` for production: + +@@snip [logback.xml](/akka-actor-typed-tests/src/test/resources/logback-doc-prod.xml) + +For development you might want to log to standard out, but also have all debug level logging to file, like +in this example: + +@@snip [logback.xml](/akka-actor-typed-tests/src/test/resources/logback-doc-dev.xml) + +Place the `logback.xml` file in `src/main/resources/logback.xml`. For tests you can define different +logging configuration in `src/test/resources/logback-test.xml`. + +#### MDC values + +When logging via the @scala[`log`]@java[`getLog`] of the `ActorContext` as described in +@ref:[How to log](#how-to-log) Akka captures the actor's path and includes that in MDC with +attribute name `akkaSource`. + +This can be included in the log output with `%X{akkaSource}` specifier within the pattern layout configuration: + +``` + + %date{ISO8601} %-5level %logger{36} %X{akkaSource} - %msg%n + +``` + +## Internal logging by Akka + +### Event bus + +For historical reasons logging by the Akka internals and by classic actors are performed asynchronously +through an event bus. Such log events are processed by an event handler actor, which then emits them to +SLF4J or directly to standard out. + +When `akka-actor-typed` is on the classpath this event handler actor will emit the events to SLF4J. +The `akka.event.slf4j.Slf4jLogger` and `akka.event.slf4j.Slf4jLoggingFilter` are enabled automatically +without additional configuration. This can be disabled by `akka.use-slf4j=off` configuration property. + +In other words, you don't have to do anything for the Akka internal logging to end up in your configured +SLF4J backend. + +### Log level + +Ultimately the log level defined in the SLF4J backend is used. For the Akka internal logging it will +also check the level defined by the SLF4J backend before constructing the final log message and +emitting it to the event bus. + +However, there is an additional `akka.loglevel` configuration property that defines if logging events +with lower log level should be discarded immediately without consulting the SLF4J backend. By default +this is at `INFO` level, which means that `DEBUG` level logging from the Akka internals will not +reach the SLF4J backend even if `DEBUG` is enabled in the backend. + +You can enable `DEBUG` level for `akka.loglevel` and control the actual level in the SLF4j backend +without any significant overhead, also for production. + +``` +akka.loglevel = "DEBUG" +``` + +To turn off all Akka internal logging (not recommended) you can configure the log levels to be +`OFF` like this. + +``` +akka { + stdout-loglevel = "OFF" + loglevel = "OFF" +} +``` + +The `stdout-loglevel` is only in effect during system startup and shutdown, and setting +it to `OFF` as well, ensures that nothing gets logged during system startup or shutdown. + +### Logging to stdout during startup and shutdown + +When the actor system is starting up and shutting down the configured `loggers` are not used. +Instead log messages are printed to stdout (System.out). The default log level for this +stdout logger is `WARNING` and it can be silenced completely by setting +`akka.stdout-loglevel=OFF`. + +### Logging of Dead Letters + +By default messages sent to dead letters are logged at info level. Existence of dead letters +does not necessarily indicate a problem, but they are logged by default for the sake of caution. +After a few messages this logging is turned off, to avoid flooding the logs. +You can disable this logging completely or adjust how many dead letters are +logged. During system shutdown it is likely that you see dead letters, since pending +messages in the actor mailboxes are sent to dead letters. You can also disable logging +of dead letters during shutdown. + +``` +akka { + log-dead-letters = 10 + log-dead-letters-during-shutdown = on +} +``` + +To customize the logging further or take other actions for dead letters you can subscribe +to the @ref:[Event Stream](../event-bus.md#event-stream). + +### Auxiliary logging options + +Akka has a few configuration options for very low level debugging. These make more sense in development than in production. + +You almost definitely need to have logging set to DEBUG to use any of the options below: + +``` +akka { + loglevel = "DEBUG" +} +``` + +This config option is very good if you want to know what config settings are loaded by Akka: + +``` +akka { + # Log the complete configuration at INFO level when the actor system is started. + # This is useful when you are uncertain of what configuration is used. + log-config-on-start = on +} +``` + +If you want unhandled messages logged at DEBUG: + +``` +akka { + actor { + debug { + # enable DEBUG logging of unhandled messages + unhandled = on + } + } +} +``` + +If you want to monitor subscriptions (subscribe/unsubscribe) on the ActorSystem.eventStream: + +``` +akka { + actor { + debug { + # enable DEBUG logging of subscription changes on the eventStream + event-stream = on + } + } +} +``` + + +### Auxiliary remote logging options + +If you want to see all messages that are sent through remoting at DEBUG log level, use the following config option. +Note that this logs the messages as they are sent by the transport layer, not by an actor. + +``` +akka.remote.artery { + # If this is "on", Akka will log all outbound messages at DEBUG level, + # if off then they are not logged + log-sent-messages = on +} +``` + +If you want to see all messages that are received through remoting at DEBUG log level, use the following config option. +Note that this logs the messages as they are received by the transport layer, not by an actor. + +``` +akka.remote.artery { + # If this is "on", Akka will log all inbound messages at DEBUG level, + # if off then they are not logged + log-received-messages = on +} +``` + +### MDC values from Akka internal logging + +Since the logging is done asynchronously the thread in which the logging was performed is captured in +MDC with attribute name `sourceThread`. +With Logback the thread name is available with `%X{sourceThread}` specifier within the pattern layout configuration: + +``` + + %date{ISO8601} %-5level %logger{36} %X{sourceThread} - %msg%n + +``` + +The path of the actor in which the logging was performed is available in the MDC with attribute name `akkaSource`, +With Logback the actor path is available with `%X{akkaSource}` specifier within the pattern layout configuration: +``` + + %date{ISO8601} %-5level %logger{36} %X{akkaSource} - %msg%n + +``` + +The actor system in which the logging was performed is available in the MDC with attribute name `sourceActorSystem`, +but that is typically also included in the `akkaSource` attribute. +With Logback the ActorSystem name is available with `%X{sourceActorSystem}` specifier within the pattern layout configuration: + +``` + + %date{ISO8601} %-5level %logger{36} %X{sourceActorSystem} - %msg%n + +``` + +Akka's internal logging is asynchronous which means that the timestamp of a log entry is taken from +when the underlying logger implementation is called, which can be surprising at first. +If you want to more accurately output the timestamp, use the MDC attribute `akkaTimestamp`. +With Logback the timestamp is available with `%X{akkaTimestamp}` specifier within the pattern layout configuration: + +``` + + %X{akkaTimestamp} %-5level %logger{36} %X{akkaTimestamp} - %msg%n + +``` + + +## Logging in tests + +Testing utilities are described in @ref:[Testing](testing.md#test-of-logging). diff --git a/akka-docs/src/main/paradox/typed/testing.md b/akka-docs/src/main/paradox/typed/testing.md index e6daca4205..1672664e96 100644 --- a/akka-docs/src/main/paradox/typed/testing.md +++ b/akka-docs/src/main/paradox/typed/testing.md @@ -225,6 +225,65 @@ Java : @@snip [ManualTimerExampleTest.scala](/akka-actor-testkit-typed/src/test/java/jdocs/akka/actor/testkit/typed/javadsl/ManualTimerExampleTest.java) { #manual-scheduling-simple } +### Test of logging + +To verify that certain @ref:[logging](logging.md) events are emitted there is a utility called `LoggingEventFilter`. +You define a criteria of the expected logging events and it will assert that the given number of occurrences +of matching logging events are emitted within a block of code. + +@@@ note + +The `LoggingEventFilter` implementation @ref:[requires Logback dependency](logging.md#logback). + +@@@ + +For example, a criteria that verifies that an `INFO` level event with a message containing "Received message" is logged: + +Scala +: @@snip [LoggingDocExamples.scala](/akka-actor-typed-tests/src/test/scala/docs/akka/typed/LoggingDocExamples.scala) { #test-logging } + +Java +: @@snip [LoggingDocExamples.java](/akka-actor-typed-tests/src/test/java/jdocs/akka/typed/LoggingDocExamples.java) { #test-logging } + +More advanced criteria can be built by chaining conditions that all must be satisfied for a matching event. + +Scala +: @@snip [LoggingDocExamples.scala](/akka-actor-typed-tests/src/test/scala/docs/akka/typed/LoggingDocExamples.scala) { #test-logging-criteria } + +Java +: @@snip [LoggingDocExamples.java](/akka-actor-typed-tests/src/test/java/jdocs/akka/typed/LoggingDocExamples.java) { #test-logging-criteria } + +See @apidoc[typed.*.LoggingEventFilter] for more details. + +### Silence logging output from tests + +When running tests, it's typically preferred to have the output to standard out, together with the output from the +testing framework (@scala[ScalaTest]@java[JUnit]). On one hand you want the output to be clean without logging noise, +but on the other hand you want as much information as possible if there is a test failure (for example in CI builds). + +The Akka TestKit provides a `LogCapturing` utility to support this with ScalaTest or JUnit. It will buffer log events instead +of emitting them to the `ConsoleAppender` immediately (or whatever Logback appender that is configured). When +there is a test failure the buffered events are flushed to the target appenders, typically a `ConsoleAppender`. + +@@@ note + +The `LogCapturing` utility @ref:[requires Logback dependency](logging.md#logback). + +@@@ + +@scala[Mix `LogCapturing` trait into the ScalaTest]@java[Add a `LogCapturing` `@Rule` in the JUnit test] like this: + +Scala +: @@snip [ScalaTestIntegrationExampleSpec.scala](/akka-actor-testkit-typed/src/test/scala/docs/akka/actor/testkit/typed/scaladsl/ScalaTestIntegrationExampleSpec.scala) { #log-capturing } + +Java +: @@snip [LogCapturingExampleTest.java](/akka-actor-testkit-typed/src/test/java/jdocs/akka/actor/testkit/typed/javadsl/LogCapturingExampleTest.java) { #log-capturing } + +Then you also need to configure the `CapturingAppender` and `CapturingAppenderDelegate` in +`src/test/resources/logback-test.xml`: + +@@snip [logback-test.xml](/akka-actor-typed-tests/src/test/resources/logback-doc-test.xml) + ## Synchronous behavior testing The `BehaviorTestKit` provides a very nice way of unit testing a `Behavior` in a deterministic way, but it has diff --git a/akka-docs/src/test/resources/logback-test.xml b/akka-docs/src/test/resources/logback-test.xml index 1982b856a3..f877ccdf75 100644 --- a/akka-docs/src/test/resources/logback-test.xml +++ b/akka-docs/src/test/resources/logback-test.xml @@ -4,9 +4,8 @@ - - DEBUG - DENY + + INFO %date{ISO8601} %-5level %logger %X{akkaSource} %X{sourceThread} - %msg%n diff --git a/akka-persistence-typed/src/test/resources/logback-test.xml b/akka-persistence-typed/src/test/resources/logback-test.xml index 5e80aa8ee0..254c2d1af2 100644 --- a/akka-persistence-typed/src/test/resources/logback-test.xml +++ b/akka-persistence-typed/src/test/resources/logback-test.xml @@ -4,9 +4,8 @@ - - DEBUG - DENY + + INFO %date{ISO8601} %-5level %logger %X{akkaSource} %X{sourceThread} { "persistenceId": "%X{persistenceId}", "persistencePhase": "%X{persistencePhase}" } - %msg%n diff --git a/project/Dependencies.scala b/project/Dependencies.scala index aa2a39355b..70e9876069 100644 --- a/project/Dependencies.scala +++ b/project/Dependencies.scala @@ -24,6 +24,7 @@ object Dependencies { val jacksonVersion = "2.9.9" val jacksonDatabindVersion = "2.9.9.3" val protobufJavaVersion = "3.9.1" + val logbackVersion = "1.2.3" val scala212Version = "2.12.9" val scala213Version = "2.13.0" @@ -98,7 +99,7 @@ object Dependencies { val protobufRuntime = "com.google.protobuf" % "protobuf-java" % protobufJavaVersion - val logback = "ch.qos.logback" % "logback-classic" % "1.2.3" // EPL 1.0 + val logback = "ch.qos.logback" % "logback-classic" % logbackVersion // EPL 1.0 object Docs { val sprayJson = "io.spray" %% "spray-json" % "1.3.5" % "test" diff --git a/project/Paradox.scala b/project/Paradox.scala index 7f8dd05265..a5dbc0f5e3 100644 --- a/project/Paradox.scala +++ b/project/Paradox.scala @@ -39,7 +39,8 @@ object Paradox { "fiddle.code.base_dir" -> (sourceDirectory in Test).value.getAbsolutePath, "fiddle.akka.base_dir" -> (baseDirectory in ThisBuild).value.getAbsolutePath, "aeron_version" -> Dependencies.aeronVersion, - "netty_version" -> Dependencies.nettyVersion)) + "netty_version" -> Dependencies.nettyVersion, + "logback_version" -> Dependencies.logbackVersion)) val rootsSettings = Seq( paradoxRoots := List(