Friday, July 17, 2020

How springboot logging works

Spring is an opinionated framework, which means it chooses a reasonable default for you if you don't choose it yourself.

What logging facility the springboot chooses for you by default?

The answer is slf4j + logback

When you set spring boot dependency in the pom

<dependency>
<groupId>org.springframework.boot</groupId>
<artifactId>spring-boot-starter-web</artifactId>
</dependency>

That dependency depends on (thus brings in) spring-boot-starter-logging, which depends on sping-jcl (spring commons logging bridge), which is the logging facility springs framework use to do the log.

In the code, we just have to do the log as the following:
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.springframework.beans.factory.annotation.Autowired;
import org.springframework.core.env.Environment;
import org.springframework.web.bind.annotation.GetMapping;
import org.springframework.web.bind.annotation.RequestParam;
import org.springframework.web.bind.annotation.RestController;

import com.example.my.mydemo.handler.ClientHandler;
import com.example.my.mydemo.model.Client;

@RestController
public class ClientController {
    Logger logger = LoggerFactory.getLogger(ClientController.class);

    @Autowired
    Environment env;
    
    private final ClientHandler clientHandler;
    @Autowired
    public ClientController(ClientHandler clientHandler) {
        this.clientHandler = clientHandler;
    }
    
    @GetMapping("/client")
    public Client getClient(@RequestParam(value = "id", defaultValue = "1") String id) {
        logger.debug("/client requested with parameter {}", id);
        return clientHandler.handle(id);
    } 
    
    @GetMapping("/")
    public String test() {
        return env.getProperty("Greetings.Visit");
    }
    
    @Override
    public String toString() {
        return "ClientController, use id to lookup client information, url: http://localhost:8080/client?id=1";
    }

}

The slf4j is just an interface, the jar classes that implement these interfaces are log4j, which is in the class path of your maven dependencies. As you already guessed, spring did the default config for you.

mvn dependency:tree
...
[INFO] +- org.springframework.boot:spring-boot-starter-web:jar:2.3.0.RELEASE:compile
[INFO] |  +- org.springframework.boot:spring-boot-starter:jar:2.3.0.RELEASE:compile
[INFO] |  |  +- org.springframework.boot:spring-boot:jar:2.3.0.RELEASE:compile
[INFO] |  |  +- org.springframework.boot:spring-boot-autoconfigure:jar:2.3.0.RELEASE:compile
[INFO] |  |  +- org.springframework.boot:spring-boot-starter-logging:jar:2.3.0.RELEASE:compile
[INFO] |  |  |  +- ch.qos.logback:logback-classic:jar:1.2.3:compile
[INFO] |  |  |  |  \- ch.qos.logback:logback-core:jar:1.2.3:compile
[INFO] |  |  |  +- org.apache.logging.log4j:log4j-to-slf4j:jar:2.13.2:compile
[INFO] |  |  |  |  \- org.apache.logging.log4j:log4j-api:jar:2.13.2:compile
[INFO] |  |  |  \- org.slf4j:jul-to-slf4j:jar:1.7.30:compile
...

With these logging facilities in place, we just have to follow the spring's convention to configure the logging facility if you don't like the default. The convention is:
as long as you put a file named logback.xml or spring-logback.xml under directory src/main/resources, spring will use the file to configure logback.
Here is an example logback.xml content. By default, logback log level is INFO, the reconfiguration want to log DEBUG for class ClientController and JdbcTemplate. While the log of  ClientController is print to the console, which is the default, the JdbcTemplate is write to /logs.sql with dates postfix in the file name logs/sql.20-06-30_19.log, the file name changes with time, and the content looks like:
"2020-06-30 19:12:44,252 DEBUG[http-nio-8080-exec-1] o.s.j.c.JdbcTemplate - Executing prepared SQL statement [select name, email, id from Client where id = ?]"

<?xml version="1.0" encoding="UTF-8"?>
<configuration>
<include resource="org/springframework/boot/logging/logback/base.xml"/>
<appender name="MyFile" class="ch.qos.logback.core.rolling.RollingFileAppender">
<rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
<fileNamePattern>
logs/sql.%d{yy-MM-dd_HH}.log
</fileNamePattern>
</rollingPolicy>
<encoder>
<pattern>
%date{ISO8601} %-5level[%thread] %logger{1} - %msg%n
</pattern>
</encoder>
</appender>
<logger name="com.example.my.mydemo.controller.ClientController" level="DEBUG"/>
<logger name="org.springframework.jdbc.core.JdbcTemplate" level="DEBUG">
<appender-ref ref="MyFile"/>
</logger>
</configuration>

Now setback and enjoy the springboot logging for free (almost).

FYI.
If you are a fan of lombok. The one line 
Logger logger = LoggerFactory.getLogger(ClientController.class);
can be replaced by lombok annotation @Slf4j
the annotation will generate one line of code for you
Logger log = LoggerFactory.getLogger(ClientController.class);

then you can use variable log in later code.

Actually, to use lombok you have to add maven dependency, then add one extra import line in java code, so it is just a stylish choice for some developers.
...
import com.example.my.mydemo.model.Client;
import lombok.extern.slf4j.Slf4j;

@RestController
@Slf4j
public class ClientController { 
...
    @GetMapping("/client")
    public Client getClient(@RequestParam(value = "id", defaultValue = "1") String id) {
        log.debug("/client requested with parameter {}"id);
        return clientHandler.handle(id);
    }
...
For more information about lombok, check out How Lombok save developer's time.

No comments:

Post a Comment

Why I stopped publishing blog posts as information provider

Now the AI can generate content. Does that mean the web publishing industry reaches the end? ChatGPT said: ChatGPT Not at all. While AI can ...