others-how to add custom logger appender to springboot kotlin project ?

1. Purpose

In this post, I will demonstrate how to add a custom logger appender to a springboot project written in kotin language.

2. Solution

2.1 The default log configurations in spring boot project

Spring Boot uses Commons Logging for all internal logging but leaves the underlying log implementation open. Default configurations are provided for Java Util Logging, Log4j2, and Logback. In each case, loggers are pre-configured to use console output with optional file output also available.

By default, if you use the “Starters”, Logback is used for logging. Appropriate Logback routing is also included to ensure that dependent libraries that use Java Util Logging, Commons Logging, Log4J, or SLF4J all work correctly.

Commons-logging and slf4j are log facades in java, that is, they provide a set of common interfaces, and the specific implementation can be freely chosen by developers. log4j and logback are specific log implementations.

The more commonly used collocations are commons-logging+log4j, slf4j+logback

2.1.1 What is commons logging?

Commons-logging is a common logging interface provided by apache. Users can freely choose a third-party log component as a specific implementation, such as log4j, or the logging that comes with jdk, and common-logging will automatically find out the actual log library used when the program is running through a dynamic search mechanism.

So using common-logging is usually used in conjunction with log4j. The advantage of using it is that the code dependency is common-logging instead of log4j, which avoids direct coupling with the specific logging scheme. When necessary, the third-party library for logging implementation can be changed

import org.apache.commons.logging.Log;
import org.apache.commons.logging.LogFactory;

public class A {
    private static  Log logger = LogFactory.getLog(A.class);
}

Principle of dynamic discovery of logging implementation:

Log is an interface declaration. The LogFactory will load the specific log system inside and obtain the implementation class that implements the Log interface.

The process of loading the log system inside LogFactory is as follows:

  • First, look for the org.apache.commons.logging.LogFactory property configuration.
  • Otherwise, using the service discovery mechanism provided by JDK1.3, it will scan the META-INF/services/org.apache.commons.logging.LogFactory file under the classpah, and if found, load the configuration inside and use the configuration inside.
  • Otherwise, search for commons-logging.properties from the Classpath, and if found, load it according to the configuration inside.
  • Otherwise, use the default configuration: if Log4j can be found, it will use log4j by default, if not, it will use JDK14Logger, and if not, it will use the SimpleLog provided by commons-logging.

From the above loading process, as long as log4j is introduced and log4j.xml is configured in the classpath, commons-logging will make log4j work normally, and the code does not need to rely on any log4j code.

2.2 Why slf4j is better than commons logging

The full name of slf4j is Simple Logging Facade for JAVA, a simple log facade for java. Similar to Apache Common-Logging, it is a façade encapsulation provided for different log frameworks, which can be connected to a log implementation solution without modifying any configuration during deployment. However, he statically binds the real Log library at compile time. When using SLF4J, if you need to use a certain log implementation, then you must choose the correct set of SLF4J jar packages (various bridging packages).

slf4j static binding principle:

SLF4J will bind import org.slf4j.impl.StaticLoggerBinder during compilation; this class implements binding access to specific log solutions. Any implementation based on slf4j must have this class. For example: org.slf4j.slf4j-log4j12-1.5.6: Provides an adaptation to log4j. Note: If any two packages that implement slf4j are present at the same time, then there may be problems

common-logging uses a dynamic search mechanism to automatically find out the log library actually used when the program is running. Since it uses ClassLoader to find and load the underlying logging library, frameworks like OSGI cannot work properly, because different plugins of OSGI use their own ClassLoader. This mechanism of OSGI ensures that the plug-ins are independent of each other, but it makes Apache Common-Logging unable to work.

slf4j statically binds the real Log library at compile time, so it can be used in OSGI. In addition, SLF4J supports parameterized log strings, which avoids having to write if(logger.isDebugEnable()) to reduce the performance loss of string splicing. Now you can directly write: logger.debug(“current user is : {}”, user). Assembly of the message is postponed until it can determine whether to display the message, but the cost of obtaining parameters is not spared.

2.3 How to use Slf4j instead of Commons Logging in springboot?

First, exclude commons-logging in your maven pom.xml as follows

 <dependency> 
    <groupId>org.springframework</groupId> 
    <artifactId>spring-core</artifactId> 
    <exclusions> 
        <exclusion> 
            <groupId>commons-logging</groupId> 
            <artifactId>commons-logging</artifactId> 
        </exclusion> 
    </exclusions>
</dependency>

Then use slf4j as follows:

