Logging

jim stafford

Introduction

Why log?

Logging has many uses within an application — spanning:

auditing actions
reporting errors
providing debug information to assist in locating a problem

With much of our code located in libraries — logging is not just for our application code. We will want to know audit, error, and debug information in our library calls as well:

did that timer fire?
which calls failed?
what HTTP headers were input or returned from a REST call?

Why use a Logger over System.out?

Use of Loggers allow statements to exist within the code that will either:

be disabled
log output uninhibited
log output with additional properties (e.g., timestamp, thread, caller, etc.)

Logs are:

commonly are written to the console and/or files by default — but that is not always the case
can be exported to centralized servers or database(s)
- form integrated picture of distributed system
- provide search and alarm capabilities.

However simple or robust your end logs become, logging starts with the code and is a very important thing to include from the beginning (even if we waited a few modules to cover it).

Goals

The student will learn:

to understand the value in using logging over simple System.out.println calls
to understand the interface and implementation separation of a modern logging framework
the relationship between the different logger interfaces and implementations
to use log levels and verbosity to properly monitor the application under different circumstances
to express valuable context information in logged messages
to manage logging verbosity
to configure the output of logs to provide useful information

Objectives

At the conclusion of this lecture and related exercises, the student will be able to:

obtain access to an SLF4J Logger
issue log events at different severity levels
filter log events based on source and severity thresholds
efficiently bypass log statements that do not meet criteria
format log events for regular and exception parameters
customize log patterns
customize appenders
add contextual information to log events using Mapped Diagnostic Context
trigger additional logging events using Markers
use Spring Profiles to conditionally configure logging

Starting References

There are many resources on the Internet that cover logging, the individual logging implementations, and the Spring Boot opinionated support for logging.

Spring Boot Logging Feature provides documentation from a top-down perspective of how it supplies a common logging abstraction over potentially different logging implementations.
SLF4J Web Site provides documentation, articles, and presentations on SLF4J — the chosen logging interface for Spring Boot and much of the Java community.
Logback Web Site provides a wealth of documentation, articles, and presentations on Logback — the default logging implementation for Spring Boot.
Log4J2 Web Site provides core documentation on Log4J2 — a directly supported Spring Boot alternative logging implementation.
Java Util Logging (JUL) Documentation Web Site provides an overview of JUL — a lesser supported Spring Boot alternative implementation for logging.

Logging Dependencies

supplied through dependency on spring-boot-starter
- its dependency on spring-boot-starter-logging
only need to supply additional dependencies when
- changing default logging implementation
- making use of optional, specialized logging extensions

Spring Boot Starter Logging Dependencies

$ mvn dependency:tree
...
[INFO] info.ejava.examples.app:appconfig-logging-example:jar:6.1.0-SNAPSHOT
[INFO] \- org.springframework.boot:spring-boot-starter:jar:3.3.2:compile
...
[INFO]    +- org.springframework.boot:spring-boot-starter-logging:jar:3.3.2:compile (1)
[INFO]    |  +- ch.qos.logback:logback-classic:jar:1.5.6:compile
[INFO]    |  |  +- ch.qos.logback:logback-core:jar:1.5.6:compile
[INFO]    |  |  \- org.slf4j:slf4j-api:jar:2.0.13:compile
[INFO]    |  +- org.apache.logging.log4j:log4j-to-slf4j:jar:2.23.1:compile
[INFO]    |  |  \- org.apache.logging.log4j:log4j-api:jar:2.23.1:compile
[INFO]    |  \- org.slf4j:jul-to-slf4j:jar:2.0.13:compile
...
[INFO]    +- org.springframework:spring-core:jar:3.3.2:compile
[INFO]    |  \- org.springframework:spring-jcl:jar:3.3.2:compile

1	dependency on `spring-boot-starter` brings in `spring-boot-starter-logging`

Logging Libraries

spring-core dependency brings in its own repackaging and optimizations of Commons Logging within spring-jcl
- spring-jcl provides a thin wrapper that looks for logging APIs and self-bootstraps itself to use them — with a preference for the SLF4J interface, then Log4J2 directly, and then JUL as a fallback
- spring-jcl looks to have replaced the need for jcl-over-slf4j
spring-boot-starter-logging provides dependencies for the SLF4J API, adapters and three optional implementations
- implementations — these will perform the work behind the SLF4J interface calls
  - Logback (the default)
  - Log4J2
  - Java Util Logging
- adapters — these will bridge the SLF4J calls to the implementations
  - Logback implements SLF4J natively - no adapter necessary
  - log4j-to-slf4j bridges Log4j to SLF4J
  - jul-to-slf4j - bridges Java Util Logging (JUL) to SLF4J

Logging Default

If we use Spring Boot with spring-boot-starter right out of the box, we will be using the SLF4J API and Logback implementation configured to work correctly for most cases.

Spring and Spring Boot Internal Logging

Spring and Spring Boot use an internal version of the Apache Commons Logging API (Git Repo)
- previously known as the Jakarta Commons Logging or JCL ( Ref: Wikipedia, Apache Commons Logging)
- rehosted within the spring-jcl module
- serves as a bridge to different logging implementations (Ref: Spring Boot Logging)

Getting Started

Lets begin with a comparison with System.out so we can see how they are similar and different

System.out

System.out was built into Java from day 1

no extra imports are required
no extra libraries are required

System.out writes to wherever System.out references — default is stdout

You have seen many earlier examples just like the following.

Example System.out Call

@Component
@Profile("system-out") (1)
public class SystemOutCommand implements CommandLineRunner {
    public void run(String... args) throws Exception {
        System.out.println("System.out message");
    }
}

1	restricting component to profile to allow us to turn off unwanted output after this demo

System.out Output

Example System.out Output

$ java -jar target/appconfig-logging-example-*-SNAPSHOT-bootexec.jar \
--spring.profiles.active=system-out (1)

System.out message (2)

1	activating profile that turns on our component and turns off all logging
2	System.out is not impacted by logging configuration and printed to stdout

Turning Off Spring Boot Logging

Where did all the built-in logging (e.g., Spring Boot banner, startup messages, etc.) go in the last example?

Turning Off Spring Boot Logging

The system-out profile specified a logging.level.root property that effectively turned off all logging.

application-system-out.properties

spring.main.banner-mode=off (1)
logging.level.root=OFF (2)

1	turns off printing of verbose Spring Boot startup banner
2	turns off all logging (inheriting from the root configuration)

Technically the logging was only turned off for loggers inheriting the root configuration — but we will ignore that detail for right now and just say "all logging".

Getting a Logger

fundamental design idiom — separate interface from implementation
our calling should have simple access to a simple interface to express
- information to be logged
- the severity of that information
want implementation to have limitless capability to produce and manage logs
- but want only to pay for what we likely will use
Logging frameworks allow that to occur
- provide primary access thru a logging interface
- provide a means to create an instance of that logger

Figure 1. Logging Framework Primary Stereotypes

Factory creates Logger

Different APIs and Techniques to Get Logger

Lets take a look at several ways to obtain a Logger using different APIs and techniques

Java Util Logger Interface Example

Java Util Logger (JUL) has been built into Java since 1.4
primary interface is the Logger class — both factory and interface for Logger

package info.ejava.examples.app.config.logging.factory;
...
import java.util.logging.Logger; (1)

@Component
public class JULLogger implements CommandLineRunner {
    private static final Logger log = Logger.getLogger(JULLogger.class.getName()); (2)

    @Override
    public void run(String... args) throws Exception {
        log.info("Java Util logger message"); (3)
    }
}

1	import the JUL `Logger` class
2	get a reference to the JUL `Logger` instance by String name
3	issue a log event

JUL Example Output

output shows code using JUL interface integrated into Spring Boot logs

Example Java Util Logging (JUL) Output

java -jar target/appconfig-logging-example-*-SNAPSHOT-bootexec.jar \
--spring.profiles.active=factory
...
20:40:54,136 INFO  info.ejava.examples.app.config.logging.factory.JULLogger - Java Util logger message
...

However, JUL is not widely used as an API or implementation. I won’t detail it here, but it has been reported to be much slower and missing robust features of modern alternatives. That does not mean JUL cannot be used as an API for your code (and the libraries your code relies on) and an implementation for your packaged application. It just means using it as an implementation is uncommon and won’t be the default in Spring Boot and other frameworks.

SLF4J Logger Interface Example

example sequence similar to JUL sequence
- except using SLF4J Logger interface and LoggerFactory class

package info.ejava.examples.app.config.logging.factory;

import org.slf4j.Logger; (1)
import org.slf4j.LoggerFactory;
...
@Component
public class DeclaredLogger implements CommandLineRunner {
    private static final Logger log = LoggerFactory.getLogger(DeclaredLogger.class); (2)

    @Override
    public void run(String... args) throws Exception {
        log.info("declared SLF4J logger message"); (3)
   }
}

1	import the SLF4J `Logger` interface and `LoggerFactory` class
2	get a reference to the SLF4J `Logger` instance using the `LoggerFactory` class
3	issue a log event

SLF4J LoggerFactory Improvement

One immediate improvement SLF4J has over JUL interface is the convenience getLogger() method that accepts a class. Loggers are structured in a tree hierarchy and it is common best practice to name them after the fully qualified class that they are called from. The String form is also available but the Class form helps encourage and simplify following a common best practice.

SLF4J Example Output

$ java -jar target/appconfig-logging-example-*-SNAPSHOT-bootexec.jar \
--spring.profiles.active=factory (1)
...
20:40:55,156 INFO  info.ejava.examples.app.config.logging.factory.DeclaredLogger - declared SLF4J logger message
...

1	supplying custom profile to filter output to include only the factory examples

