Merge pull request #28308 from akka/wip-mdc-logback-config-patriknw

use %mdc logback config to output all MDC entries
This commit is contained in:
Patrik Nordwall 2019-12-05 16:26:30 +01:00 committed by GitHub
commit 619a4494d5
No known key found for this signature in database
GPG key ID: 4AEE18F83AFDEB23
18 changed files with 119 additions and 118 deletions

View file

@ -8,7 +8,7 @@
<level>INFO</level>
</filter>
<encoder>
<pattern>%date{ISO8601} %-5level %logger %X{akkaSource} %X{sourceThread} - %msg%n</pattern>
<pattern>%date{ISO8601} %-5level %logger %marker - %msg {%mdc}%n</pattern>
</encoder>
</appender>

View file

@ -6,14 +6,14 @@
<level>INFO</level>
</filter>
<encoder>
<pattern>[%date{ISO8601}] [%level] [%logger] [%thread] [%X{akkaSource}] - %msg%n</pattern>
<pattern>[%date{ISO8601}] [%level] [%logger] [%marker] [%thread] - %msg {%mdc}%n</pattern>
</encoder>
</appender>
<appender name="FILE" class="ch.qos.logback.core.FileAppender">
<file>target/myapp-dev.log</file>
<encoder>
<pattern>[%date{ISO8601}] [%level] [%logger] [%thread] [%X{akkaSource}] - %msg%n</pattern>
<pattern>[%date{ISO8601}] [%level] [%logger] [%marker] [%thread] - %msg {%mdc}%n</pattern>
</encoder>
</appender>

View file

@ -8,7 +8,7 @@
<fileNamePattern>myapp_%d{yyyy-MM-dd}.log</fileNamePattern>
</rollingPolicy>
<encoder>
<pattern>[%date{ISO8601}] [%level] [%logger] [%thread] [%X{akkaSource}] - %msg%n</pattern>
<pattern>[%date{ISO8601}] [%level] [%logger] [%marker] [%thread] - %msg {%mdc}%n</pattern>
</encoder>
</appender>

View file

@ -6,7 +6,7 @@
<level>INFO</level>
</filter>
<encoder>
<pattern>[%date{ISO8601}] [%level] [%logger] [%thread] [%X{akkaSource}] - %msg%n</pattern>
<pattern>[%date{ISO8601}] [%level] [%logger] [%marker] [%thread] - %msg {%mdc}%n</pattern>
</encoder>
</appender>

View file

@ -8,7 +8,7 @@
<level>INFO</level>
</filter>
<encoder>
<pattern>%date{ISO8601} %-5level %logger %X{akkaSource} %X{sourceThread} - %msg%n</pattern>
<pattern>%date{ISO8601} %-5level %logger %marker - %msg {%mdc}%n</pattern>
</encoder>
</appender>

View file

@ -8,7 +8,7 @@
<level>INFO</level>
</filter>
<encoder>
<pattern>%date{ISO8601} %-5level %logger %X{akkaSource} %X{sourceThread} - %msg%n</pattern>
<pattern>%date{ISO8601} %-5level %logger %marker - %msg {%mdc}%n</pattern>
</encoder>
</appender>
<root level="DEBUG">

View file

@ -3,7 +3,7 @@
<!-- Copyright (C) 2009-2018 Lightbend Inc. <https://www.lightbend.com> -->
<variable name="pattern" value="%date{ISO8601} %-5level %logger %X{akkaSource} %X{sourceThread} - %msg%n" />
<variable name="pattern" value="%date{ISO8601} %-5level %logger %marker - %msg {%mdc}%n" />
<variable name="folder" value="${user.dir}/target/metrics" />

View file

@ -5,7 +5,7 @@
<appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
<encoder>
<pattern>%date{ISO8601} %-5level %logger %X{akkaSource} %X{sourceThread} - %msg%n</pattern>
<pattern>%date{ISO8601} %-5level %logger %marker - %msg {%mdc}%n</pattern>
</encoder>
</appender>

View file

@ -8,7 +8,7 @@
<level>INFO</level>
</filter>
<encoder>
<pattern>%date{ISO8601} %-5level %logger %X{akkaSource} %X{sourceThread} { "persistenceId": "%X{persistenceId}", "persistencePhase": "%X{persistencePhase}" } - %msg%n</pattern>
<pattern>%date{ISO8601} %-5level %logger %marker - %msg {%mdc}%n</pattern>
</encoder>
</appender>

View file