import org.slf4j.Logger; 
import org.slf4j.LoggerFactory; 
public class HelloWorld {
 public static void main(String[] args) { 
    Logger logger = LoggerFactory.getLogger(HelloWorld.class); 
    logger.info("Hello World"); } 
 }

2.4 Why logback is better than log4j?

As a general, reliable, fast and flexible logging framework, LogBack will serve as a complete implementation of the new logging system composed of Log4j and slf4j. LogBack claims to have excellent performance, “Some key operations, such as the operation of determining whether to record a log statement, have significantly improved their performance. This operation takes 3 nanoseconds in LogBack and 30 nanoseconds in Log4j. Seconds. LogBack is also faster at creating loggers: 13 microseconds compared to 23 microseconds in Log4j. What’s more, it only takes 94 nanoseconds to fetch an existing logger, compared to 2234 in Log4J In nanoseconds, the time is reduced to 1/23. The performance improvement compared to JUL (java.util.logging) is also significant”. In addition, all LogBack documents are provided free of charge, unlike Log4J, which only provides some free documents and requires users to purchase paid documents.

2.5 How to configure logback with configuration file in spring boot?

In your project, create a file in src/main/resources/ named logback-spring.xml, here is an example:

<?xml version="1.0" encoding="UTF-8"?>
<configuration>
    <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
        <encoder>
            <pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} %magenta([%thread]) %highlight(%-5level) %logger{36}.%M - %msg%n</pattern>
        </encoder>
    </appender>
    <root level="info">
        <appender-ref ref="STDOUT" />
    </root>
</configuration>

  • %d – outputs the data and time that the log occurred in formats that SimpleDateFormat allows.
  • %thread – outputs the name of the thread that the log message occurred in.
  • $-5level – outputs the logging level of the log message.
  • %logger{36} – outputs the package + class name the log message occurred in. The number inside the brackets represents the - maximum length of the package + class name. If the output is longer than the specified length, it will take a substring of the - first character of each individual package starting from the root package until the output is below the maximum length. The - class name will never be reduced. A nice diagram of this can be found in the Conversion Word docs.
  • %M – outputs the name of the method that the log message occurred in (apparently this is quite slow to use and not recommended - unless you’re not worried about performance, or if the method name is particularly important to you).
  • %msg – outputs the actual log message.
  • %n – line break.
  • %magenta() – sets the color of the output contained in the brackets to magenta (other colors are available).
  • highlight() – sets the color of the output contained in the brackets depending on the logging level (for example ERROR = red).

Here is a more detailed example of logback-spring.xml:

<?xml version="1.0" encoding="UTF-8" ?>

