Slf4j, Lockback and Log4J2

In this article I show how to write logs in a Spring Boot application. I also show how to configure the Logback and Log4J2 loggers.

Content

Slf4j
Log Levels
Logback
Logback vs Log4j2
Log4j2

More details can be found in this video.

All the code of the article is available in this repository.

Slf4j

By default, a Sprint Boot application is ready to accept using loggers in the code. In fact, it already has an interface, Slf4J, and a logger, Logback, ready to be used.

As I have Lombok installed, I can directly use the annotation @Slf4j to create a logger in my class.

@RequiredArgsConstructor
@Service
@Slf4j
public class UserService {
   ...

What will do the annotation @Slf4j is just create a logger inside the class with the current class as follow:

private static final org.slf4j.Logger log = org.slf4j.LoggerFactory.getLogger(UserService.class);

Now, I can use directly the log constant to log content:

log.info("Creating new user {}", credentialsDto.getLogin());

With the curly bracket, I can replace the variable value inside the string. Why using the curly brackets and not the string concatenation?

In this case, I am logging at the INFO level. I may have my logger configured to print INFO and higher levels or only print WARNING and higher levels. If my log may not be printed, with the string concatenation, I have the operation of the concatenation done even if my log won’t be printed. With the variable replacement, if my log won’t be printed the operation of the replacement won’t be done. This will afford me some CPU operations. Especially, if I write a lot of logs in different levels.

Log Levels

There are five levels of logs: ERROR, WARNING, INFO, DEBUG and TRACE. Each of those levels accept a single message to be printed or with variables to be replaced inside the message. As said, the replacement will be done only if needed.

log.warning("Some problems were detected");
log.debug("Creating new user {}", credentialsDto.getLogin());

And with each of those levels, i can also print an exception stacktrace. If i pass an exception object as the last parameter, the logger will print first my message and then
the exception stacktrace.

log.error("Unable to open the file", ex);
log.warning("Invalid data", ex);

But which level to use in each case? The ERROR level should be used to inform about a non-recoverable error. This means that the application can’t continue with the workflow. This means that the request must stop right now and return some 500 HTTP code with an associated message. This occurs like a missing configuration, a network problem or an unavailable external service. My application needs this configuration to be fetched, or this external service to be requested. If it’s not available, I can’t answer the user’s request.

The WARNING also informs me about an error, but my application can continue with some work around. I may have some network problems with my external service. But I have some old values in the cache. I can answer the user’s request. Maybe not the best way, but I can do something.

The INFO level is there to audit some user’s behavior. Like when the user’s logged in, the users change a configuration, the users try to upload an invalid file. This example may also be included in the WARNING level.

The DEBUG level is more likely to obtain enough information to trace a problem and try to reproduce it locally. I may print the input parameters for a complicated algorithm.

And finally, the TRACE level is like the DEBUG, try to reproduce a behavior locally, but this time logging all the inner steps of the complicated algorithm. The DEBUG level will print the inputs and outputs. And the TRACE level will also print all intermediary steps.

But the main point of those logs is the later propose. Those logs should be written consequently to be read afterwards. I can easily trace a bad behavior from the logs, but I need the logs to be good enough, with enough information to be useful. It’s better to write too many logs than not enough. I can limit and filter the logs in the configuration.

Logback

I’ve written my first line of log, but what do they look like with no configuration?

2022-02-11 09:46:46,031        INFO [main] ache.juli.logging.DirectJDKLog: Starting ProtocolHandler ["http-nio-8080"]
2022-02-11 09:46:46,049        INFO [main] mbedded.tomcat.TomcatWebServer: Tomcat started on port(s): 8080 (http) with context path ''
2022-02-11 09:46:46,052        INFO [main] amework.boot.StartupInfoLogger: Started Application in 5.006 seconds (JVM running for 6.323)

Okay, this is fine. I think I have enough information to start. But let’ fine-tune Logback with the log4j2.xml file. I will configure my logger to print at the same time to the console and to a file.

<?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>%-30(%d %p) %-30.30([%t] %C): %msg%n%throwable</Pattern>
        </layout>
    </appender>

    <appender name="File" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <file>logs/app-logback.log</file>
        <encoder class="ch.qos.logback.classic.encoder.PatternLayoutEncoder">
            <Pattern>%d %p [%t] %C: %msg%n%throwable</Pattern>
        </encoder>


        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
            <fileNamePattern>logs/archived/app-%d{yyyy-MM-dd}.%i-logback.log</fileNamePattern>
            <timeBasedFileNamingAndTriggeringPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP">
                <maxFileSize>10MB</maxFileSize>
            </timeBasedFileNamingAndTriggeringPolicy>
        </rollingPolicy>
    </appender>

