Logging

Logging has many uses within an application — spanning:

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:

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

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

The student will learn:

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

System.out was built into Java from day 1

System.out writes to wherever System.out references. The default is stdout. You have seen many earlier examples just like the following.

The example SystemOutCommand component above outputs the following statement when called with the system-out profile active (using spring.profiles.active property).

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

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

The following output shows that even code using the JUL interface will be integrated into our standard Spring Boot logs.

Naming loggers after the fully qualified class name is so common that the Lombok library was able to successfully take advantage of that fact to automate the tasks for adding the imports and declaring the Logger during Java compilation.

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

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

Now lets say we create a message to log through straight, eager String concatenation. What is wong here?

Assuming the information from the toString() call is valuable and needed when we have DEBUG enabled — a verbosity check is one common solution we can use to determine if the end result is worth the work. There are two very similar ways we can do this.

The first way is to dynamically check the current threshold level of the logger within the code and only execute if the requested severity level is enabled. We are still going to build the relatively expensive String when DEBUG is enabled but we are going to save all that processing time when it is not enabled. This overall approach of using a code block works best when creating the message requires multiple lines of code. This specific technique of dynamically checking is suitable when there are very few checks within a class.

SLF4J API offers another solution that removes the need for the if clause — thus cleaning your code of those extra conditional blocks. The SLF4J Logger interface has a format and args variant for each verbosity level call that permits the threshold to be consulted prior to converting any of the parameters to a String.

The format specification uses a set of curly braces ("{}") to express an insertion point for an ordered set of arguments. There are no format options. It is strictly a way to lazily call toString() on each argument and insert the result.

The second set of results are from logging threshold set to DEBUG. You can see that causes the relatively expensive toString() to be called for each of the four techniques shown with somewhat equal results. I would not put too much weight on a few milliseconds difference between the calls here except to know that neither provide a noticeable processing delay over the other when the logging threshold has been met.

When we run the example, note that the message is printed in its normal location and a stack trace is added for the supplied Exception parameter.

Note that you can continue to use parameterized logging with Exceptions. The message passed in above was actually a format with no parameters. The snippet below shows a format with two parameters and an Exception.

The first two parameters are used in the formatting of the core message. The last Exception parameters is printed as a regular exception.

Spring Boot comes out of the box with a slightly more verbose default pattern expressed with the CONSOLE_LOG_PATTERN property. The following snippet depicts the information found within the Logback property definition — with some new lines added in to help read it.

You should see some familiar conversion words from my earlier pattern example. However, there are some additional conversion words used as well. Again, keep the Logback Conversion Documentation close by to lookup any additional details.

We will take a look at conditional variable substitution in a moment. This next example reverts to the default CONSOLE_LOG_PATTERN.

Spring Boot defines color coding for the console that is not visible in the text of this document. The color for severity level is triggered by the level — red for ERROR, yellow for WARN, and green for the other three levels.

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

Variables can be defined with default values in the event they are not defined. In the following expression ${LOG_DATEFORMAT_PATTERN:-yyyy-MM-dd HH:mm:ss.SSS}:

As we saw from a peek at the Spring Boot CONSOLE_LOG_PATTERN default definition, we can change the format of the timestamp using the LOG_DATEFORMAT_PATTERN system property. That system property can flexibly be set using the logging.pattern.dateformat property. See the Spring Boot Documentation for information on this and other properties. The following example shows setting that property using a command line argument.

We also saw from the default definition of CONSOLE_LOG_PATTERN that the severity level of the output can be changed using the LOG_LEVEL_PATTERN system property. That system property can be flexibly set with the logging.pattern.level property. The following example shows setting the format to a single character, left justified. Therefore, we can map INFO⇒ I, WARN⇒ W, and ERROR⇒ E.

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:

I added two new helpful properties that could be considered controversial because they require extra overhead to obtain that information from the JVM. The technique has commonly involved throwing and catching an exception internally to determine the calling location from the self-generated stack trace:

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

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

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

Loggers are organized in a hierarchy starting with a root logger called "root". As you would expect, higher in the tree are considered ancestors and lower in the tree are called descendants.

Except for root, the ancestor/descendant structure of loggers depends on the hierarchical name of each logger. Based on the loggers in the diagram

Each logger has a set of allowed properties. Each logger may define its own value for those properties, inherit the value of its parent, or be assigned a default (as in the case for root).

The first inheritance property we will look at is a familiar one to you — severity threshold level. As the diagram shows