<!-- levels from high to low OFF , FATAL , ERROR , WARN , INFO , DEBUG , TRACE , ALL -->
<!-- Log output rules According to the current ROOT level, when the log output is higher than the root default level, it will be output -->
<!-- Each filter configured below is to filter out the output file, high-level files will appear, and low-level log information will still appear, and only log logs of this level will be recorded through filter filtering -->
<!-- scan When this property is set to true, if the configuration file changes, it will be reloaded. The default value is true. -->
<!-- scanPeriod sets the time interval for monitoring whether the configuration file has been modified. If no time unit is given, the default unit is milliseconds. This property takes effect when scan is true. The default time interval is 1 minute. -->
<!-- debug When this property is set to true, it will print out the internal log information of logback, and check the running status of logback in real time. The default value is false. -->
<configuration scan="true" scanPeriod="60 seconds" debug="false">

     <!-- Dynamic log level -->
     <jmxConfigurator/>

     <!-- Define the log file output location -->
     <property name="log.log_dir" value="logs"/>
     <property name="log.log_name" value="log"/>
     <!-- log maximum history 30 days -->
     <property name="log.maxHistory" value="30"/>
     <property name="log. level" value="debug"/>
     <property name="log.maxSize" value="5MB" />

     <!-- ConsoleAppender console output log -->
     <appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
         <encoder>
             <pattern>
                 <!-- Set the log output format -->
                 <!-- date [thread] [class]-[log level] log content -->
                 %blue(%d{yyyy-MM-dd HH:mm:ss,SSS}) [%cyan(%t)] [%yellow(%c)]-[%highlight(%p)] %m%n
             </pattern>
         </encoder>
     </appender>

     <!-- ERROR level log -->
     <!-- Rolling record file, first record the log to the specified file, when a certain condition is met, record the log to other files RollingFileAppender -->
     <appender name="ERROR" class="ch.qos.logback.core.rolling.RollingFileAppender">
         <!-- filter, only record WARN level logs -->
         <!-- If the log level is equal to the configuration level, the filter will accept or reject the log according to onMath and onMismatch. -->
         <filter class="ch.qos.logback.classic.filter.LevelFilter">
             <!-- Set filter level -->
             <level>ERROR</level>
             <!-- Used to configure operations that meet the filter conditions -->
             <onMatch>ACCEPT</onMatch>
             <!-- Used to configure operations that do not meet the filter conditions -->
             <onMismatch>DENY</onMismatch>
         </filter>
         <!-- The most commonly used scrolling strategy, it formulates a scrolling strategy based on time. It is responsible for both scrolling and triggering scrolling -->
         <rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy">
             <!--The log output location can be relative, and absolute path -->
             <fileNamePattern>
                 ${log.log_dir}/error/%d{yyyy-MM-dd}/error_${log.log_name}-%i.log
             </fileNamePattern>
             <!-- Optional node, controls the maximum number of retained archive files, and deletes old files if the number exceeds, assuming that it is set to roll every month, and <maxHistory> is 6,
             Then only the files of the last 6 months will be saved, and the old files before will be deleted. Note that when deleting old files, the directories created for archiving will also be deleted -->
             <maxHistory>${log.maxHistory}</maxHistory>
             <!--The maximum size of the log file-->
             <MaxFileSize>${log.maxSize}</MaxFileSize>
         </rollingPolicy>
         <encoder>
             <pattern>
                 <!-- Set the log output format -->
                 %d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] %-5level %logger{50} - %msg%n
             </pattern>
         </encoder>
     </appender>

     <!-- INFO level log appender -->
     <appender name="INFO" class="ch.qos.logback.core.rolling.RollingFileAppender">
         <filter class="ch.qos.logback.classic.filter.LevelFilter">
             <level>INFO</level>
             <onMatch>ACCEPT</onMatch>
             <onMismatch>DENY</onMismatch>
         </filter>
         <rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy">
             <fileNamePattern>${log.log_dir}/info/%d{yyyy-MM-dd}/info_${log.log_name}-%i.log</fileNamePattern>
             <maxHistory>${log.maxHistory}</maxHistory>
             <MaxFileSize>${log.maxSize}</MaxFileSize>
         </rollingPolicy>
         <encoder>
             <pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [%-5level] %logger - %msg%n</pattern>
         </encoder>
     </appender>


     <!-- DEBUG level log appender -->
     <appender name="DEBUG" class="ch.qos.logback.core.rolling.RollingFileAppender">
         <filter class="ch.qos.logback.classic.filter.LevelFilter">
             <level>DEBUG</level>
             <onMatch>ACCEPT</onMatch>
             <onMismatch>DENY</onMismatch>
         </filter>
         <rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy">
             <fileNamePattern>${log.log_dir}/debug/%d{yyyy-MM-dd}/debug_${log.log_name}-%i.log</fileNamePattern>
             <maxHistory>${log.maxHistory}</maxHistory>
             <MaxFileSize>${log.maxSize}</MaxFileSize>
         </rollingPolicy>
         <encoder>
             <pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [%-5level] %logger - %msg%n</pattern>
         </encoder>
     </appender>

     <!--Set an appender that is passed upwards, and all levels of logs will be output -->
     <appender name="app" class="ch.qos.logback.core.rolling.RollingFileAppender">
         <rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy">
             <fileNamePattern>${log.log_dir}/app/%d{yyyy-MM-dd}/app_${log.log_name}-%i.log</fileNamePattern>
             <maxHistory>${log.maxHistory}</maxHistory>
             <MaxFileSize>${log.maxSize}</MaxFileSize>
         </rollingPolicy>
         <encoder>
             <pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [%-5level] %logger - %msg%n</pattern>
         </encoder>
     </appender>

     <!--The log output of the class under the name package-->
     <logger name="com.example.webtest.controller" additivity="true" level="DEBUG">
         <appender-ref ref="ERROR" />
         <appender-ref ref="INFO" />
     </logger>

     <!-- root level DEBUG -->
     <root>
         <!-- console output -->
         <appender-ref ref="CONSOLE"/>
         <!-- Output files regardless of the log under any package -->
         <!--<appender-ref ref="ERROR"/>-->
     </root>
</configuration>

2.6 What is appender in logging?

Appenders forward logs from Loggers to an output destination. During this process, log messages are formatted using a Layout before being delivered to their final destination. Multiple Appenders can be combined to write log events to multiple destinations.