Lombok SLF4J Declaration Example

Naming loggers with fully qualified class name is so common that Lombok library able to automate declaring Logger during Java compilation

Lombok Example Call

package info.ejava.examples.app.config.logging.factory;

import lombok.extern.slf4j.Slf4j;
...
@Component
@Slf4j (1)
public class LombokDeclaredLogger implements CommandLineRunner {
    (2)
    @Override
    public void run(String... args) throws Exception {
        log.info("lombok declared SLF4J logger"); (3)
    }
}

1	`@Slf4j` annotation automates the import statements and Logger declaration
2	Lombok will declare a static `log` property using `LoggerFactory` during compilation
3	normal log statement provided by calling class — no different from earlier example

Lombok Example Output

Since Lombok primarily automates code generation at compile time, the produced output is identical to the previous manual declaration example.

Lombok Example Output

$ java -jar target/appconfig-logging-example-*-SNAPSHOT-bootexec.jar \
--spring.profiles.active=factory
...
20:40:55,155 INFO  info.ejava.examples.app.config.logging.factory.LombokDeclaredLogger - lombok declared SLF4J logger message
...

Lombok Dependency

Of course, we need to add the following dependency to the project pom.xml to enable Lombok annotation processing.

Lombok Dependency

<!-- used to declare logger -->
<dependency>
    <groupId>org.projectlombok</groupId>
    <artifactId>lombok</artifactId>
    <scope>provided</scope>
</dependency>

Logging Levels

Logger returned from the LoggerFactory
- has an associated level — represents its verbosity threshold
Logger methods indicate their severity

logging severity level calls supported by SLF4J span from trace() to error()
logging threshold levels supported by Spring Boot and Logback also span from TRACE to ERROR and include an OFF
- all levels are case insensitive
treat TRACE being less severe than ERROR

Severity levels supported by other APIs ( JUL Levels, Log4J2 Levels) are mapped to levels supported by SLF4J.

Common Level Use

Although there cannot be enforcement of when to use which level — there are common conventions. The following is a set of conventions I live by:

TRACE

Detailed audits events and verbose state of processing

example: Detailed state at a point in the code. SQL, params, and results of a query.

DEBUG

Audit events and state giving insight of actions performed

example: Beginning/ending a decision branch or a key return value

INFO

Notable audit events and state giving some indication of overall activity performed

example: Started/completed transaction for purchase

WARN

Something unusual to highlight but the application was able to recover

example: Read timeout for remote source

ERROR

Significant or unrecoverable error occurred and an important action failed. These should be extremely limited in their use.

example: Cannot connect to database

Log Level Adjustments

Obviously, there are no perfect guidelines. Adjustments need to be made on a case by case basis.

When forming your logging approach — ask yourself "are the logs telling me what I need to know when I look under the hood?", "what can they tell me with different verbosity settings?", and "what will it cost in terms of performance and storage?".

The last thing you want to do is to be called in for a problem and the logs tell you nothing or too much of the wrong information. Even worse — changing the verbosity of the logs will not help for when the issue occurs the next time.

Logging Level Example Calls

The following is an example of making very simple calls to the logger at different severity levels.

Logging Level Example Calls

package info.ejava.examples.app.config.logging.levels;
...
@Slf4j
public class LoggerLevels implements CommandLineRunner {
    @Override
    public void run(String... args) throws Exception {
        log.trace("trace message"); (1)
        log.debug("debug message");
        log.info("info message");
        log.warn("warn message");
        log.error("error message"); (1)
    }
}

1	example issues one log message at each of the available LSF4J severity levels

Logging Level Output: INFO

Logging Level INFO Example Output

$ java -jar target/appconfig-logging-example-*-SNAPSHOT-bootexec.jar \
--spring.profiles.active=levels (1)

06:36:15,910 INFO  info.ejava.examples.app.config.logging.levels.LoggerLevels - info message (2)
06:36:15,912 WARN  info.ejava.examples.app.config.logging.levels.LoggerLevels - warn message
06:36:15,912 ERROR info.ejava.examples.app.config.logging.levels.LoggerLevels - error message

1	profile sets `info.ejava.examples.app.config.logging.levels` threshold level to INFO
2	messages logged for `INFO`, `WARN`, and `ERROR` severity because they are >= `INFO`

application-levels.properties

#application-levels.properties
logging.pattern.console=%date{HH:mm:ss.SSS} %-5level %logger - %msg%n (3)

logging.level.info.ejava.examples.app.config.logging.levels=info (2)
logging.level.root=OFF (1)

1	all loggers are turned off by default
2	example package logger threshold level produces log events with severity >= `INFO`
3	customized console log messages to contain pertinent example info

Logging Level Output: DEBUG

Lower threshold for logger to DEBUG — get one additional severity level than INFO in output

Logging Level DEBUG Example Output

$ java -jar target/appconfig-logging-example-*-SNAPSHOT-bootexec.jar \
--spring.profiles.active=levels \
--logging.level.info.ejava.examples.app.config.logging.levels=DEBUG (1)

06:37:04,292 DEBUG info.ejava.examples.app.config.logging.levels.LoggerLevels - debug message (2)
06:37:04,293 INFO  info.ejava.examples.app.config.logging.levels.LoggerLevels - info message
06:37:04,294 WARN  info.ejava.examples.app.config.logging.levels.LoggerLevels - warn message
06:37:04,294 ERROR info.ejava.examples.app.config.logging.levels.LoggerLevels - error message

1	logging.level sets `info.ejava.examples.app.config.logging.levels` threshold level to DEBUG
2	messages logged for `DEBUG`, `INFO`, `WARN`, and `ERROR` severity because they are >= `DEBUG`

Logging Level Output: TRACE

Lower threshold for logger to TRACE — get two additional severity levels than INFO in output

Logging Level TRACE Example Output

$ java -jar target/appconfig-logging-example-*-SNAPSHOT-bootexec.jar \
--spring.profiles.active=levels \
--logging.level.info.ejava.examples.app.config.logging.levels=TRACE (1)

06:37:19,968 TRACE info.ejava.examples.app.config.logging.levels.LoggerLevels - trace message (2)
06:37:19,970 DEBUG info.ejava.examples.app.config.logging.levels.LoggerLevels - debug message
06:37:19,970 INFO  info.ejava.examples.app.config.logging.levels.LoggerLevels - info message
06:37:19,970 WARN  info.ejava.examples.app.config.logging.levels.LoggerLevels - warn message
06:37:19,970 ERROR info.ejava.examples.app.config.logging.levels.LoggerLevels - error message

1	logging.level sets `info.ejava.examples.app.config.logging.levels` threshold level to TRACE
2	messages logged for all severity levels because they are >= `TRACE`

Logging Level Output: WARN

Lower threshold for logger to WARN — get one less severity level than INFO in output

Logging Level WARN Example Output

$ java -jar target/appconfig-logging-example-*-SNAPSHOT-bootexec.jar \
--spring.profiles.active=levels \
--logging.level.info.ejava.examples.app.config.logging.levels=WARN (1)

06:37:32,753 WARN  info.ejava.examples.app.config.logging.levels.LoggerLevels - warn message (2)
06:37:32,755 ERROR info.ejava.examples.app.config.logging.levels.LoggerLevels - error message

1	logging.level sets `info.ejava.examples.app.config.logging.levels` threshold level to WARN
2	messages logged for `WARN`, and `ERROR` severity because they are >= `WARN`

Logging Level Output: OFF

Lower threshold for logger to OFF — get no output produced

Logging Level OFF Example Output

$ java -jar target/appconfig-logging-example-*-SNAPSHOT-bootexec.jar \
--spring.profiles.active=levels \
--logging.level.info.ejava.examples.app.config.logging.levels=OFF (1)

(2)

1	logging.level sets `info.ejava.examples.app.config.logging.levels` threshold level to OFF
2	no messages logged because logger turned off

Discarded Message Expense

substantial savings can come from turning off verbose severity level thresholds
however — even disabled threshold calls can increase execution time
- building message to be logged carries its own expense

Example Expensive toString()

class ExpensiveToLog {
    public String toString() { (1)
        try { Thread.sleep(1000); } catch (Exception ignored) {}
        return "hello";
    }
}

1	calling `toString()` on instances of this class will incur noticeable delay

Blind String Concatenation

What is wong here?

Blind String Concatenation Example

ExpensiveToLog obj=new ExpensiveToLog();
//...
log.debug("debug for expensiveToLog: " + obj + "!");

The log message will get formed by eagerly concatenating several Strings together
One of those Strings is produced by a relatively expensive toString() method
Problem: The work of eagerly forming the String is wasted if DEBUG is not enabled

Verbosity Check

Assume information from toString() call is

valuable
needed when we have DEBUG enabled

Verbosity check is one common solution

determine if end result worth the work

Two very similar ways we can do this

Dynamically
Statically

Dynamic Verbosity Check

check current threshold level of logger — only execute if requested severity level is enabled
- still building expensive String when DEBUG is enabled
- saves processing time when DEBUG not enabled

Dynamic Verbosity Check Example

if (log.isDebugEnabled()) { (1)
    log.debug("debug for expensiveToLog: " + obj +"!");
}

1	code block with expensive `toString()` call is bypassed when `DEBUG` disabled

works best when multiple lines of code required
suitable when there are very few checks within a class

Static Final Verbosity Check

define a static final boolean variable to result of enabled test
allows JVM to know value of predicate will never change
- allowing code block and further checks to be eliminated when disabled

Static Verbosity Check Example

private static final boolean DEBUG_ENABLED = log.isDebugEnabled(); (1)
...
    if (DEBUG_ENABLED) { (2)
        log.debug("debug for expensiveToLog: " + obj + "!");
    }