The following table shows the specified and effective values applied to each logger for their threshold.

These thresholds can be expressed in a property file.

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

To date we have been able to work mostly with Spring Boot properties when using loggers. However, we will need to know a few things about the Logger Configuration File in order to define an appender and assign it to logger(s). We will start with how the logger configuration is found.

Logback and Log4J2 both use XML as their primary definition language. Spring Boot will automatically locate a well-known named configuration file in the root of the classpath:

Spring Boot documentation recommends using the -spring.xml suffixed files over the provider default named files in order for Spring Boot to assure that all documented features can be enabled. Alternately, we can explicitly specify the location using the logging.config property to reference anywhere in the classpath or file system.

The XML file has a root configuration element which contains details of the appender(s) and logger(s). See the Spring Boot Configuration Documentation and the Logback Configuration Documentation for details on how to configure.

We will lose most/all of the default Spring Boot customizations for logging when we define our own custom logging configuration file. We can restore them by adding an include. This is that same file that we looked at earlier for the definition of CONSOLE_LOG_PATTERN.

These appenders, in addition to level, are inherited from ancestor to descendant unless there is an override defined by the property additivity=false.

To make use of the new "user" and "requestId" properties of the thread, we can add the %mdc (or %X) conversion word to the appender pattern as follows.

The following is an example of running the MDC example. Users are randomly selected and work is performed for both identified and anonymous users. This allows us to track who made the work request and sort out the results of each work request.

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

Markers have a single property called name and an optional collection of child Markers. The name and collection properties allow the 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 — which caches the Markers it creates unless requested to make them detached so they can be uniquely added to separate parents.

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.

The following shows the results of running the marker example — where both events are written to the console appender and only the log event with the ALARM Marker is written to the alarm appender.

As we saw earlier with appender additivity, multiple appenders can be associated with the same logger (root logger in this case). With the trigger property supplied, a file-based appender is added to the root logger to produce a log file in addition to our console output.

Under these simple conditions, a file is produced in the current directory with the specified mylog.log filename and the following contents.

The file and parent directories will be created if they do not exist. The default definition of the appender will append to an existing file if it already exists. Therefore — if we run the example a second time we get a second set of messages in the file.

If we take a look at the definition for Spring Boot’s Logback FILE Appender, we can see that it is a Logback RollingFileAppender with a Logback SizeAndTimeBasedRollingPolicy.

The Logback RollingFileAppender will:

The Logback SizeAndTimeBasedRollingPolicy will:

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.

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

One trigger for changing over to the next file is logging.logback.rollingpolicy.max-file-size. Note this property is Logback-specific. The condition is satisfied when the current logfile reaches this value. The default is 10MB.

The following example changes that to 9400 Bytes. Once each instance of logging.file.name reached the logging.logback.rollingpolicy.max-file-size, it is compressed and moved to a filename with the pattern from logging.pattern.rolling-file-name. I picked 9400 Bytes based on the fact the application wrote 4800 Bytes each minute. The file size would be evaluated each minute and exceed the limit every 2 minutes. Notice the uncompressed, archived files are at least 9400 Bytes and 2 minutes apart.

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

The following example is similar to the previous one with the exception that the logging.pattern.rolling-file-name ends in gz — triggering the historical file to be compressed.

logging.logback.rollingpolicy.max-history will constrain the number of files created for independent timestamps. In the example below, I constrained the limit to 2. Note that the logging.logback.rollingpolicy.max-history property does not seem to apply to files terminated because of size. For that, we can use logging.file.total-size-cap.

The following example triggers file changeover every 1000 Bytes and makes use of the index because we encounter multiple changes per timestamp pattern. The files are aged-off at the point where total size for all logs reaches logging.logback.rollingpolicy.total-size-cap. Thus historical files with indexes 1 thru 9 have been deleted at this point in time in order to stay below the file size limit.

The following example triggers file changeover every second and makes no use of the index because the timestamp pattern is so granular that max-size is not reached before the timestamp changes the base. As with the previous example, the files are also aged-off when the total byte count reaches logging.logback.rollingpolicy.total-size-cap.

The following is an example custom configuration where we wish to turn off console logging and only rely on the logfiles. This result is essentially a copy/edit of the supplied base.xml.

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

Our first execution uses all defaults and is written to ${java.io.tmpdir}/spring.log

Our second execution specified an override for the logfile to use. This is expressed exactly as we did earlier with the default configuration.