Appender can control the destination of log output. An output source is called an Appender. The categories of appenders are:

  • Console
  • File
  • JDBC, JMS, etc.

logger can be specified through the configuration file.

Logback Appender class diagram: An appender is configured with the element, which takes two mandatory attributes name and class. The name attribute specifies the name of the appender whereas the class attribute specifies the fully qualified name of the appender class to instantiate.

In logback, Appenders are ultimately responsible for outputting logging events. However, they may delegate the actual formatting of the event to a Layout or to an Encoder object. Each layout/encoder is associated with one and only one appender, referred to as the owning appender. Some appenders have a built-in or fixed event format. Consequently, they do not require nor have a layout/encoder. For example, the SocketAppender simply serializes logging events before transmitting them over the wire.

2.7 How to add custom logger appender to spring boot project written in kotlin?

For example, if we want to add a custom appender(apache skywalking logging appender), how to do this job?

First , open src/main/resources/logback-spring.xml, fill it as follows:

<?xml version="1.0" encoding="UTF-8"?>
<configuration>
    <include resource="org/springframework/boot/logging/logback/defaults.xml"/>
    <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
        <encoder class="ch.qos.logback.core.encoder.LayoutWrappingEncoder">
            <layout class="org.apache.skywalking.apm.toolkit.log.logback.v1.x.TraceIdPatternLogbackLayout">
                <pattern>
                    [%sw_ctx]  %d{dd-MM-yyyy HH:mm:ss.SSS} %magenta([%-15.15thread]) %highlight(%-5level) %yellow(%-40.40C{40}) - %msg%n%throwable
                </pattern>
            </layout>
        </encoder>
    </appender>

    <root level="INFO">
        <appender-ref ref="STDOUT" />
    </root>
</configuration>

You can see that we use custom layout class in the logback append: org.apache.skywalking.apm.toolkit.log.logback.v1.x.TraceIdPatternLogbackLayout And then use %sw_ctx to print custom skywalking context info in the log.

Then , in your spring boot controllers , add and use slf4j logger in kotlin as follows:

package com.example.controllers

import com.example.domain.Message
import org.slf4j.Logger
import org.slf4j.LoggerFactory
import org.springframework.web.bind.annotation.GetMapping
import org.springframework.web.bind.annotation.RestController

@RestController
class MessageController {
    val Any.logger: Logger
        get() = LoggerFactory.getLogger(this.javaClass)

    @GetMapping
    fun index(): List<Message> {
        logger.info("got list request")
        var result = listOf(
            Message("1","hello1"),
            Message("2","Object"),
            Message("3","Privot"),
        )
        return result
    }
}

Then edit the project’s build.gradle.kts:

import org.jetbrains.kotlin.gradle.tasks.KotlinCompile

plugins {
    id("org.springframework.boot")

    kotlin("jvm")
    kotlin("plugin.spring")
    id("application")
}


dependencies {
    implementation(project(":api-common"))
    implementation("org.springframework.boot:spring-boot-starter-data-jpa")
    implementation("org.springframework.boot:spring-boot-starter-web")
    implementation("com.fasterxml.jackson.module:jackson-module-kotlin")
    implementation("org.jetbrains.kotlin:kotlin-reflect")
    implementation("org.jetbrains.kotlin:kotlin-stdlib-jdk8")
    implementation("org.apache.skywalking:apm-toolkit-logback-1.x:8.12.0") //important
    developmentOnly("org.springframework.boot:spring-boot-devtools")
    runtimeOnly("com.h2database:h2")
    testImplementation("org.springframework.boot:spring-boot-starter-test")
}


kotlin {
    jvmToolchain(11)
}


application {
    applicationDefaultJvmArgs = listOf("-javaagent:/Users/bswen/tech/skywalking/agent/skywalking-agent/skywalking-agent.jar=agent.service_name=api-messages",
        "-Dskywalking_config=/Users/bswen/KotlinProjects/blog/blog-backend-apis/blog-backend-apis/skywalking/agent.config")
}

The most important dependeny for this function is:

implementation("org.apache.skywalking:apm-toolkit-logback-1.x:8.12.0")

Run the program and test the controllers, we got this log:

[SW_CTX:[api-messages,[email protected],N/A,N/A,-1]]  11-12-2022 22:54:32.206 [nio-8081-exec-1] INFO  c.example.controllers.MessageController  - got list request

It works!



3. Summary

In this post, I demonstrated how to add a custom log appender in spring boot project written in kotlin. That’s it, thanks for your reading.