@ -5,7 +5,7 @@
<appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
<encoder>
<pattern>%date{ISO8601} %-5level %logger %X{akkaSource} %X{sourceThread} - %msg%n</pattern>
<pattern>%date{ISO8601} %-5level %logger %marker - %msg {%mdc}%n</pattern>
</encoder>
</appender>

View file

@ -8,7 +8,7 @@
<level>INFO</level>
</filter>
<encoder>
<pattern>%date{ISO8601} %-5level %logger %X{akkaSource} %X{sourceThread} - %msg%n</pattern>
<pattern>%date{ISO8601} %-5level %logger %marker - %msg {%mdc}%n</pattern>
</encoder>
</appender>

View file

@ -430,19 +430,27 @@ in this example:
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 properties can be included in the Logback output with for example `%X{akkaSource}` specifier within the
[pattern layout configuration](http://logback.qos.ch/manual/layouts.html#mdc):
```
<encoder>
<pattern>%date{ISO8601} %-5level %logger{36} %X{akkaSource} - %msg%n</pattern>
</encoder>
```
All MDC properties as key-value entries can be included with `%mdc`:
```
<encoder>
<pattern>%date{ISO8601} %-5level %logger{36} - %msg {%mdc}%n</pattern>
</encoder>
```
### 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
Mapped Diagnostic Context (MDC) with attribute name `sourceThread`.
With Logback the thread name is available with `%X{sourceThread}` specifier within the pattern layout configuration:
```
<appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
<encoder>
<pattern>%date{ISO8601} %-5level %logger{36} %X{sourceThread} - %msg%n</pattern>
</encoder>
</appender>
```
@@@ note
@ -455,26 +463,12 @@ available in the logs.
Another helpful facility is that Akka captures the actors address when
instantiating a logger within it, meaning that the full instance identification
is available for associating log messages e.g. with members of a router. This
information is available in the MDC with attribute name `akkaSource`:
information is available in the MDC with attribute name `akkaSource`.
```
<appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
<encoder>
<pattern>%date{ISO8601} %-5level %logger{36} %X{akkaSource} - %msg%n</pattern>
</encoder>
</appender>
```
The address of the actor system, containing host and port if the system is using cluster, is available through `akkaAddress`.
Finally, the actor system in which the logging was performed
is available in the MDC with attribute name `sourceActorSystem`:
```
<appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
<encoder>
<pattern>%date{ISO8601} %-5level %logger{36} %X{sourceActorSystem} - %msg%n</pattern>
</encoder>
</appender>
```
is available in the MDC with attribute name `sourceActorSystem`.
For more details on what this attribute contains—also for non-actors—please see
[How to Log](#how-to-log).
@ -483,15 +477,7 @@ For more details on what this attribute contains—also for non-actors—please
Akka's 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`:
```
<appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
<encoder>
<pattern>%X{akkaTimestamp} %-5level %logger{36} %X{akkaTimestamp} - %msg%n</pattern>
</encoder>
</appender>
```
If you want to more accurately output the timestamp, use the MDC attribute `akkaTimestamp`.
### MDC values defined by the application
@ -552,6 +538,14 @@ Now, the values will be available in the MDC, so you can use them in the layout
</appender>
```
All MDC properties as key-value entries can be included with `%mdc`:
```
<encoder>
<pattern>%date{ISO8601} %-5level %logger{36} - %msg {%mdc}%n</pattern>
</encoder>
```
### Using Markers
Some logging libraries allow, in addition to MDC data, attaching so called "markers" to log statements.
@ -563,17 +557,6 @@ Markers are available through the LoggingAdapters, when obtained via `Logging.wi
The first argument passed into all log calls then should be a `akka.event.LogMarker`.
The slf4j bridge provided by Akka in `akka-slf4j` will automatically pick up this marker value and make it available to SLF4J.
For example you could use it like this:
```
<pattern>%date{ISO8601} [%marker][%level] [%msg]%n</pattern>
```
A more advanced (including most Akka added information) example pattern would be:
```
<pattern>%date{ISO8601} level=[%level] marker=[%marker] logger=[%logger] akkaSource=[%X{akkaSource}] sourceActorSystem=[%X{sourceActorSystem}] sourceThread=[%X{sourceThread}] mdc=[ticket-#%X{ticketNumber}: %X{ticketDesc}] - msg=[%msg]%n----%n</pattern>
```
Akka is logging some events with markers. Some of these events also include structured MDC properties.
@ -583,6 +566,16 @@ Akka is logging some events with markers. Some of these events also include stru
* Akka Remoting is using the markers defined in @apidoc[akka.remote.RemoteLogMarker].
* Akka Cluster Sharding is using the markers defined in @apidoc[akka.cluster.sharding.ShardingLogMarker].
Markers and MDC properties are automatically picked up by the [Logstash Logback encoder](https://github.com/logstash/logstash-logback-encoder).
The marker can be included in the Logback output with `%marker` and all MDC properties as key-value entries with `%mdc`.
```
<encoder>
<pattern>[%date{ISO8601}] [%level] [%logger] [%marker] [%thread] - %msg {%mdc}%n</pattern>
</encoder>
```
#### Using SLF4J's Markers
It is also possible to use the `org.slf4j.Marker` with the `LoggingAdapter` when using slf4j.

View file

@ -221,10 +221,15 @@ 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`.
@ref:[How to log](#how-to-log) Akka includes a few MDC properties:
This can be included in the log output with `%X{akkaSource}` specifier within the pattern layout configuration:
* `akkaSource`: the actor's path
* `akkaAddress`: the full address of the ActorSystem, including hostname and port if Cluster is enabled
* `akkaTags`: tags defined in the `Props` of the actor
* `sourceActorSystem`: the name of the ActorSystem
These MDC properties can be included in the Logback output with for example `%X{akkaSource}` specifier within the
[pattern layout configuration](http://logback.qos.ch/manual/layouts.html#mdc):
```
<encoder>
@ -232,6 +237,15 @@ This can be included in the log output with `%X{akkaSource}` specifier within th
</encoder>
```
All MDC properties as key-value entries can be included with `%mdc`:
```
<encoder>
<pattern>%date{ISO8601} %-5level %logger{36} - %msg {%mdc}%n</pattern>
</encoder>
```
## Internal logging by Akka
### Event bus
@ -385,51 +399,34 @@ akka.remote.artery {
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 path of the actor in which the logging was performed is available in the MDC with attribute name `akkaSource`.
The actor system name 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>
```
The address of the actor system, containing host and port if the system is using cluster, is available through `akkaAddress`:
```
<encoder>
<pattern>%date{ISO8601} %-5level %logger{36} %X{akkaAddress} - %msg%n</pattern>
</encoder>
```
The address of the actor system, containing host and port if the system is using cluster, is available through `akkaAddress`.
For typed actors the log event timestamp is taken when the log call was made but for
Akka's _internal_ logging as well as the classic actor 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 for such loggers, use the MDC attribute `akkaTimestamp`. Note that
the MDC key will not have any value for a typed actor.
With Logback the timestamp is available with `%X{akkaTimestamp}` specifier within the pattern layout configuration:
These MDC properties can be included in the Logback output with for example `%X{akkaSource}` specifier within the
[pattern layout configuration](http://logback.qos.ch/manual/layouts.html#mdc):
```
<encoder>
<pattern>%X{akkaTimestamp} %-5level %logger{36} %X{akkaTimestamp} - %msg%n</pattern>
<pattern>%date{ISO8601} %-5level %logger{36} %X{akkaSource} - %msg%n</pattern>
</encoder>
```
All MDC properties as key-value entries can be included with `%mdc`:
```
<encoder>
<pattern>%date{ISO8601} %-5level %logger{36} - %msg {%mdc}%n</pattern>
</encoder>
```
@ -443,6 +440,16 @@ Akka is logging some events with markers. Some of these events also include stru
* Akka Remoting is using the markers defined in @apidoc[akka.remote.RemoteLogMarker].
* Akka Cluster Sharding is using the markers defined in @apidoc[akka.cluster.sharding.ShardingLogMarker].
Markers and MDC properties are automatically picked up by the [Logstash Logback encoder](https://github.com/logstash/logstash-logback-encoder).
The marker can be included in the Logback output with `%marker` and all MDC properties as key-value entries with `%mdc`.
```
<encoder>
<pattern>[%date{ISO8601}] [%level] [%logger] [%marker] [%thread] - %msg {%mdc}%n</pattern>
</encoder>
```
### Logger names
It can be useful to enable debug level or other SLF4J backend configuration for certain modules of Akka when

View file

@ -8,7 +8,7 @@
<level>INFO</level>
</filter>
<encoder>
<pattern>%date{ISO8601} %-5level %logger %X{akkaSource} %X{sourceThread} - %msg%n</pattern>
<pattern>%date{ISO8601} %-5level %logger %marker - %msg {%mdc}%n</pattern>
</encoder>
</appender>

View file

@ -4,7 +4,7 @@
<appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
<encoder>
<pattern>%date{ISO8601} %-5level %logger %X{akkaSource} %X{sourceThread} - %msg%n</pattern>
<pattern>%date{ISO8601} %-5level %logger %marker - %msg {%mdc}%n</pattern>
</encoder>
</appender>
@ -12,7 +12,7 @@
<file>target/akka-osgi.log</file>
<append>true</append>
<encoder>
<pattern>%date{ISO8601} %-5level %logger %X{akkaSource} %X{sourceThread} - %msg%n</pattern>
<pattern>%date{ISO8601} %-5level %logger %marker - %msg {%mdc}%n</pattern>
</encoder>
</appender>

View file

@ -8,7 +8,7 @@
<level>INFO</level>
</filter>
<encoder>
<pattern>%date{ISO8601} %-5level %logger %X{akkaSource} %X{sourceThread} { "persistenceId": "%X{persistenceId}", "persistencePhase": "%X{persistencePhase}" } - %msg%n</pattern>
<pattern>%date{ISO8601} %-5level %logger %marker - %msg {%mdc}%n</pattern>
</encoder>
</appender>

View file

@ -7,7 +7,7 @@
</appender>
<appender name="TEST" class="akka.event.slf4j.Slf4jLoggerSpec$TestAppender">
<encoder>
<pattern>%date{ISO8601} level=[%level] marker=[%marker] logger=[%logger] akkaSource=[%X{akkaSource}] akkaAddress=[%X{akkaAddress}] sourceActorSystem=[%X{sourceActorSystem}] sourceThread=[%X{sourceThread}] mdc=[ticket-#%X{ticketNumber}: %X{ticketDesc} p1: %X{p1} p2: %X{p2}] - msg=[%msg]%n----%n</pattern>
<pattern>%date{ISO8601} level=[%level] marker=[%marker] logger=[%logger] mdc=[%mdc] - msg=[%msg]%n----%n</pattern>
</encoder>
</appender>
<logger name="akka.event.slf4j.Slf4jLoggingFilterSpec$DebugLevelProducer"

View file

@ -81,7 +81,7 @@ class Slf4jLoggerSpec extends AkkaSpec(Slf4jLoggerSpec.config) with BeforeAndAft
output.reset()
}
val sourceThreadRegex = "sourceThread=\\[Slf4jLoggerSpec-akka.actor.default-dispatcher-[1-9][0-9]*\\]"
val sourceThreadRegex = "sourceThread=Slf4jLoggerSpec-akka.actor.default-dispatcher-[1-9][0-9]*"
"Slf4jLogger" must {
@ -90,8 +90,8 @@ class Slf4jLoggerSpec extends AkkaSpec(Slf4jLoggerSpec.config) with BeforeAndAft
awaitCond(outputString.contains("----"), 5 seconds)
val s = outputString
s should include("akkaSource=[akka://Slf4jLoggerSpec/user/logProducer]")
s should include("akkaAddress=[akka://Slf4jLoggerSpec]")
s should include("akkaSource=akka://Slf4jLoggerSpec/user/logProducer")
s should include("akkaAddress=akka://Slf4jLoggerSpec")
s should include("level=[ERROR]")
s should include("logger=[akka.event.slf4j.Slf4jLoggerSpec$LogProducer]")
(s should include).regex(sourceThreadRegex)
@ -105,8 +105,8 @@ class Slf4jLoggerSpec extends AkkaSpec(Slf4jLoggerSpec.config) with BeforeAndAft
awaitCond(outputString.contains("----"), 5 seconds)
val s = outputString
s should include("akkaSource=[akka://Slf4jLoggerSpec/user/logProducer]")
s should include("akkaAddress=[akka://Slf4jLoggerSpec]")
s should include("akkaSource=akka://Slf4jLoggerSpec/user/logProducer")
s should include("akkaAddress=akka://Slf4jLoggerSpec")
s should include("level=[INFO]")
s should include("logger=[akka.event.slf4j.Slf4jLoggerSpec$LogProducer]")
(s should include).regex(sourceThreadRegex)
@ -128,7 +128,8 @@ class Slf4jLoggerSpec extends AkkaSpec(Slf4jLoggerSpec.config) with BeforeAndAft
awaitCond(outputString.contains("----"), 5 seconds)
val s = outputString
s should include("marker=[testMarker]")
s should include("p1: 1 p2: B")
s should include("p1=1")
s should include("p2=B")
s should include("msg=[interesting message]")
}
@ -153,7 +154,7 @@ class Slf4jLoggerSpec extends AkkaSpec(Slf4jLoggerSpec.config) with BeforeAndAft
awaitCond(outputString.contains("----"), 5 seconds)
val s = outputString
s should include("marker=[SLF [ ADDED ]]")
s should include("mdc=[ticket-#3671: Custom MDC Values")
s should include("ticketDesc=Custom MDC Values")
s should include("msg=[security-wise interesting message]")
}
@ -164,11 +165,11 @@ class Slf4jLoggerSpec extends AkkaSpec(Slf4jLoggerSpec.config) with BeforeAndAft
awaitCond(outputString.contains("----"), 5 seconds)
val s = outputString
s should include("akkaSource=[akka://Slf4jLoggerSpec/user/logProducer]")
s should include("akkaSource=akka://Slf4jLoggerSpec/user/logProducer")
s should include("level=[INFO]")
s should include("logger=[akka.event.slf4j.Slf4jLoggerSpec$LogProducer]")
(s should include).regex(sourceThreadRegex)
s should include("mdc=[ticket-#3671: Custom MDC Values")
s should include("ticketDesc=Custom MDC Values")
s should include("msg=[Message with custom MDC values]")
}
@ -185,11 +186,11 @@ class Slf4jLoggerSpec extends AkkaSpec(Slf4jLoggerSpec.config) with BeforeAndAft
awaitCond(outputString.contains("----"), 5 seconds)
val s = outputString
s should include("akkaSource=[akka://Slf4jLoggerSpec/user/logProducer]")
s should include("akkaSource=akka://Slf4jLoggerSpec/user/logProducer")
s should include("level=[INFO]")
s should include("logger=[akka.event.slf4j.Slf4jLoggerSpec$LogProducer]")
(s should include).regex(sourceThreadRegex)
s should include("mdc=[ticket-#3671: null")
s should include("ticketDesc=null")
s should include("msg=[Message with null custom MDC values]")
}
@ -198,7 +199,7 @@ class Slf4jLoggerSpec extends AkkaSpec(Slf4jLoggerSpec.config) with BeforeAndAft
log.info("test")
awaitCond(outputString.contains("----"), 5 seconds)
val s = outputString
s should include("akkaSource=[akka.event.slf4j.Slf4jLoggerSpec.MyLogSource(akka://Slf4jLoggerSpec)]")
s should include("akkaSource=akka.event.slf4j.Slf4jLoggerSpec.MyLogSource(akka://Slf4jLoggerSpec)")
s should include("logger=[akka.event.slf4j.Slf4jLoggerSpec.MyLogSource(akka://Slf4jLoggerSpec)]")
}
@ -207,7 +208,7 @@ class Slf4jLoggerSpec extends AkkaSpec(Slf4jLoggerSpec.config) with BeforeAndAft
log.info("test")
awaitCond(outputString.contains("----"), 5 seconds)
val s = outputString
s should include("akkaSource=[akka.event.slf4j.Slf4jLoggerSpec.MyLogSource]")
s should include("akkaSource=akka.event.slf4j.Slf4jLoggerSpec.MyLogSource")
s should include("logger=[akka.event.slf4j.Slf4jLoggerSpec.MyLogSource]")
}
@ -216,7 +217,7 @@ class Slf4jLoggerSpec extends AkkaSpec(Slf4jLoggerSpec.config) with BeforeAndAft
log.info("test")
awaitCond(outputString.contains("----"), 5 seconds)
val s = outputString
s should include("akkaSource=[Slf4jLoggerSpec$MyLogSource(akka://Slf4jLoggerSpec)]")
s should include("akkaSource=Slf4jLoggerSpec$MyLogSource(akka://Slf4jLoggerSpec)")
s should include("logger=[akka.event.slf4j.Slf4jLoggerSpec$MyLogSource]")
}
@ -225,7 +226,7 @@ class Slf4jLoggerSpec extends AkkaSpec(Slf4jLoggerSpec.config) with BeforeAndAft
log.info("test")
awaitCond(outputString.contains("----"), 5 seconds)
val s = outputString
s should include("akkaSource=[Slf4jLoggerSpec$MyLogSource]")
s should include("akkaSource=Slf4jLoggerSpec$MyLogSource")
s should include("logger=[akka.event.slf4j.Slf4jLoggerSpec$MyLogSource]")
}
@ -234,7 +235,7 @@ class Slf4jLoggerSpec extends AkkaSpec(Slf4jLoggerSpec.config) with BeforeAndAft
log.info("test")
awaitCond(outputString.contains("----"), 5 seconds)
val s = outputString
s should include("sourceActorSystem=[Slf4jLoggerSpec]")
s should include("sourceActorSystem=Slf4jLoggerSpec")
}
}