...

1	logger’s verbosity level tested when class loaded and stored in `static final` variable
2	code block with expensive `toString()`

better when multiple blocks of code to make conditional on the threshold level of same logger
assumes logger threshold will never change or JVM will be restarted to change value

I have seen this technique commonly used in libraries where they anticipate many calls and they are commonly judged on their method throughput performance.

SLF4J Parameterized Logging

SLF4J API offers another solution
- removes need for if clause — cleaning code extra conditional blocks
SLF4J Logger interface has a format and args variant for each verbosity level call
- threshold consulted prior to converting any of the parameters to String
curly braces ("{}") express ordered insertion point in format spec for args
no format options — lazily calls toString() on each arg and inserts result

SLF4J Parameterized Logging Example

log.debug("debug for expensiveToLog: {}!", obj); (1) (2)

1	`{}` is a placeholder for the result of `obj.toString()` if called
2	`obj.toString()` only called and overall message concatenated if logger threshold set to ⇐ `DEBUG`

Simple Performance Results: Disabled

Not scientific by any means, but the following results try to highlight the major cost differences between blind concatenation and the other methods. The basic results also show the parameterized logging technique to be on par with the threshold level techniques with far less code complexity.

The test code warms up the logger with a few calls and then issues the debug statements shown above in succession with time hacks taken in between each.

The first set of results are from logging threshold set to INFO. The blind concatenation shows that it eagerly calls the obj.toString() method just to have its resulting message discarded. The other methods do not pay a measurable penalty.

test code
- warms up logger with few calls
- issues the debug statements shown above in succession
- time hacks taken in between each
first set of results are from logging threshold set to INFO
- blind concatenation shows it eagerly calls the obj.toString() method just to have its resulting message discarded
- other methods do not pay a measurable penalty

major cost differences between blind concatenation and other methods
parameterized logging technique on par with threshold level techniques with far less code complexity

Disabled Logger Relative Results

$ java -jar target/appconfig-logging-example-*-SNAPSHOT-bootexec.jar \
--spring.profiles.active=expense \
--logging.level.info.ejava.examples.app.config.logging.expense=INFO

11:44:25.462 INFO  info.ejava.examples.app.config.logging.expense.DisabledOptimization - warmup logger
11:44:26.476 INFO  info.ejava.examples.app.config.logging.expense.DisabledOptimization - \

concat: 1012, ifDebug=0, DEBUG_ENABLED=0, param=0 (1) (2)

1	eager blind concatenation pays `toString()` cost even when not needed (1012ms)
2	verbosity check and lazy parameterized logging equally efficient (0ms)

Simple Performance Results: Enabled

expensive toString() called for each of the four techniques
- neither provide noticeable processing delay over the other when logging threshold met
- do not put much weight on a few milliseconds difference between calls

Enabled Logger Relative Results

$ java -jar target/appconfig-logging-example-*-SNAPSHOT-bootexec.jar \
--spring.profiles.active=expense \
--logging.level.info.ejava.examples.app.config.logging.expense=DEBUG

11:44:43.560 INFO  info.ejava.examples.app.config.logging.expense.DisabledOptimization - warmup logger
11:44:43.561 DEBUG info.ejava.examples.app.config.logging.expense.DisabledOptimization - warmup logger
11:44:44.572 DEBUG info.ejava.examples.app.config.logging.expense.DisabledOptimization - debug for expensiveToLog: hello!
11:44:45.575 DEBUG info.ejava.examples.app.config.logging.expense.DisabledOptimization - debug for expensiveToLog: hello!
11:44:46.579 DEBUG info.ejava.examples.app.config.logging.expense.DisabledOptimization - debug for expensiveToLog: hello!
11:44:46.579 DEBUG info.ejava.examples.app.config.logging.expense.DisabledOptimization - debug for expensiveToLog: hello!
11:44:47.582 INFO  info.ejava.examples.app.config.logging.expense.DisabledOptimization - \

concat: 1010, ifDebug=1003, DEBUG_ENABLED=1004, param=1003 (1)

1	all four methods paying the cost of the relatively expensive `obj.toString()` call

Exception Logging

SLF4J parameterized logging treats Exceptions special if last parameter
- will not have its toString() called
- stack trace for Exception is logged instead

Example Exception Logging

public void run(String... args) throws Exception {
    try {
        log.info("calling iThrowException");
        iThrowException();
    } catch (Exception ex) {
        log.warn("caught exception", ex); (1)
    }
}

private void iThrowException() throws Exception {
    throw new Exception("example exception");
}

1	`Exception` passed to logger with message

Exception Example Output

message is printed in its normal location
stack trace is added for the supplied Exception parameter

Example Exception Logging Output

$ java -jar target/appconfig-logging-example-*-SNAPSHOT-bootexec.jar \
--spring.profiles.active=exceptions

13:41:17.119 INFO  info.ejava.examples.app.config.logging.exceptions.ExceptionExample - calling iThrowException
13:41:17.121 WARN  info.ejava.examples.app.config.logging.exceptions.ExceptionExample - caught exception (1)
java.lang.Exception: example exception (2)
        at info.ejava.examples.app.config.logging.exceptions.ExceptionExample.iThrowException(ExceptionExample.java:23)
        at info.ejava.examples.app.config.logging.exceptions.ExceptionExample.run(ExceptionExample.java:15)
        at org.springframework.boot.SpringApplication.callRunner(SpringApplication.java:784)
...
    at org.springframework.boot.loader.Launcher.launch(Launcher.java:51)
        at org.springframework.boot.loader.JarLauncher.main(JarLauncher.java:52)

1	normal message logged
2	stack trace for last `Exception` parameter logged

Exception Logging and Formatting

can use parameterized logging with Exceptions
snippet below shows a format with two parameters and an Exception
(previous example was a format with no non-Exception parameters)

Example Exception Logging with Parameters

log.warn("caught exception {} {}", "p1","p2", ex);

Example Exception Logging with Parameters Output

13:41:17.119 INFO  info.ejava.examples.app.config.logging.exceptions.ExceptionExample - calling iThrowException
13:41:17.122 WARN  info.ejava.examples.app.config.logging.exceptions.ExceptionExample - caught exception p1 p2 (1)
java.lang.Exception: example exception (2)
        at info.ejava.examples.app.config.logging.exceptions.ExceptionExample.iThrowException(ExceptionExample.java:23)
        at info.ejava.examples.app.config.logging.exceptions.ExceptionExample.run(ExceptionExample.java:15)
        at org.springframework.boot.SpringApplication.callRunner(SpringApplication.java:784)
...
    at org.springframework.boot.loader.Launcher.launch(Launcher.java:51)
        at org.springframework.boot.loader.JarLauncher.main(JarLauncher.java:52)

1	two early parameters ("p1" and "p2") where used to complete the message template
2	`Exception` passed as the last parameter had its stack trace logged

Logging Pattern

previous examples showed logging output using a custom pattern
expressed using logging.pattern.console property

Sample Custom Pattern

logging.pattern.console=%date{HH:mm:ss.SSS} %-5level %logger - %msg%n

Example Pattern Contents

The pattern consisted of (ref: Logback Conversion Documentation):

logging.pattern.console=%date{HH:mm:ss.SSS} %-5level %logger - %msg%n

%date (or %d)- time of day down to millisecs
%level (or %p, %le)- severity level left justified and padded to 5 characters
%logger (or %c, %lo)- full name of logger
%msg (or %m, %message) - full logged message
%n - operating system-specific new line

If you remember, that produced the following output.

Review: LoggerLevels Example Pattern Output

java -jar target/appconfig-logging-example-*-SNAPSHOT-bootexec.jar \
--spring.profiles.active=levels

06:00:38.891 INFO  info.ejava.examples.app.config.logging.levels.LoggerLevels - info message
06:00:38.892 WARN  info.ejava.examples.app.config.logging.levels.LoggerLevels - warn message
06:00:38.892 ERROR info.ejava.examples.app.config.logging.levels.LoggerLevels - error message

Default Console Pattern

Spring Boot default pattern expressed in CONSOLE_LOG_PATTERN property
following snippet depicts information found within the Logback property definition — new lines added in to help read it

Gist of CONSOLE_LOG_PATTERN from GitHub

%clr(%d{${LOG_DATEFORMAT_PATTERN:-yyyy-MM-dd HH:mm:ss.SSS}}){faint}
%clr(${LOG_LEVEL_PATTERN:-%5p})
%clr(${PID:- }){magenta}
%clr(---){faint}
%clr([%15.15t]){faint}
%clr(%-40.40logger{39}){cyan}
%clr(:){faint}
%m%n${LOG_EXCEPTION_CONVERSION_WORD:-%wEx}}

Default Console Pattern Contents

%d - timestamp defaulting to full format
%p - severity level right justified and padded to 5 characters
$PID - system property containing the process ID
%t (or %thread) - thread name right justified and padded to 15 characters and chopped at 15 characters
%logger - logger name optimized to fit within 39 characters , left justified and padded to 40 characters, chopped at 40 characters
%m - fully logged message
%n - operating system-specific new line
%wEx - Spring Boot-defined exception formatting

Default Console Pattern Output

LoggerLevels Output with Default Spring Boot Console Log Pattern

java -jar target/appconfig-logging-example-*-SNAPSHOT-bootexec.jar \
--logging.level.root=OFF \
--logging.level.info.ejava.examples.app.config.logging.levels.LoggerLevels=TRACE

