Get Started Quickly With Spring Boot Logging

Hot on the heels of the Get Started Quickly With Python Logging and Getting Started Quickly With C++ Logging articles, we’re headed across the coffee shop to look at logging in the context of the Java Spring Boot framework. While we’ve written already on the topic of Java logging in Get Started Quickly With Java Logging, the Spring Boot framework simplifies a lot of the plumbing involved in getting up and running. In this article we’ll learn how to:

  • Create a Spring Boot starter project
  • Use Gradle to build our application
  • Configure the default Spring Boot logger
  • Use Log4j2 with Spring Boot
  • Customize the logging configurations

Grab your Venti red-eye triple espresso with almond milk, and let’s get started!spring_boot_logging_scalyr

Create a Spring Boot Test Project

Before we delve into logging and Spring Boot, we need a demo project to experiment with. The easiest way to get going with Spring Boot is to use the online Spring Initializr project generator.

Head over to Spring Initializr, and let’s update a few of the options on that page. For this article we’ll use Gradle for dependency management and to build our application. If you want to import the project into Eclipse or IntelliJ, feel free.

The Spring Initializr website defaults to Maven for dependency management. Let’s change the “Generate a” drop down from “Maven Project” to “Gradle Project.” Now there are just a couple more tweaks we need to make to be consistent with this article. In the “Search for dependencies” input box, enter Web and select the “Full-stack web development” option. Next, change the “Artifact” text input from “demo” to “logging.” Now we’re good to go!

Check out the below screenshot to see all of the changes to make:

Once you’ve made the changes, click the “Generate Project” button to download an archive containing our project. After extracting the downloaded archive, you’ll have the following files:

Building the Spring Boot Starter Project

If you’ve never used Gradle before, I highly recommend reading up on it as an alternative to Maven. It uses the same repositories as Maven, but its own domain-specific language (DSL) based on Groovy. This results in shorter and clearer build scripts than the verbose XML configurations Maven uses. Life is too short to deal with XML if we don’t have to. We also don’t have to worry about installing anything. The gradlew command will take care of downloading everything that’s required. It’s also already included in our project source.

Let’s test our current setup by building and running our application. In the console, run the following command from the root of our project folder:

$ ./gradlew bootRun

The initial build and project execution will take a few minutes while Gradle downloads dependencies. Once that finishes, the compilation and execution phase will kick in. After a couple of minutes you’ll see the message that the embedded Tomcat server is listening on port 8080:

2018-07-19 08:51:39.705  INFO 23549 --- [           main] o.s.w.s.handler.SimpleUrlHandlerMapping  : Mapped URL path [/webjars/**] onto handler of type [class org.springframework.web.servlet.resource.ResourceHttpRequestHandler]
2018-07-19 08:51:39.705  INFO 23549 --- [           main] o.s.w.s.handler.SimpleUrlHandlerMapping  : Mapped URL path [/**] onto handler of type [class org.springframework.web.servlet.resource.ResourceHttpRequestHandler]
2018-07-19 08:51:39.933  INFO 23549 --- [           main] o.s.j.e.a.AnnotationMBeanExporter        : Registering beans for JMX exposure on startup
2018-07-19 08:51:40.010  INFO 23549 --- [           main] o.s.b.w.embedded.tomcat.TomcatWebServer  : Tomcat started on port(s): 8080 (http) with context path ''
2018-07-19 08:51:40.016  INFO 23549 --- [           main] com.example.logging.LoggingApplication   : Started LoggingApplication in 4.314 seconds (JVM running for 4.959)

Open a browser and enter http://localhost:8080 to see our application:

You probably weren’t expecting that. For whatever reason, the projects created with Spring Initializr don’t include a default controller. This means Spring Boot has no idea how to handle our request. Let’s fix that.

Fixing the Spring Boot Starter Project

To resolve our error message, we need to create a controller. Under the src/main/java/com/example/logging folder, create a new file and name it LoggingController.java and insert the following into it:

package com.example.logging;

import org.springframework.web.bind.annotation.RequestMapping;
import org.springframework.web.bind.annotation.RestController;

@RestController
public class LoggingController {

  @RequestMapping("/")
  public String index() {
    return "Welcome to Spring Logging!";
  }
}

If the application is still running, kill it by pressing Ctrl-C back in the console. There isn’t any automatic reloading, so to see the result of our changes we need to stop and rerun the application. Once the application finishes restarting, refresh the page in the browser. You’ll see our welcome message indicating that we have a working project:

We now have a working controller to add our logging statements to. With that out of the way, let’s get on with the purpose of this article and get into the logging.

Using the Default Spring Boot Logger

Spring Boot comes with a preconfigured default logger based on the Logback framework. We can use this logging setup out of the box without any additional configuration since the spring-web-starter package we built our project on includes this dependency already. The default logger is great for quick prototyping or experimenting. However, we’ll inevitably want a bit more configuration, which we’ll get to in later sections.

First, to update our logging controller to use this built-in logger, update LoggingController.java to the following:

package com.example.logging;

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.springframework.web.bind.annotation.RequestMapping;
import org.springframework.web.bind.annotation.RestController;

@RestController
public class LoggingController {

  Logger logger = LoggerFactory.getLogger(LoggingController.class);

  @RequestMapping("/")
  public String index() {
    logger.trace("This is a TRACE message.");
    logger.debug("This is a DEBUG message.");
    logger.info("This is an INFO message.");
    logger.warn("This is a WARN message.");
    logger.error("You guessed it, an ERROR message.");
    
    return "Welcome to Spring Logging! Check the console to see the log messages.";
  }
}

If you haven’t already, stop the current running application by pressing Ctrl-C again in the console. Then, run the updated application again:

$ ./gradlew bootRun

Refresh your browser, and you’ll see our updated message:

Once that finishes loading, look over at the console to see our log messages in all their glory:

2018-07-19 09:20:57.221  INFO 28614 — [nio-8080-exec-1] com.example.logging.LoggingController    : This is an INFO message.
2018-07-19 09:20:57.223  WARN 28614 — [nio-8080-exec-1] com.example.logging.LoggingController    : This is a WARN message.
2018-07-19 09:20:57.225 ERROR 28614 — [nio-8080-exec-1] com.example.logging.LoggingController    : You guessed it, an ERROR message.

Hmm… Looks like we’re only seeing the INFO, WARN, and ERROR log messages, and not the TRACE and DEBUG messages. If you’re at all familiar with Java logging, this probably won’t come as a surprise. The Spring Boot logger is configured to only log messages of INFO level or higher. We can see the TRACE and DEBUG messages if we add the following to our application.properties file:

logging.level.root=WARN
logging.level.com.example=TRACE

Now rerun the application and refresh your browser. In the console output we’ll see our missing log statements:

2018-07-19 09:26:32.535 TRACE 28643 --- [nio-8080-exec-1] com.example.logging.LoggingController    : This is a TRACE message.
2018-07-19 09:26:32.535 DEBUG 28643 --- [nio-8080-exec-1] com.example.logging.LoggingController    : This is a DEBUG message.
2018-07-19 09:26:32.535  INFO 28643 --- [nio-8080-exec-1] com.example.logging.LoggingController    : This is an INFO message.
2018-07-19 09:26:32.535  WARN 28643 --- [nio-8080-exec-1] com.example.logging.LoggingController    : This is a WARN message.
2018-07-19 09:26:32.535 ERROR 28643 --- [nio-8080-exec-1] com.example.logging.LoggingController    : You guessed it, an ERROR message.

We now have working code outputting log messages. Let’s move onto configuring Logback by creating a separate configuration file to override the defaults. While we’re at it, we’ll go ahead and add a custom message layout as well.

Create a Custom Logback Configuration

While we can configure everything we need to for Logback in our application.properties file, this isn’t recommended, as this file is prone to getting polluted with a lot of settings for various things in any sizable application. The recommended way in Spring is to store the Logback configuration in a separate file named logback-spring.xml. Spring will load this before any other Logback configuration if it exists.

Go ahead and create the logback-spring.xml  file under src/main/resources in the same place as application.properties and drop the following into it:

<?xml version="1.0" encoding="UTF-8"?>
<configuration>
  <appender name="Console" class="ch.qos.logback.core.ConsoleAppender">
    <layout class="ch.qos.logback.classic.PatternLayout">
      <Pattern>
        %d{yyyy-MM-dd HH:mm:ss} [%thread] %-5level %logger{36} - %msg%n
      </Pattern>
    </layout>
  </appender>

  <root level="info">
    <appender-ref ref="Console" />
  </root>

  <!-- Log everything at the TRACE level -->
  <logger name="com.example" level="trace" additivity="false">
    <appender-ref ref="Console" />
  </logger>
</configuration>

We won’t get into all the details of the Logback configuration here, but we are directing everything at TRACE level or higher (effectively logging everything) in our application to the console. If you want to dive into additional Logback configuration, all of it is well documented. In short, we create a console log appender and set a custom message pattern. This controls the formatting of any messages being logged with it. Our log messages will now look like this:

2018-07-19 12:51:19 [http-nio-8080-exec-1] TRACE c.example.logging.LoggingController - This is a TRACE message.
2018-07-19 12:51:19 [http-nio-8080-exec-1] DEBUG c.example.logging.LoggingController - This is a DEBUG message.
2018-07-19 12:51:19 [http-nio-8080-exec-1] INFO  c.example.logging.LoggingController - This is an INFO message.
2018-07-19 12:51:19 [http-nio-8080-exec-1] WARN  c.example.logging.LoggingController - This is a WARN message.
2018-07-19 12:51:19 [http-nio-8080-exec-1] ERROR c.example.logging.LoggingController - You guessed it, an ERROR message.

This message pattern uses the following Logback variables:

  • %d{yyyy-MM-dd HH:mm:ss}Date in the specified format
  • [%thread] Current thread identifier writing the message
  • %-5level The message level with five-character, fixed-width spacing
  • %logger{36} The name of the logger writing the message
  • %msg%n The actual message followed by a new line

That’s it for the Logback configuration. This configuration file is also where you can add any additional appenders or formatters. Refer to the Logback documentation for all the configuration examples.

Now let’s swap out our Logback setup for our trusty standby logging library, Log4j2.

Configure Log4j2 for Logging

Spring Boot uses the SLF4J library under the hood to abstract its logging. This makes switching to Log4j2 relatively simple. It’s just a matter of adding a new configuration file and the Log4j2 dependency to our dependencies.

Since we started with the Spring Boot web starter, we currently have a transitive dependency on the Logback library. The Logback library comes in through the spring-jcl library dependency. To use Log4j2, we need to first exclude the Logback library. We’ll then include the Log4j2 library. Let’s update our Gradle build to make these changes.

Currently, our Gradle build file, build.gradle, looks like this:

buildscript {
  ext {
    springBootVersion = '2.0.3.RELEASE'
  }
  repositories {
    mavenCentral()
  }
  dependencies {
    classpath("org.springframework.boot:spring-boot-gradle-plugin:${springBootVersion}")
  }
}

apply plugin: 'java'
apply plugin: 'eclipse'
apply plugin: 'org.springframework.boot'
apply plugin: 'io.spring.dependency-management'

group = 'com.example'
version = '0.0.1-SNAPSHOT'
sourceCompatibility = 1.8

repositories {
  mavenCentral()
}

dependencies {
  compile('org.springframework.boot:spring-boot-starter-web')
  testCompile('org.springframework.boot:spring-boot-starter-test')
}

Replace the contents of build.gradle with this:

buildscript {
  ext {
    springBootVersion = '2.0.3.RELEASE'
  }
  repositories {
    mavenCentral()
  }
  dependencies {
    classpath("org.springframework.boot:spring-boot-gradle-plugin:${springBootVersion}")
  }
}

apply plugin: 'java'
apply plugin: 'eclipse'
apply plugin: 'org.springframework.boot'
apply plugin: 'io.spring.dependency-management'

group = 'com.example'
version = '0.0.1-SNAPSHOT'
sourceCompatibility = 1.8

repositories {
  mavenCentral()
}

configurations.all {
  exclude group:'org.springframework.boot', module: 'spring-boot-starter-logging'
}

dependencies {
  compile('org.springframework.boot:spring-boot-starter-web')
  compile('org.springframework.boot:spring-boot-starter-log4j2')
  testCompile('org.springframework.boot:spring-boot-starter-test')
}

In the updated build script, we’ve added an exclude group for the spring-boot-starter-logging module, which is where the Logback dependency comes from. We then add an additional compile time dependency on the spring-boot-starter-log4j2, which, as you guessed right, includes the Log4j2 library and the relevant Spring Boot configuration.

We’ll configure our Log4j2 logging to output the same message format used in our earlier Logback example. Let’s add a Log4j2 configuration file to our project.

Create the following named log4j2-spring.xml file in src/main/resources where our application.properties  resides:

<?xml version="1.0" encoding="UTF-8"?>
<Configuration>
  <Appenders>
    <Console name="Console" target="SYSTEM_OUT">
      <PatternLayout
          pattern="%d{yyyy-MM-dd HH:mm:ss} [%thread] %-5level %logger{36} - %msg%n"/>
    </Console>
  </Appenders>

  <Loggers>

    <!-- LOG everything at INFO level -->
    <Root level="info">
      <AppenderRef ref="Console" />
    </Root>

    <!-- LOG "com.example" at TRACE level -->
    <Logger name="com.example" level="trace">
    </Logger>
  </Loggers>
</Configuration>

While this looks very similar to the Logback example, there are a few minor differences. Running our application, we see that we have the same output as before:

2018-07-19 13:11:21 [http-nio-8080-exec-1] TRACE com.example.logging.LoggingController - This is a TRACE message.
2018-07-19 13:11:21 [http-nio-8080-exec-1] DEBUG com.example.logging.LoggingController - This is a DEBUG message.
2018-07-19 13:11:21 [http-nio-8080-exec-1] INFO  com.example.logging.LoggingController - This is an INFO message.
2018-07-19 13:11:21 [http-nio-8080-exec-1] WARN  com.example.logging.LoggingController - This is a WARN message.
2018-07-19 13:11:21 [http-nio-8080-exec-1] ERROR com.example.logging.LoggingController - You guessed it, an ERROR message.

We’ve now successfully swapped out Logback for Log4j2.

Why Use Log4j2 Instead of Logback?

Why would we want to go through this extra setup to use Log4j2 when Logback is ready to go? Well, being able to swap over to Log4j2 is handy, especially when moving from an existing project to Spring Boot. We can carry over our existing Log4j2 configuration file and not have to worry about it. This is particularly useful when working with an existing and complex Log4j2 configuration. It’s common to have various appenders writing to multiple files with different formats or specific package-level logging. We can always convert the configuration into Logback when there’s more time to spare before the release!

While Logback is considered the successor to Log4j2, Log4j2 is still used in many applications. If you’ve never used Logback before, check out the following reasons to switch.

The End of Our Logging Journey

At this point you’ve successfully configured Spring Boot to log with two different logging frameworks. We’ve also looked at how to add additional logging configuration to the Spring Boot project. This may also be your first experience using Gradle, and I’d highly recommend trying it out for a while.

Logging is paramount to successfully monitoring and troubleshooting applications. Don’t overlook security needs when adding logging to an application. It’s important to ensure we aren’t logging sensitive information such as passwords or account details. Refer to the OWASP Logging Cheatsheet for additional suggestions on what to look out for.

This post was written by Casey Dunham. Casey, who recently launched his own security business, is known for his unique approaches to all areas of application security, stemming from his 10+ year career as a professional software developer. His strengths include secure SDLC development consulting; threat modeling; developer training; and auditing web, mobile, and desktop applications for security flaws.