raboof/pekko
1
0
Fork 0
Code Issues Pull requests Projects Releases 6 Packages Wiki Activity Actions 10

Reference docs for SL4J logging in Typed, #27648 (#27696)

Browse source 
* 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 <will.sargent@gmail.com>
This commit is contained in:
Patrik Nordwall 2019-09-17 17:26:13 +02:00 • committed by GitHub
parent ea7704928b
commit 8cb2721c33
No known key found for this signature in database
GPG key ID: 4AEE18F83AFDEB23
22 changed files with 998 additions and 30 deletions
Download patch file Download diff file Expand all files Collapse all files

2
akka-docs/src/main/paradox/index-utilities.md
View file

@ -4,7 +4,7 @@
@@@ index
* [logging](logging.md)
* [logging](typed/logging.md)
* [common/circuitbreaker](common/circuitbreaker.md)
@@@

36
akka-docs/src/main/paradox/logging.md
View file

@ -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
```
<appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
<encoder>
<pattern>%X{akkaTimestamp} %-5level %logger{36} %X{akkaSource} - %msg%n</pattern>
<pattern>%X{akkaTimestamp} %-5level %logger{36} %X{akkaTimestamp} - %msg%n</pattern>
</encoder>
</appender>
```

393
akka-docs/src/main/paradox/typed/logging.md Normal file
View file

@ -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:
```
<encoder>
<pattern>%date{ISO8601} %-5level %logger{36} %X{akkaSource} - %msg%n</pattern>
</encoder>
```
## 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
}
}
}
```
<a id="logging-remote"></a>
### 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:
```
<encoder>
<pattern>%date{ISO8601} %-5level %logger{36} %X{sourceThread} - %msg%n</pattern>
</encoder>
```
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:
```
<encoder>
<pattern>%date{ISO8601} %-5level %logger{36} %X{akkaSource} - %msg%n</pattern>
</encoder>
```
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:
```
<encoder>
<pattern>%date{ISO8601} %-5level %logger{36} %X{sourceActorSystem} - %msg%n</pattern>
</encoder>
```
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:
```
<encoder>
<pattern>%X{akkaTimestamp} %-5level %logger{36} %X{akkaTimestamp} - %msg%n</pattern>
</encoder>
```
## Logging in tests
Testing utilities are described in @ref:[Testing](testing.md#test-of-logging).

59
akka-docs/src/main/paradox/typed/testing.md
View file

@ -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

5
akka-docs/src/test/resources/logback-test.xml
View file

@ -4,9 +4,8 @@
<statusListener class="ch.qos.logback.core.status.NopStatusListener" />
<appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
<filter class="ch.qos.logback.classic.filter.LevelFilter">
<level>DEBUG</level>
<onMatch>DENY</onMatch>
<filter class="ch.qos.logback.classic.filter.ThresholdFilter">
<level>INFO</level>
</filter>
<encoder>
<pattern>%date{ISO8601} %-5level %logger %X{akkaSource} %X{sourceThread} - %msg%n</pattern>