2020-03-27 06:31:21.475 TRACE 31203 --- [           main] i.e.e.a.c.logging.levels.LoggerLevels    : trace message
2020-03-27 06:31:21.477 DEBUG 31203 --- [           main] i.e.e.a.c.logging.levels.LoggerLevels    : debug message
2020-03-27 06:31:21.477  INFO 31203 --- [           main] i.e.e.a.c.logging.levels.LoggerLevels    : info message
2020-03-27 06:31:21.477  WARN 31203 --- [           main] i.e.e.a.c.logging.levels.LoggerLevels    : warn message
2020-03-27 06:31:21.477 ERROR 31203 --- [           main] i.e.e.a.c.logging.levels.LoggerLevels    : error message

color triggered by level
- red for ERROR
- yellow for WARN
- green for others

Variable Substitution

logging configurations within Spring Boot make use of variable substitution
- value of LOG_DATEFORMAT_PATTERN will be applied wherever the expression ${LOG_DATEFORMAT_PATTERN} appears
- "${}" characters are part of variable expression and will not be part of the result

Conditional Variable Substitution

variables can be defined with default values
${LOG_DATEFORMAT_PATTERN:-yyyy-MM-dd HH:mm:ss.SSS}
- the value of LOG_DATEFORMAT_PATTERN will be used if defined
- the value of "yyyy-MM-dd HH:mm:ss.SSS" will be used if not defined

The "${}" and embedded ":-" characters following the variable name are part of the expression when appearing within an XML configuration file and will not be part of the result. The dash (-) character should be removed if using within a property definition.

Date Format Pattern

default CONSOLE_LOG_PATTERN timestamp can be changed using LOG_DATEFORMAT_PATTERN system property
- can flexibly be set using logging.pattern.dateformat property

Setting Date Format

$ java -jar target/appconfig-logging-example-*-SNAPSHOT-bootexec.jar \
--logging.level.root=OFF \
--logging.level.info.ejava.examples.app.config.logging.levels.LoggerLevels=INFO \
--logging.pattern.dateformat="HH:mm:ss.SSS" (1)

08:20:42.939  INFO 39013 --- [           main] i.e.e.a.c.logging.levels.LoggerLevels    : info message
08:20:42.942  WARN 39013 --- [           main] i.e.e.a.c.logging.levels.LoggerLevels    : warn message
08:20:42.942 ERROR 39013 --- [           main] i.e.e.a.c.logging.levels.LoggerLevels    : error message

1	setting `LOG_DATEFORMAT_PATTERN` using `logging.pattern.dateformat` property

Log Level Pattern

default CONSOLE_LOG_PATTERN severity level can be changed using LOG_LEVEL_PATTERN system property
- can be flexibly set using logging.pattern.level property
example shows setting format to single character, left justified
- mapping INFO⇒ I, WARN⇒ W, and ERROR⇒ E

$ java -jar target/appconfig-logging-example-*-SNAPSHOT-bootexec.jar \
--logging.level.root=OFF \
--logging.level.info.ejava.examples.app.config.logging.levels.LoggerLevels=INFO \
--logging.pattern.dateformat="HH:mm:ss.SSS" \
--logging.pattern.level="%.-1p" (1)
             (2)
08:59:17.376 I 44756 --- [           main] i.e.e.a.c.logging.levels.LoggerLevels    : info message
08:59:17.379 W 44756 --- [           main] i.e.e.a.c.logging.levels.LoggerLevels    : warn message
08:59:17.379 E 44756 --- [           main] i.e.e.a.c.logging.levels.LoggerLevels    : error message

1	`logging.level.pattern` expressed to be 1 character, left justified
2	single character produced in console log output

Conversion Pattern Specifiers

Spring Boot Features Web Page documents some formatting rules. However, more details on the parts within the conversion pattern are located on the Logback Pattern Layout Web Page. The overall end-to-end pattern definition I have shown you is called a "Conversion Pattern". Conversion Patterns are made up of:

Literal Text (e.g., ---, whitespace, :) — hard-coded strings providing decoration and spacing for conversion specifiers
Conversion Specifiers - (e.g., %-40.40logger{39}) — an expression that will contribute a formatted property of the current logging context
- starts with %
- followed by format modifiers — (e.g., -40.40) — addresses min/max spacing and right/left justification
  - optionally provide minimum number of spaces
    use a negative number (-#) to make it left justified and a positive number (#) to make it right justified
  - optionally provide maximum number of spaces using a decimal place and number (.#). Extra characters will be cut off
    use a negative number (.-#) to start from the left and positive number (.#) to start from the right
- followed by a conversion word (e.g., logger, msg) — keyword name for the property
- optional parameters (e.g., {39}) — see individual conversion words for details on each

overall end-to-end pattern definition called "Conversion Pattern"
Spring Boot Features Web Page and primarily the Logback Pattern Layout Web Page document conversion pattern formatting rules

Conversion Patterns

Literal Text (e.g., ---, whitespace) — hard-coded decoration/spacing around conversion specifiers
Conversion Specifiers - (e.g., %-40.40logger{39}) — an expression that will contribute a formatted property of the current logging context
- starts with %
- followed by format modifiers — (e.g., -40.40) — min/max spacing and right/left justification
  - optionally provide minimum number of spaces
    use a negative number (-#) to make it left justified and a positive number (#) to make it right justified
  - optionally provide maximum number of spaces using a decimal place and number (.#). Extra characters will be cut off
    use a negative number (.-#) to start from the left and positive number (.#) to start from the right
- followed by a conversion word (e.g., logger, msg) — keyword name for property
- optional parameters (e.g., {39}) — see individual conversion words for details on each

Format Modifier Impact Example

Table 1. %level Format Modifier Impact Example
logging.pattern.loglevel	output	comment
[%level]	[INFO] [WARN] [ERROR]	value takes whatever space necessary
[%6level]	[ INFO] [ WARN] [ ERROR]	value takes at least 6 characters, right justified
[%-6level]	[INFO ] [WARN ] [ERROR ]	value takes at least 6 characters, left justified
[%.-2level]	[IN] [WA] [ER]	value takes no more than 2 characters, starting from the left
[%.2level]	[FO] [RN] [OR]	value takes no more than 2 characters, starting from the right

Example Override

must override entire CONSOLE_LOG_PATTERN system property to go further
- define it using logging.pattern.console property
too much to define on the command line
- move our definition to a profile-based property file

#application-layout.properties (1)

#default to time-of-day for the date
logging.pattern.dateformat=HH:mm:ss.SSS
#supply custom console layout
logging.pattern.console=%clr(%d{${LOG_DATEFORMAT_PATTERN:HH:mm:ss.SSS}}){faint} \
%clr(${LOG_LEVEL_PATTERN:%5p}) \
%clr(-){faint} \
%clr(%.27logger{40}){cyan}\
%clr(#){faint}\
%clr(%method){cyan}\ (2)
%clr(:){faint}\
%clr(%line){cyan} \ (2)
%m%n\
${LOG_EXCEPTION_CONVERSION_WORD:%wEx}}

logging.level.info.ejava.examples.app.config.logging.levels.LoggerLevels=INFO
logging.level.root=OFF

1	property file used when `layout` profile active
2	customization added `method` and `line` of caller — at a processing expense

Expensive Conversion Words

added two new helpful properties
- could be considered controversial
- require extra overhead to obtain that information from the JVM
%method (or %M) - name of method calling logger
%line (or %L) - line number of the file where logger call was made

The additional "expensive" fields are being used for console output for demonstrations using a demonstration profile. Consider your log information needs on a case-by-case basis and learn from this lesson what and how you can modify the logs for your specific needs. For example — to debug an error, you can switch to a more detailed and verbose profile without changing code.

Example Override Output

We can activate the profile and demonstrate the modified format using the following command.

Example Console Pattern Override Output

$ java -jar target/appconfig-logging-example-*-SNAPSHOT-bootexec.jar \
--spring.profiles.active=layout

14:25:58.428  INFO - logging.levels.LoggerLevels#run:14 info message
14:25:58.430  WARN - logging.levels.LoggerLevels#run:15 warn message
14:25:58.430 ERROR - logging.levels.LoggerLevels#run:16 error message

The coloring does not show up above so the image below provides a perspective of what that looks like.

Layout Fields

Please see the Logback Layouts Documentation for a detailed list of conversion words and how to optionally format them.

Loggers

We have demonstrated a fair amount capability thus far without having to know much about the internals of the logger framework. However, we need to take a small dive into the logging framework in order to explain some further concepts.

Logger Ancestry
Logger Inheritance
Appenders
Logger Additivity

Logger Tree

loggers are organized in hierarchy starting with a root logger called "root"
higher in the tree are ancestors and lower in the tree are descendants

Except for root, structure of loggers depends on hierarchical name of each logger

X, Y.3, and security are descendants and direct children of root
Y.3 is example of logger lacking an explicitly defined parent in hierarchy before reaching root. We can skip many levels between child and root and still retain same hierarchical name
X.1, X.2, and X.3 are descendants of X and root and direct children of X
Y.3.p is descendant of Y.3 and root and direct child of Y.3

Logger Inheritance

each logger has a set of allowed properties and may
- define its own value,
- inherit value of parent
- be assigned a default (as in the case for root)

Logger Threshold Level Inheritance

root, loggerX, security, loggerY.3, loggerX.1 and loggerX.3 set an explicit value for their threshold
loggerX.2 and loggerY.3.p inherit the threshold from their parent

Figure 2. Logger Level Inheritance

Logger Effective Threshold Level Inheritance

logger name	specified threshold	effective threshold
root	OFF	OFF
X	INFO	INFO
X.1	ERROR	ERROR
X.2		INFO
X.3	OFF	OFF
Y.3	WARN	WARN
Y.3.p		WARN
security	TRACE	TRACE

logger name

specified threshold

effective threshold

root

OFF

OFF

 INFO

 INFO

X.1

 ERROR

 ERROR

X.2

 INFO

X.3

OFF

OFF

Y.3

 WARN

 WARN

Y.3.p

 WARN

security

 TRACE

 TRACE

Example Logger Threshold Level Properties

These thresholds can be expressed in a property file.

application-tree.properties Snippet

logging.level.X=info
logging.level.X.1=error
logging.level.X.3=OFF
logging.level.security=trace
logging.level.Y.3=warn
logging.level.root=OFF

Example Logger Threshold Level Output

impact of logging level inheritance from ancestors to descendants

Effective Logger Theshold Level Output

$ java -jar target/appconfig-logging-example-*-SNAPSHOT-bootexec.jar \
--spring.profiles.active=tree

CONSOLE  05:58:14.956  INFO - X#run:25 X info
CONSOLE  05:58:14.959  WARN - X#run:26 X warn
CONSOLE  05:58:14.959 ERROR - X#run:27 X error
CONSOLE  05:58:14.960 ERROR - X.1#run:27 X.1 error (2)
CONSOLE  05:58:14.960  INFO - X.2#run:25 X.2 info (1)
CONSOLE  05:58:14.960  WARN - X.2#run:26 X.2 warn
CONSOLE  05:58:14.960 ERROR - X.2#run:27 X.2 error
CONSOLE  05:58:14.960  WARN - Y.3#run:26 Y.3 warn
CONSOLE  05:58:14.960 ERROR - Y.3#run:27 Y.3 error
CONSOLE  05:58:14.960  WARN - Y.3.p#run:26 Y.3.p warn (1)
CONSOLE  05:58:14.961 ERROR - Y.3.p#run:27 Y.3.p error
CONSOLE  05:58:14.961 TRACE - security#run:23 security trace (3)
CONSOLE  05:58:14.961 DEBUG - security#run:24 security debug
CONSOLE  05:58:14.962  INFO - security#run:25 security info
CONSOLE  05:58:14.962  WARN - security#run:26 security warn
CONSOLE  05:58:14.962 ERROR - security#run:27 security error

1	X.2 and Y.3.p exhibit the same threshold level as their parents X (`INFO`) and Y.3 (`WARN`)
2	X.1 (`ERROR`) and X.3 (`OFF`) override their parent threshold levels
3	security is writing all levels >= TRACE

Appenders

Loggers generate LoggerEvents but do not directly log anything
Appenders are responsible for taking LoggerEvent and producing a log
many types of appenders
- been working exclusively with ConsoleAppender thus far
- will work with some others before we are done
at this point — just know that a ConsoleLogger uses:
- an encoder to determine when to write messages to the log
- a layout to determine how to transform an individual LoggerEvent to a String
- a pattern when using a PatternLayout to define the transformation

Logger has N Appenders

Each of the loggers in our tree has the chance to have 0..N appenders.

Figure 3. Logger / Appender Relationship

Logger Configuration Files

use Logger Configuration File to define appender and assign to logger(s)
- Logback and Log4J2 both use XML for their primary definition
- well-known named configuration files found in root of classpath:
  - logback.xml or logback-spring.xml for Logback
  - log4j2.xml or log4j2-spring.xml for Log4J2

Spring Boot documentation recommends using -spring.xml suffixed files over provider default named files
- assures Spring Boot can enable all documented features
alternately, can use explicit location using logging.config property

application-tree.properties Reference

...
logging.config=classpath:/logging-configs/tree/logback-spring.xml (1)
...

1	an explicit property reference to the logging configuration file to use

Logback Root Configuration Element

XML file has root configuration element
- contains details of the appender(s) and logger(s)
- Docs
  - Spring Boot Configuration Documentation
  - Logback Configuration Documentation

logging-configs/tree/logback-spring.xml Configuration

<configuration debug="false"> (1)
   ...
</configuration>

1	`debug` attribute triggers logback debug

Retain Spring Boot Defaults

lose most/all default Spring Boot logging defaults when we define our own custom logging configuration file
restore them by adding an include.
- same file looked at earlier for definition of CONSOLE_LOG_PATTERN

logging-configs/tree/logback-spring.xml Retain Spring Boot Defaults

<configuration>
    <!-- bring in Spring Boot defaults for Logback -->
    <include resource="org/springframework/boot/logging/logback/defaults.xml"/>
   ...
</configuration>

Appender Configuration

Our example tree has three (3) appenders total. Each adds a literal string prefix so we know which appender is being called.

logging-configs/tree/logback-spring.xml Appenders

<!-- leverages what Spring Boot would have given us for console -->
<appender name="console" class="ch.qos.logback.core.ConsoleAppender">
    <encoder class="ch.qos.logback.classic.encoder.PatternLayoutEncoder"> (1)
        <pattern>CONSOLE  ${CONSOLE_LOG_PATTERN}</pattern> (2)
        <charset>utf8</charset>
    </encoder>
</appender>
<appender name="X-appender" class="ch.qos.logback.core.ConsoleAppender">
    <encoder>
        <pattern>X        ${CONSOLE_LOG_PATTERN}</pattern>
    </encoder>
</appender>
<appender name="security-appender" class="ch.qos.logback.core.ConsoleAppender">
    <encoder>
        <pattern>SECURITY ${CONSOLE_LOG_PATTERN}</pattern>
    </encoder>
</appender>

1	PatternLayoutEncoder is the default encoder
2	`CONSOLE_PATTERN_LAYOUT` is defined in included defaults.xml

This example forms the basis for demonstrating logger/appender assignment and appender additivity. ConsoleAppender is used in each case for ease of demonstration and not meant to depict a realistic configuration.

Appenders Attached to Loggers

each appender attached to single logger using appender-ref element
- console is attached to the root logger
- X-appender is attached to loggerX logger
- security-appender is attached to security logger

latching two child appender assignments within appenders profile

logging-configs/tree/logback-spring.xml Loggers

<springProfile name="appenders"> (1)
    <logger name="X">
        <appender-ref ref="X-appender"/> (2)
    </logger>

    <!-- this logger starts a new tree of appenders, nothing gets written to root logger -->
    <logger name="security" additivity="false">
        <appender-ref ref="security-appender"/>
    </logger>
</springProfile>

<root>
    <appender-ref ref="console"/>
</root>

1	using Spring Boot Logback extension to only enable appenders when profile active
2	appenders associated with logger using `appender-ref`

Appender Tree Inheritance

appenders are inherited from ancestor loggers unless overridden by property additivity=false

Figure 4. Example Logger Tree with Appenders

Appender Additivity Result

Table 2. Inheritance and Additivity Result
logger name	assigned threshold	assigned appender	effective threshold	effective appender
root	OFF	console	OFF	console
X	INFO	X-appender	INFO	console, X-appender
X.1	ERROR		ERROR	console, X-appender
X.2			INFO	console, X-appender
X.3	OFF		OFF	console, X-appender
Y.3	WARN		WARN	console
Y.3.p			WARN	console
security *additivity=false	TRACE	security-appender	TRACE	security-appender

Logger Inheritance Tree Output

$ java -jar target/appconfig-logging-example-*-SNAPSHOT-bootexec.jar \
--spring.profiles.active=tree,appenders

X        19:12:07.220  INFO - X#run:25 X info (1)
CONSOLE  19:12:07.220  INFO - X#run:25 X info (1)
X        19:12:07.224  WARN - X#run:26 X warn
CONSOLE  19:12:07.224  WARN - X#run:26 X warn
X        19:12:07.225 ERROR - X#run:27 X error
CONSOLE  19:12:07.225 ERROR - X#run:27 X error
X        19:12:07.225 ERROR - X.1#run:27 X.1 error
CONSOLE  19:12:07.225 ERROR - X.1#run:27 X.1 error
X        19:12:07.225  INFO - X.2#run:25 X.2 info
CONSOLE  19:12:07.225  INFO - X.2#run:25 X.2 info
X        19:12:07.225  WARN - X.2#run:26 X.2 warn
CONSOLE  19:12:07.225  WARN - X.2#run:26 X.2 warn
X        19:12:07.226 ERROR - X.2#run:27 X.2 error
CONSOLE  19:12:07.226 ERROR - X.2#run:27 X.2 error
CONSOLE  19:12:07.226  WARN - Y.3#run:26 Y.3 warn (2)
CONSOLE  19:12:07.227 ERROR - Y.3#run:27 Y.3 error (2)
CONSOLE  19:12:07.227  WARN - Y.3.p#run:26 Y.3.p warn
CONSOLE  19:12:07.227 ERROR - Y.3.p#run:27 Y.3.p error
SECURITY 19:12:07.227 TRACE - security#run:23 security trace (3)
SECURITY 19:12:07.227 DEBUG - security#run:24 security debug (3)
SECURITY 19:12:07.227  INFO - security#run:25 security info (3)
SECURITY 19:12:07.228  WARN - security#run:26 security warn (3)
SECURITY 19:12:07.228 ERROR - security#run:27 security error (3)

1	log messages written to logger X and descendants are written to console and X-appender appenders
2	log messages written to logger Y.3 and descendants are written only to console appender
3	log messages written to security logger are written only to security appender because of `additivity=false`

Mapped Diagnostic Context

focus thus far has been on calls made within the code
- without much concern about overall context in which calls were made

multi-threaded, multi-user environment have additional context information
- e.g., userId and transactionId
SLF4J and logging implementations support call context information using Mapped Diagnostic Context (MDC) and the MDC class
- essentially a ThreadLocal map of strings assigned to current thread
- MDC values commonly set and cleared in container filters that fire before/after client calls executed

MDC Example

run() method playing role of "container filter" — setting and clearing MDC
- setting a "user" and "requestId" key
doWork() method is oblivious of MDC — simply logs start and end of work

MDC Example

import org.slf4j.MDC;
...
public class MDCLogger implements CommandLineRunner {
    private static final String[] USERS = new String[]{"jim", "joe", "mary"};
    private static final SecureRandom r = new SecureRandom();

    @Override
    public void run(String... args) throws Exception {
        for (int i=0; i<5; i++) {
            String user = USERS[r.nextInt(USERS.length)];
            MDC.put("user", user); (1)
            MDC.put("requestId", Integer.toString(r.nextInt(99999)));
            doWork();
            MDC.clear(); (2)
            doWork();
        }
    }

    public void doWork() {
        log.info("starting work");
        log.info("finished work");
    }
}

1	`run()` method simulates container filter setting context properties before call executed
2	context properties removed after all calls for the context complete

MDC Example Pattern

add %mdc (or %X) conversion word to appender pattern to make use of new "user" and "requestId" properties for current thread

Adding MDC Properties to Pattern

#application-mdc.properties
logging.pattern.console=%date{HH:mm:ss.SSS} %-5level [%-9mdc{user:-anonymous}][%5mdc{requestId}] %logger{0} - %msg%n

%mdc{user:-anonymous} - the identity of the user making the call or "anonymous" if not supplied
%mdc{requestId} - the specific request made or blank if not supplied

MDC Example Output

tracking who made work request and boundary of each request — both identified and anonymous

MDC Example Output

$ java -jar target/appconfig-logging-example-*-SNAPSHOT-bootexec.jar --spring.profiles.active=mdc

17:11:59.100 INFO  [jim      ][61165] MDCLogger - starting work
17:11:59.101 INFO  [jim      ][61165] MDCLogger - finished work
17:11:59.101 INFO  [anonymous][     ] MDCLogger - starting work
17:11:59.101 INFO  [anonymous][     ] MDCLogger - finished work
17:11:59.101 INFO  [mary     ][ 8802] MDCLogger - starting work
17:11:59.101 INFO  [mary     ][ 8802] MDCLogger - finished work
17:11:59.101 INFO  [anonymous][     ] MDCLogger - starting work
17:11:59.101 INFO  [anonymous][     ] MDCLogger - finished work
17:11:59.101 INFO  [mary     ][86993] MDCLogger - starting work
17:11:59.101 INFO  [mary     ][86993] MDCLogger - finished work
17:11:59.101 INFO  [anonymous][     ] MDCLogger - starting work
17:11:59.101 INFO  [anonymous][     ] MDCLogger - finished work
17:11:59.102 INFO  [mary     ][67677] MDCLogger - starting work
17:11:59.102 INFO  [mary     ][67677] MDCLogger - finished work
17:11:59.102 INFO  [anonymous][     ] MDCLogger - starting work
17:11:59.102 INFO  [anonymous][     ] MDCLogger - finished work
17:11:59.102 INFO  [jim      ][25693] MDCLogger - starting work
17:11:59.102 INFO  [jim      ][25693] MDCLogger - finished work
17:11:59.102 INFO  [anonymous][     ] MDCLogger - starting work
17:11:59.102 INFO  [anonymous][     ] MDCLogger - finished work

Like standard ThreadLocal variables, child threads do not inherit values of parent thread. Each thread will maintain its own MDC properties.

Clearing MDC Context

We are responsible for setting the MDC context variables as well as clearing them when the work is complete.

One way to do that is using a finally block and manually calling MDC.clear()

try {
    MDC.put("user", user); (1)
    MDC.put("requestId", requestId);
    doWork();
} finally {
    MDC.clear();
}

Another is by using a try-with-closable and have the properties automatically cleared when the try block finishes.

try (MDC.MDCCloseable mdc = MDC.putCloseable("user", user);
     MDC.MDCCloseable mdc = MDC.putCloseable("requestId", requestId) {
    doWork();
}

Markers

SLF4J and logging implementations support markers
Unlike MDC data — which quietly sit in the background — markers are optionally supplied on a per-call basis
- trigger reporting events to appenders — e.g., flush log, send the e-mail
- implement additional severity levels — e.g., log.warn(FLESH_WOUND,"come back here!") versus log.warn(FATAL,"ouch!!!")

The additional functionality commonly is implemented through the use of filters assigned to appenders looking for these Markers.

To me having triggers initiated by the logging statements does not sound appropriate (but still could be useful). However, when the thought of filtering comes up — I think of cases where we may want to better classify the subject(s) of the statement so that we have more to filter on when configuring appenders. More than once I have been in a situation where adjusting the verbosity of a single logger was not granular enough to provide an ideal result.

Marker Class

Markers have a single property called name and an optional collection of child Markers
- allow parent marker to represent one or more values
Appender filters test Markers using the contains() method to determine if the parent or any children are the targeted value
Markers are obtained through the MarkerFactory
- caches managed Markers it creates
- can make detached Markers so they can be uniquely added to separate parents

Marker Example

The following simple example issues two log events. The first is without a Marker and the second with a Marker that represents the value ALARM.

Marker Example

import org.slf4j.Marker;
import org.slf4j.MarkerFactory;
...
public class MarkerLogger implements CommandLineRunner {
    private static final Marker ALARM = MarkerFactory.getMarker("ALARM"); (1)

    @Override
    public void run(String... args) throws Exception {
        log.warn("non-alarming warning statement"); (2)
        log.warn(ALARM,"alarming statement"); (3)
    }
}

1	created single managed marker
2	no marker added to logging call
3	marker added to logging call to trigger something special about this call

Marker Appender Filter Example

Alarm Appender

    <appender name="alarms" class="ch.qos.logback.core.ConsoleAppender">
        <filter class="ch.qos.logback.core.filter.EvaluatorFilter">
            <evaluator name="ALARM" class="ch.qos.logback.classic.boolex.OnMarkerEvaluator">
                <marker>ALARM</marker>
            </evaluator>
            <onMatch>ACCEPT</onMatch>
            <onMismatch>DENY</onMismatch>
        </filter>
        <encoder>
            <pattern>%red(ALARM&gt;&gt;&gt; ${CONSOLE_LOG_PATTERN})</pattern>
        </encoder>
    </appender>

All Event Appender

    <appender name="console" class="ch.qos.logback.core.ConsoleAppender">
        <encoder>
            <pattern>${CONSOLE_LOG_PATTERN}</pattern>
        </encoder>
    </appender>

Both Appenders added to root Logger

<configuration>
    <include resource="org/springframework/boot/logging/logback/defaults.xml"/>
...
    <root>
        <appender-ref ref="console"/>
        <appender-ref ref="alarms"/>
    </root>
</configuration>

Marker Example Result

$ java -jar target/appconfig-logging-example-*-SNAPSHOT-bootexec.jar \
--spring.profiles.active=markers

18:06:52.135 WARN  [] MarkerLogger - non-alarming warning statement (1)
18:06:52.136 WARN  [ALARM] MarkerLogger - alarming statement (1)
ALARM>>> 18:06:52.136 WARN  [ALARM] MarkerLogger - alarming statement (2)

1	non-ALARM and ALARM events are written to the console appender
2	ALARM event is also written to alarm appender

File Logging

console logging simple to demonstrate and to try out for yourself
more significant application will need to write this information somewhere to store and analyze
Spring Boot’s default file appender
- not active by default
- triggered by specifying the log’s file name or path

Trigger FILE Appender

$ java -jar target/appconfig-logging-example-*-SNAPSHOT-bootexec.jar \
--spring.profiles.active=levels \
--logging.file.name="mylog.log" (1)

$ ls ./mylog.log (2)
./mylog.log

1	adding this property adds file logging to default configuration
2	this expressed logfile will be written to `mylog.log` in current directory

root Logger Appenders

appender additivity — multiple appenders can be associated with the same logger (root logger in this case)
- produces log file in addition to our console output

Figure 5. root Logger Appenders

FILE Appender Output

file is being written to current directory using "mylog.log" filename

FILE Appender File Output

$ cat mylog.log (1)
2020-03-29 07:14:33.533  INFO 90958 --- [main] i.e.e.a.c.logging.levels.LoggerLevels    : info message
2020-03-29 07:14:33.542  WARN 90958 --- [main] i.e.e.a.c.logging.levels.LoggerLevels    : warn message
2020-03-29 07:14:33.542 ERROR 90958 --- [main] i.e.e.a.c.logging.levels.LoggerLevels    : error message

1	written to file specified by `logging.file` property

file and parent directories will be created if they do not exist
will append to an existing file if it already exists

FILE Appender Defaults to Append Mode

$ cat mylog.log
2020-03-29 07:14:33.533  INFO 90958 --- [main] i.e.e.a.c.logging.levels.LoggerLevels    : info message
2020-03-29 07:14:33.542  WARN 90958 --- [main] i.e.e.a.c.logging.levels.LoggerLevels    : warn message
2020-03-29 07:14:33.542 ERROR 90958 --- [main] i.e.e.a.c.logging.levels.LoggerLevels    : error message
2020-03-29 07:15:00.338  INFO 91090 --- [main] i.e.e.a.c.logging.levels.LoggerLevels    : info message (1)
2020-03-29 07:15:00.342  WARN 91090 --- [main] i.e.e.a.c.logging.levels.LoggerLevels    : warn message
2020-03-29 07:15:00.342 ERROR 91090 --- [main] i.e.e.a.c.logging.levels.LoggerLevels    : error message

1	messages from second execution appended to same log

Spring Boot FILE Appender Definition

Spring Boot’s Logback FILE Appender
- Logback RollingFileAppender
- Logback SizeAndTimeBasedRollingPolicy

Spring Boot Default FILE Appender Definition

<appender name="FILE"
          class="ch.qos.logback.core.rolling.RollingFileAppender"> (1)
    <filter class="ch.qos.logback.classic.filter.ThresholdFilter">
        <level>${FILE_LOG_THRESHOLD}</level>
    </filter>
    <encoder>
        <pattern>${FILE_LOG_PATTERN}</pattern>
        <charset>${FILE_LOG_CHARSET}</charset>
    </encoder>
    <file>${LOG_FILE}</file>
    <rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy"> (2)
        <fileNamePattern>${LOGBACK_ROLLINGPOLICY_FILE_NAME_PATTERN:-${LOG_FILE}.%d{yyyy-MM-dd}.%i.gz}</fileNamePattern>
        <cleanHistoryOnStart>${LOGBACK_ROLLINGPOLICY_CLEAN_HISTORY_ON_START:-false}</cleanHistoryOnStart>
        <maxFileSize>${LOGBACK_ROLLINGPOLICY_MAX_FILE_SIZE:-10MB}</maxFileSize>
        <totalSizeCap>${LOGBACK_ROLLINGPOLICY_TOTAL_SIZE_CAP:-0}</totalSizeCap>
        <maxHistory>${LOGBACK_ROLLINGPOLICY_MAX_HISTORY:-7}</maxHistory>
    </rollingPolicy>
</appender>

1	performs file rollover functionality based on configured policy
2	specifies policy and policy configuration to use

RollingFileAppender

The Logback RollingFileAppender will:

write log messages to a specified file — and at some point, switch to writing to a different file
use a triggering policy to determine the point in which to switch files (i.e., "when it will occur")
use a rolling policy to determine how the file switchover will occur (i.e., "what will occur")
use a single policy for both if the rolling policy implements both policy interfaces
use file append mode by default

The rollover settings/state is evaluated no sooner than once a minute. If you set the maximum sizes to small amounts and log quickly for test/demonstration purposes, you will exceed your defined size limits until the recheck timeout has expired.

SizeAndTimeBasedRollingPolicy

The Logback SizeAndTimeBasedRollingPolicy will:

trigger a file switch when the current file reaches a maximum size
trigger a file switch when the granularity of the primary date (%d) pattern in the file path/name would rollover to a new value
supply a name for the old/historical file using a mandatory date (%d) pattern and index (%i)
define a maximum number of historical files to retain
define a total size to allocate to current and historical files

FILE Appender Properties

name description default

logging.file.path

full or relative path of directory written to — ignored when logging.file.name provided

logging.file.name

full or relative path of filename written to — may be manually built using ${logging.file.path}

${logging.file.path}/spring.log

logging.pattern.rolling-file-name

pattern expression for historical file — must include a date and index — may express compression

${logging.file.name}.%d{yyyy-MM-dd}.%i.gz

logging.logback.rollingpolicy.max-file-size

maximum size of log before changeover — must be less than total-size-cap

10MB

logging.logback.rollingpolicy.max-history

maximum number of historical files to retain when changing over because of date criteria

logging.logback.rollingpolicy.total-size-cap

maximum amount of total space to consume — must be greater than max-size

(no limit)

Invalid Logger File Property

If file logger property value is invalid, the application will run without the FILE appender activated.

logging.file.path

If we specify only the logging.file.path, the filename will default to spring.log and will be written to the directory path we supply.

logging.file.path Example

$ java -jar target/appconfig-logging-example-*-SNAPSHOT-bootexec.jar \
--logging.file.path=target/logs (1)
...
$ ls target/logs (2)
spring.log

1	specifying `logging.file.path` as `target/logs`
2	produces a `spring.log` in that directory

logging.file.name

If we specify only the logging.file.name, the file will be written to the filename and directory we explicitly supply.

logging.file.name Example

$ java -jar target/appconfig-logging-example-*-SNAPSHOT-bootexec.jar \
--logging.file.name=target/logs/mylog.log (1)
...
$ ls target/logs (2)
mylog.log

1	specifying a `logging.file.name`
2	produces a logfile with that path and name

logging.logback.rollingpolicy.max-file-size Trigger

trigger to change to the next file
satisfied when the current logfile reaches this value — default is 10MB
example sets maximum to 9400 Bytes

Evaluation is no more often than 1 minute.

logging.logback.rollingpolicy.max-file-size Example

java -jar target/appconfig-logging-example-*-SNAPSHOT-bootexec.jar \
--spring.profiles.active=rollover \
--logging.file.name=target/logs/mylog.log \
--logging.pattern.rolling-file-name='${logging.file.name}.%d{yyyy-MM-dd}.%i.log' \
--logging.logback.rollingpolicy.max-file-size=9400B (1)
...
ls -ltrh target/logs/

-rw-r--r--  1 jim  staff   9.4K Aug  9 11:29 mylog.log.2024-08-09.0.log (3)
-rw-r--r--  1 jim  staff   9.5K Aug  9 11:31 mylog.log.2024-08-09.1.log (2)
-rw-r--r--  1 jim  staff   1.6K Aug  9 11:31 mylog.log (1)

1	`logging.logback.rollingpolicy.max-file-size` limits the size of the current logfile
2	historical logfiles renamed according to `logging.pattern.rolling-file-name` pattern
3	file size is evaluated each minute and archived when satisfied

logging.pattern.rolling-file-name

There are several aspects of logging.pattern.rolling-file-name to be aware of

%d timestamp pattern and %i index are required. The FILE appender will either be disabled (for %i) or the application startup will fail (for %d) if not specified
the timestamp pattern directly impacts changeover when there is a value change in the result of applying the timestamp pattern. Many of my examples here use a pattern that includes HH:mm:ss just for demonstration purposes. A more common pattern would be by date only.
the index is used when the logging.logback.rollingpolicy.max-file-size triggers the changeover and we already have a historical name with the same timestamp.
the number of historical files is throttled using logging.logback.rollingpolicy.max-history only when index is used and not when file changeover is due to logging.logback.rollingpolicy.max-file-size
the historical file will be compressed if gz is specified as the suffix

logging.pattern.rolling-file-name Default Value

${logging.file.name}.%d{yyyy-MM-dd}.%i.gz

%d timestamp pattern and %i index are required
%d timestamp pattern directly impacts when file changeover will occur when still below logging.logback.rollingpolicy.max-file-size
- changeover occurs when there is a value change in result of applying timestamp pattern
%i index used when logging.logback.rollingpolicy.max-file-size triggers changeover and we already have historical name with same timestamp
number of historical files throttled using logging.logback.rollingpolicy.max-history only when %i index used and not when file changeover is due to logging.logback.rollingpolicy.max-file-size
historical file will be compressed if gz is specified as the suffix

Timestamp Rollover Example

$ java -jar target/appconfig-logging-example-*-SNAPSHOT-bootexec.jar \
--spring.profiles.active=rollover \
--logging.file.name=target/logs/mylog.log \
--logging.pattern.rolling-file-name='${logging.file.name}.%d{yyyy-MM-dd-HH:mm:ss}.%i'.log (1)
...
$ ls -ltrh target/logs

total 64
-rw-r--r--  1 jim  staff    79B Aug  9 12:04 mylog.log.2024-08-09-12:04:54.0.log
-rw-r--r--  1 jim  staff    79B Aug  9 12:04 mylog.log.2024-08-09-12:04:55.0.log
-rw-r--r--  1 jim  staff    79B Aug  9 12:04 mylog.log.2024-08-09-12:04:56.0.log
-rw-r--r--  1 jim  staff    79B Aug  9 12:04 mylog.log.2024-08-09-12:04:57.0.log
-rw-r--r--  1 jim  staff    79B Aug  9 12:04 mylog.log.2024-08-09-12:04:58.0.log
-rw-r--r--  1 jim  staff    79B Aug  9 12:04 mylog.log.2024-08-09-12:04:59.0.log
-rw-r--r--  1 jim  staff    79B Aug  9 12:05 mylog.log.2024-08-09-12:05:00.0.log
-rw-r--r--  1 jim  staff    79B Aug  9 12:05 mylog.log


$ file target/logs/mylog.log.2024-08-09-12\:04\:54.0.log (2)
target/logs/mylog.log.2024-08-09-12:04:54.0.log: ASCII text

1	`logging.pattern.rolling-file-name` pattern triggers changeover at the seconds boundary
2	historical logfiles are left uncompressed because of `.log` name suffix specified

Using a date pattern to include minutes and seconds is just for demonstration and learning purposes. Most patterns would be daily.

History Compression Example

$ java -jar target/appconfig-logging-example-*-SNAPSHOT-bootexec.jar \
--spring.profiles.active=rollover \
--logging.file.name=target/logs/mylog.log \
--logging.pattern.rolling-file-name='${logging.file.name}.%d{yyyy-MM-dd-HH:mm}.%i'.gz (1)
...
$ ls -ltrh target/logs

total 48
-rw-r--r--  1 jim  staff   193B Aug  9 13:39 mylog.log.2024-08-09-13:38.0.gz (1)
-rw-r--r--  1 jim  staff   534B Aug  9 13:40 mylog.log.2024-08-09-13:39.0.gz
-rw-r--r--  1 jim  staff   540B Aug  9 13:41 mylog.log.2024-08-09-13:40.0.gz
-rw-r--r--  1 jim  staff   528B Aug  9 13:42 mylog.log.2024-08-09-13:41.0.gz
-rw-r--r--  1 jim  staff   539B Aug  9 13:43 mylog.log.2024-08-09-13:42.0.gz
-rw-r--r--  1 jim  staff   1.7K Aug  9 13:43 mylog.log

$ file target/logs/mylog.log.2024-08-09-13\:38.0.gz
target/logs/mylog.log.2024-08-09-13:38.0.gz: gzip compressed data, original size modulo 2^32 1030

1	historical logfiles are compressed when pattern uses a `.gz` suffix

logging.logback.rollingpolicy.max-history Example

constrains number of files created for independent timestamps

Max History Example

$ java -jar target/appconfig-logging-example-*-SNAPSHOT-bootexec.jar \
--spring.profiles.active=rollover \
--logging.file.name=target/logs/mylog.log \
--logging.pattern.rolling-file-name='${logging.file.name}.%d{yyyy-MM-dd-HH:mm:ss}.%i'.log \ --logging.logback.rollingpolicy.max-history=2
...
$ ls -ltrh target/logs

total 24
-rw-r--r--  1 jim  staff    80B Aug  9 12:15 mylog.log.2024-08-09-12:15:31.0.log (1)
-rw-r--r--  1 jim  staff    80B Aug  9 12:15 mylog.log.2024-08-09-12:15:32.0.log (1)
-rw-r--r--  1 jim  staff    80B Aug  9 12:15 mylog.log

1	specifying `logging.logback.rollingpolicy.max-history` limited number of historical logfiles. Oldest files exceeding the criteria are deleted.

logging.logback.rollingpolicy.max-history property does not seem to apply to files terminated because of size. For that, we can use logging.logback.rollingpolicy.total-size-cap.

logging.logback.rollingpolicy.total-size-cap Index Example

example triggers file changeover every 1000 Bytes and makes use of index

Total Size Limit (with Index) Example

$ java -jar target/appconfig-logging-example-*-SNAPSHOT-bootexec.jar \
--spring.profiles.active=rollover \
--logging.file.name=target/logs/mylog.log \
--logging.logback.rollingpolicy.max-file-size=1000 \
--logging.pattern.rolling-file-name='${logging.file.name}.%d{yyyy-MM-dd}.%i'.log \
--logging.logback.rollingpolicy.total-size-cap=10000 (1)
...
$ ls -ltr target/logs

total 40                                                               (2)
-rw-r--r--  1 jim  staff   4.7K Aug  9 12:37 mylog.log.2024-08-09.10.log (1)
-rw-r--r--  1 jim  staff   4.7K Aug  9 12:38 mylog.log.2024-08-09.11.log (1)
-rw-r--r--  1 jim  staff   2.7K Aug  9 12:39 mylog.log (1)

1	`logging.logback.rollingpolicy.total-size-cap` constrains current plus historical files retained
2	historical files with indexes 1 thru 9 were deleted to stay below file size limit

logging.logback.rollingpolicy.total-size-cap no Index Example

example triggers file changeover every second — makes no use of the index

Total Size Limit (without Index) Example

$ java -jar target/appconfig-logging-example-*-SNAPSHOT-bootexec.jar \
--spring.profiles.active=rollover \
--logging.file.name=target/logs/mylog.log \
--logging.logback.rollingpolicy.max-file-size=100 \
--logging.pattern.rolling-file-name='${logging.file.name}.%d{yyyy-MM-dd-HH:mm:ss}.%i'.log \
--logging.logback.rollingpolicy.max-history=200 \
--logging.logback.rollingpolicy.total-size-cap=500 (1)
...
$ ls -ltrh target/logs

total 56
-rw-r--r--  1 jim  staff    79B Aug  9 12:44 mylog.log.2024-08-09-12:44:33.0.log (1)
-rw-r--r--  1 jim  staff    79B Aug  9 12:44 mylog.log.2024-08-09-12:44:34.0.log (1)
-rw-r--r--  1 jim  staff    79B Aug  9 12:44 mylog.log.2024-08-09-12:44:35.0.log (1)
-rw-r--r--  1 jim  staff    79B Aug  9 12:44 mylog.log.2024-08-09-12:44:36.0.log (1)
-rw-r--r--  1 jim  staff    79B Aug  9 12:44 mylog.log.2024-08-09-12:44:37.0.log (1)
-rw-r--r--  1 jim  staff    79B Aug  9 12:44 mylog.log.2024-08-09-12:44:38.0.log (1)
-rw-r--r--  1 jim  staff    80B Aug  9 12:44 mylog.log (1)

1	`logging.logback.rollingpolicy.total-size-cap` constrains current plus historical files retained

The logging.logback.rollingpolicy.total-size-cap value — if specified — must be larger than the logging.logback.rollingpolicy.max-file-size constraint. Otherwise the file appender will not be activated.

Custom Configurations

good default logging capability
- configurable
for cases when this is not enough:
- detailed XML Logback and Log4J2 configurations can be specified
  - loggers
  - appenders
  - filters
  - etc. of nearly unlimited power
- provided include files supply starting point for custom configurations
  - without giving up most defaults

Logback Configuration Customization

Spring Boot performs the configuration manually through code
set of XML includes supplied simulate most of what setup code performs
- create a logback-spring.xml file with a parent configuration element
  - place in root of application archive (i.e., src/main/resources of source tree)
- include one or more of the provided XML includes

Provided Logback Includes

defaults.xml - defines the logging configuration defaults we have been working with
base.xml - defines root logger with CONSOLE and FILE appenders we have discussed
- puts you at the point of the out-of-the-box configuration
console-appender.xml - defines the CONSOLE appender we have been working with
- uses the CONSOLE_LOG_PATTERN
file-appender.xml - defines the FILE appender we have been working with
- uses the RollingFileAppender with FILE_LOG_PATTERN and SizeAndTimeBasedRollingPolicy

These files provide an XML representation of what Spring Boot configures with straight Java code. There are minor differences (e.g., enable/disable FILE Appender) between using the supplied XML files and using the out-of-the-box defaults.

Customization Example: Turn off Console Logging

example turns off console logging and leaves file logging enabled

logging-configs/no-console/logback-spring.xml

<!-- logging-configs/no-console/logback-spring.xml (1)
    Example Logback configuration file to turn off CONSOLE Appender and retain all other
    FILE Appender default behavior.
-->
<configuration>
    <include resource="org/springframework/boot/logging/logback/defaults.xml"/> (2)
    <property name="LOG_FILE" value="${LOG_FILE:-${LOG_PATH:-${LOG_TEMP:-${java.io.tmpdir:-/tmp}}}/spring.log}"/> (3)
    <include resource="org/springframework/boot/logging/logback/file-appender.xml"/> (4)

    <root>
        <appender-ref ref="FILE"/> (5)
    </root>
</configuration>

1	a logback-spring.xml file has been created to host the custom configuration
2	the standard Spring Boot defaults are included
3	`LOG_FILE` defined using the original expression from Spring Boot `base.xml`
4	the standard Spring Boot FILE appender is included
5	only the FILE appender is assigned to our logger(s)

LOG_FILE Property Definition

The only complicated part is what I copy/pasted from base.xml to express the LOG_FILE property used by the included FILE appender:

LOG_FILE Property Definition

<property name="LOG_FILE"
value="${LOG_FILE:-${LOG_PATH:-${LOG_TEMP:-${java.io.tmpdir:-/tmp}}}/spring.log}"/>

use the value of ${LOG_FILE} if that is defined
otherwise use the filename spring.log and for the path
- use ${LOG_PATH} if that is defined
- otherwise use ${LOG_TEMP} if that is defined
- otherwise use ${java.io.tmpdir} if that is defined
- otherwise use /tmp

Customization Example: Leverage Restored Defaults

example shows provided FILE Appender defaults restored

Example with Default Logfile

java -jar target/appconfig-logging-example-*-SNAPSHOT-bootexec.jar  \
--logging.config=src/main/resources/logging-configs/no-console/logback-spring.xml
(no console output)

$ ls -ltr $TMPDIR/spring.log  (1)
-rw-r--r--  1 jim  staff  67238 Apr  2 06:42 /var/folders/zm/cskr47zn0yjd0zwkn870y5sc0000gn/T//spring.log

1	logfile written to restored default `${java.io.tmpdir}/spring.log`

Customization Example: Provide Override

example specifies override for the logfile to use
expressed exactly as we did earlier with the default configuration

Example with Specified Logfile

java -jar target/appconfig-logging-example-*-SNAPSHOT-bootexec.jar \
--logging.config=src/main/resources/logging-configs/no-console/logback-spring.xml \
--logging.file.name="target/logs/mylog.log" (2)
(no console output)

$ ls -ltr target/logs (1)

total 136
-rw-r--r--  1 jim  staff  67236 Apr  2 06:46 mylog.log (1)

1	logfile written to `target/logs/mylog.log`
2	defined using `logging.file.name`

Spring Profiles

can easily use Spring profiles within configuration file

Example Profile Use

<springProfile name="appenders"> (1)
    <logger name="X">
        <appender-ref ref="X-appender"/>
    </logger>

    <!-- this logger starts a new tree of appenders, nothing gets written to root logger -->
    <logger name="security" additivity="false">
        <appender-ref ref="security-appender"/>
    </logger>
</springProfile>

1	elements are activated when `appenders` profile is activated

See Profile-Specific Configuration for more examples involving multiple profile names and boolean operations.

Summary

In this module we:

made a case for the value of logging

demonstrated how logging frameworks are much better than System.out logging techniques
discussed the different interface, adapter, and implementation libraries involved with Spring Boot logging
learned how the interface of the logging framework is separate from the implementation
learned to log information at different severity levels using loggers
learned how to write logging statements that can be efficiently executed when disabled
learned how to establish a hierarchy of loggers
learned how to configure appenders and associate with loggers
learned how to configure pattern layouts
learned how to configure the FILE Appender
looked at additional topics like Mapped Data Context (MDC) and Markers that can augment standard logging events

A substantial start. Many more topics exist related to distributing, structured formatting (e.g., JSON), and accessing logs can be added by you in a straight forward manner by following the core concepts of this lesson.