    <root level="INFO">
        <appender-ref ref="File" />
        <appender-ref ref="Console" />
    </root>

    <logger name="com.sergio.socialnetwork" level="DEBUG" additivity="false">
        <appender-ref ref="File" />
        <appender-ref ref="Console" />
    </logger>

</configuration>

I’ve added a rolling policy to the file appender to avoir the file growing with no limit. When a file reach 10 megabytes, it creates a new file and rename the old one following the pattern specified.

At the end, I’ve specified that, by default, all the loggers will print info logs and higher levels, using both the file and the console appender. I’ve also indicated that I want specifically my logs to use a more detailed log level the debug level, and also use the file and console appenders.

For the format of the logs, I want that both the console and file will print the same information. Nevertheless, i’ve indicated that the console will print a more column based info: i’ve specified that some columns have no more than 30 characters length. This will ease to read the logs, as I will always see the message starting at the same position no matters the logger name is. And for the file appender, I prefer the full name to be printed, as the file may be interpreted by some script.

Logback vs Log4j2

Okay, i have my logback configuration ready. I can also try to do the same with log4j to see the differences. But first, let’s see the difference between logback, log4j and slf4j.

First of all, I’ve used slf4j. slf4j is an interface. I can have any logger behind and my code won’t change if I update my dependencies or my configuration. So why to choose logback as a logger?

logback is natively included in a Spring Boot application.
It automatically applies changes on the configuration file.
It handles gracefully the files: if there is a missing file, if there is a file too big, or if multiple threads write to the same file.
It has a fine-tuning filtering. Not only by level but by class.
And it has some appenders like the HTTP-access one which allows to read the incoming requests with detailed information.

And what about log4j2? Yes, because it’s already the second version.

It also reloads automatically upon configuration changes.
It handles file changes and rotation.
It also has fine-tuning filtering.
And HTTP-access logs.
But it also has a low latency asynchronous logs.
And the better garbage collector, which improves the time response and time performance.

So, log4j is a better option.

Log4j2

First of all, i need to exclude the logback dependency.

        <dependency>
            <groupId>org.springframework.boot</groupId>
            <artifactId>spring-boot-starter-web</artifactId>
            <exclusions>
                <exclusion>
                    <groupId>org.springframework.boot</groupId>
                    <artifactId>spring-boot-starter-logging</artifactId>
                </exclusion>
            </exclusions>
        </dependency>
        <dependency>
            <groupId>org.springframework.boot</groupId>
            <artifactId>spring-boot-starter-log4j2</artifactId>
        </dependency>

Now, create the configuration file. As before, i also want two appenders: the console and the file.

<?xml version="1.0" encoding="UTF-8"?>
<Configuration>
    <Appenders>
        <Console name="Console" target="SYSTEM_OUT">
            <PatternLayout
                    pattern="%-30d %p [%t] %-30.30C: %msg%n%throwable" />
        </Console>

        <RollingFile name="File" fileName="./logs/app-log4j2.log" filePattern="./logs/app-%d{-dd-MMMM-yyyy}-%i.log4j2.log.gz">
            <PatternLayout>
                <pattern>%d %p [%t] %C: %msg%n%throwable</pattern>
            </PatternLayout>
            <Policies>
                <OnStartupTriggeringPolicy />
                <SizeBasedTriggeringPolicy size="10 MB" />
                <TimeBasedTriggeringPolicy />
            </Policies>
        </RollingFile>
    </Appenders>

    <Loggers>
        <Root level="INFO">
            <AppenderRef ref="Console" />
            <AppenderRef ref="File" />
        </Root>

        <Logger name="com.sergio.socialnetwork" level="DEBUG"/>
    </Loggers>

</Configuration>

The pattern is quite similar as the logback one. Nevertheless, i can’t group by values. With log4j2, I can compress my files directly with the extension. I can also fine-tune the trigger to roll the files.

Conclusion

I’ve written the logs using directly slf4j, as it’s an interface.
By default, Spring Boots has logback already configured. If i want to fine-tune my logback configuration i need to create a logback.xml file.
I’ve added two appenders: one to write to the console and the second one to write to a file.
To use lock4j, I must exclude logback and create log4j.xml file.
And the configuration for log4j is quite similar as the one for logback.

References

Repository

The Dev World – Sergio Lema