Logback AsyncAppender Example
1. Introduction
In this post, we feature a comprehensive Example on Logback AsyncAppender. Most of the Java applications rely on logging messages to identify and troubleshoot problems. Logback is one of the most widely used logging frameworks in the Java community. Logback includes three classes: Logger, Appender, and Layout.
Logback appenders are responsible for outputting logging events to the destination. It provides a list of appenders as an out of box solution.
Appender | Description |
---|---|
ConsoleAppender | Appends log events to the system consoles: System.out or System.err. |
FileAppender | Appends log events to a file. |
RollingFileAppender | Appends log events to a file and backs up the log files when they reach a certain size. |
SyslogAppender | Appends log events to the System Logging Protocol (Syslog). |
SMTPAppender | Sends an email through Simple Mail Transfer Protocol (SMTP) for each logged message. |
SocketAppender | Logs the log events to a remote entity by transmitting serialized ILoggingEvents instances over a non-secured channel. |
SSLSocketAppender | Logs the log events similar to SocketAppender but over a secured channel. |
SiftingAppender | Logs log events from different threads to different log files. |
DBAppender | Inserts logging events into three database tables in a format independent of the Java programming language. |
AsyncAppender | Logs the log events asynchronously. It acts solely as an event dispatcher and must reference another appender. |
AsyncAppender acts as a dispatcher to another appender. It buffers ILoggingEvents and dispatches them to another appender asynchronously. This improves the application’s performance because it allows the application to not have to wait for the logging subsystem to complete the action. There is a potential heap memory leak when the buffer builds quicker that it can be drained. Luckily, Logback provides configuration options to address that.
In this example, I will demonstrate how to use AsyncAppender in a Spring Boot application.
2. Technologies Used
The example code in this article was built and run using:
- Java 1.8.101
- Maven 3.3.9
- Spring boot 2.0.3
- Logback 1.2.3
- Eclipse Oxygen
3. Spring Boot Application
There are many ways to create a Spring boot application. The easiest way for me is via the Spring starter tool with the steps below:
- Go to:
https://start.spring.io/
- Select
Maven Project,
Java,
and Spring Boot version2.0.3
- Enter the group name as
jcg.zheng.demo
and the artifact name aslogback-demo
- Click
Generate Project
A maven project will be generated and downloaded to your workstation. Import it into your Eclipse workspace.
3.1 Dependency Manages
Pom.xml
manages project’s dependency libraries.
pom.xml
<?xml version="1.0" encoding="UTF-8"?> <project xmlns="http://maven.apache.org/POM/4.0.0" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xsi:schemaLocation="http://maven.apache.org/POM/4.0.0 http://maven.apache.org/xsd/maven-4.0.0.xsd"> <modelVersion>4.0.0</modelVersion> <groupId>jcg.zheng.demo</groupId> <artifactId>logback-demo</artifactId> <version>0.0.1-SNAPSHOT</version> <packaging>jar</packaging> <name>logback-demo</name> <description>Demo project for Spring Boot</description> <parent> <groupId>org.springframework.boot</groupId> <artifactId>spring-boot-starter-parent</artifactId> <version>2.0.3.RELEASE</version> <relativePath /> <!-- lookup parent from repository --> </parent> <properties> <project.build.sourceEncoding>UTF-8</project.build.sourceEncoding> <project.reporting.outputEncoding>UTF-8</project.reporting.outputEncoding> <java.version>1.8</java.version> </properties> <dependencies> <dependency> <groupId>org.springframework.boot</groupId> <artifactId>spring-boot-starter</artifactId> </dependency> <dependency> <groupId>org.springframework.boot</groupId> <artifactId>spring-boot-starter-test</artifactId> <scope>test</scope> </dependency> <dependency> <groupId>javax.mail</groupId> <artifactId>mail</artifactId> <version>1.4.3</version> </dependency> </dependencies> <build> <plugins> <plugin> <groupId>org.springframework.boot</groupId> <artifactId>spring-boot-maven-plugin</artifactId> </plugin> </plugins> </build> </project>
3.2 LogbackDemoApplication
LogbackDemoApplication.java
starts the application. In this step, I will call the processStep
method from TestComponent
and TestComponent2
.
LogbackDemoApplication.java
package jcg.zheng.demo.logbackdemo; import org.slf4j.LoggerFactory; import org.springframework.boot.SpringApplication; import org.springframework.boot.autoconfigure.SpringBootApplication; import org.springframework.context.ApplicationContext; import ch.qos.logback.classic.LoggerContext; import jcg.zheng.demo.logbackdemo.component.TestComponent; import jcg.zheng.demo.logbackdemo.component.TestComponent2; @SpringBootApplication public class LogbackDemoApplication { public static void main(String[] args) { ApplicationContext context = SpringApplication.run(LogbackDemoApplication.class, args); TestComponent testCom = context.getBean(TestComponent.class); testCom.processStep(); TestComponent2 testCom2 = context.getBean(TestComponent2.class); testCom2.processStep(); LoggerContext loggerContext = (LoggerContext) LoggerFactory.getILoggerFactory(); loggerContext.stop(); } }
Note: Line 23-24: Invoking stop
to shudown the Logback’s working thread.
4. Log Messages
To log a message in Logback, you need to follow two steps:
- Obtain a
Logger
object fromorg.slf4j.LoggerFactory
. - Log a message based on the requirements.
4.1 TestComponent
In this step, I created a class and named it TestComponent
which has a processStep
method. Please note that the Logger
name is from the class name.
TestComponent.java
package jcg.zheng.demo.logbackdemo.component; import java.time.Duration; import java.time.Instant; import org.slf4j.Logger; import org.slf4j.LoggerFactory; import org.springframework.stereotype.Component; @Component public class TestComponent { private static final Logger lOG = LoggerFactory.getLogger(TestComponent.class); public static int STEP_COUNT = 10; public void processStep() { Instant start = Instant.now(); lOG.info("*** TestComponent started ***"); for (int i = 0; i < STEP_COUNT; i++) { lOG.info(" Process step {} started.", i); try { Thread.sleep(10); lOG.debug(" Process step {} detail debug message.", i); } catch (InterruptedException e) { e.printStackTrace(); } lOG.info(" Process step {} completed.", i); } Instant end = Instant.now(); lOG.warn("*** TestComponent completed with {} ***" + Duration.between(start, end)); } }
4.2 TestComponent2
Repeat step 4.1, but name the class TestComponent2
instead of TestComponent
and define the Logger
based on the Logback configuration file.
TestComponent2.java
package jcg.zheng.demo.logbackdemo.component; import java.time.Duration; import java.time.Instant; import org.slf4j.Logger; import org.slf4j.LoggerFactory; import org.springframework.stereotype.Component; @Component public class TestComponent2 { private static final String DEFINED_LOGGER = "jcg.zheng.demo.logbackdemo.component.TestComponent2"; private static final Logger lOG = LoggerFactory.getLogger(DEFINED_LOGGER); public static int STEP_COUNT = 10; public void processStep() { Instant start = Instant.now(); lOG.info("*** TestComponent2 started ***"); for (int i = 0; i < STEP_COUNT; i++) { lOG.info(" Process step {} started.", i); try { Thread.sleep(10); lOG.debug(" Process step {} detail debug message.", i); } catch (InterruptedException e) { e.printStackTrace(); } lOG.info(" Process step {} completed.", i); } Instant end = Instant.now(); lOG.warn("*** TestComponent2 completed with {} ***" + Duration.between(start, end)); } }
5. Logback Configuration
logback.xml
manages the Logback configuration. In this step, I will create six Appenders – CONSOLE
, FILE
, EMAIL
, ASYNC_CONSOLE
, ASYNC_FILE
, and ASYNC_EMAIL
.
logback.xml
<configuration debug="true" scan="true" scanPeriod="150 seconds"> <property name="LOG_DIR" value="logs" /> <appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender" target="System.out"> <encoder> <charset>UTF-8</charset> <Pattern>%d %-4relative [%thread] %-5level %logger{35} - %msg%n </Pattern> </encoder> </appender> <appender name="FILE" class="ch.qos.logback.core.FileAppender"> <file>${LOG_DIR}/demo.log</file> <encoder> <charset>UTF-8</charset> <Pattern>%d %-4relative [%thread] %-5level %logger{35} - %msg%n </Pattern> </encoder> </appender> <appender name="EMAIL" class="ch.qos.logback.classic.net.SMTPAppender"> <smtpHost>smtp.gmail.com</smtpHost> <smtpPort>587</smtpPort> <STARTTLS>true</STARTTLS> <username>test@gmail.com</username> <password>*****</password> <to>test@gmail.com</to> <from>test@gmail.com</from> <subject>TESTING: %logger{20} - %m</subject> <layout class="ch.qos.logback.classic.html.HTMLLayout" /> <asynchronousSending>false</asynchronousSending> </appender> <appender name="ASYNC_CONSOLE" class="ch.qos.logback.classic.AsyncAppender"> <discardingThreshold>0</discardingThreshold> <!-- default 20, means drop lower event when has 20% capacity remaining --> <appender-ref ref="CONSOLE" /> <queueSize>1</queueSize> <!-- default 256 --> <includeCallerData>false</includeCallerData><!-- default false --> <neverBlock>true</neverBlock><!-- default false, set to true to cause the Appender not block the application and just drop the messages --> </appender> <appender name="ASYNC_FILE" class="ch.qos.logback.classic.AsyncAppender"> <discardingThreshold>0</discardingThreshold> <!-- default 20, means drop lower event when has 20% capacity remaining --> <appender-ref ref="FILE" /> <queueSize>1</queueSize> <!-- default 256 --> <includeCallerData>false</includeCallerData><!-- default false --> <neverBlock>false</neverBlock><!-- default false, set to true to cause the Appender not block the application and just drop the messages --> </appender> <appender name="ASYNC_EMAIL" class="ch.qos.logback.classic.AsyncAppender"> <discardingThreshold>0</discardingThreshold> <!-- default 20, means drop lower event when has 20% capacity remaining --> <appender-ref ref="EMAIL" /> </appender> <logger name="jcg.zheng.demo.logbackdemo.component.TestComponent" level="info" additivity="false"> <!-- <appender-ref ref="FILE" /> --> <appender-ref ref="ASYNC_FILE" /> <appender-ref ref="ASYNC_EMAIL" /> </logger> <logger name="jcg.zheng.demo.logbackdemo.component.TestComponent2" level="debug" additivity="false"> <!-- <appender-ref ref="FILE" /> --> <appender-ref ref="ASYNC_FILE" /> </logger> <root level="error"> <appender-ref ref="ASYNC_CONSOLE" /> </root> </configuration>
Note:
- Line 37: Config
ASYNC_CONSOLE
to direct toCONSOLE
appender - Line 47: Config
ASYNC_FILE
to direct toFILE
appender - Line 57: Config
ASYNC_EMAIL
to direct toEMAIL
appender - Line 67, 68: Output
jcg.zheng.demo.logbackdemo.component.TestComponent
toASYNC_FILE
andASYNC_EMAIL
- Line 75: Output
jcg.zheng.demo.logbackdemo.component.TestComponent2
toASYNC_FILE
- Line 80: Output
root
toASYNC_CONSOLE
6. Demo
Execute LogbackDemoApplication
and watch the log from the system console as well as the demo.log
file in the logs directory.
Console Log
21:46:59,492 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback-test.xml] 21:46:59,495 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback.groovy] 21:46:59,495 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Found resource [logback.xml] at [file:/C:/gitworkspace/logback-demo/target/classes/logback.xml] 21:46:59,620 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - Will scan for changes in [file:/C:/gitworkspace/logback-demo/target/classes/logback.xml] 21:46:59,622 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - Setting ReconfigureOnChangeTask scanning period to 2 minutes 21:46:59,627 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [ch.qos.logback.core.ConsoleAppender] 21:46:59,630 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [CONSOLE] 21:46:59,640 |-INFO in ch.qos.logback.core.joran.action.NestedComplexPropertyIA - Assuming default type [ch.qos.logback.classic.encoder.PatternLayoutEncoder] for [encoder] property 21:46:59,690 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [ch.qos.logback.core.FileAppender] 21:46:59,695 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [FILE] 21:46:59,697 |-INFO in ch.qos.logback.core.joran.action.NestedComplexPropertyIA - Assuming default type [ch.qos.logback.classic.encoder.PatternLayoutEncoder] for [encoder] property 21:46:59,697 |-INFO in ch.qos.logback.core.FileAppender[FILE] - File property is set to [logs/demo.log] 21:46:59,702 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [ch.qos.logback.classic.net.SMTPAppender] 21:46:59,727 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [EMAIL] 21:46:59,755 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [ch.qos.logback.classic.AsyncAppender] 21:46:59,757 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [ASYNC_CONSOLE] 21:46:59,757 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [CONSOLE] to ch.qos.logback.classic.AsyncAppender[ASYNC_CONSOLE] 21:46:59,757 |-INFO in ch.qos.logback.classic.AsyncAppender[ASYNC_CONSOLE] - Attaching appender named [CONSOLE] to AsyncAppender. 21:46:59,760 |-INFO in ch.qos.logback.classic.AsyncAppender[ASYNC_CONSOLE] - Setting discardingThreshold to 0 21:46:59,760 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [ch.qos.logback.classic.AsyncAppender] 21:46:59,760 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [ASYNC_FILE] 21:46:59,760 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [FILE] to ch.qos.logback.classic.AsyncAppender[ASYNC_FILE] 21:46:59,760 |-INFO in ch.qos.logback.classic.AsyncAppender[ASYNC_FILE] - Attaching appender named [FILE] to AsyncAppender. 21:46:59,760 |-INFO in ch.qos.logback.classic.AsyncAppender[ASYNC_FILE] - Setting discardingThreshold to 0 21:46:59,760 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [ch.qos.logback.classic.AsyncAppender] 21:46:59,760 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [ASYNC_EMAIL] 21:46:59,762 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [EMAIL] to ch.qos.logback.classic.AsyncAppender[ASYNC_EMAIL] 21:46:59,762 |-INFO in ch.qos.logback.classic.AsyncAppender[ASYNC_EMAIL] - Attaching appender named [EMAIL] to AsyncAppender. 21:46:59,762 |-INFO in ch.qos.logback.classic.AsyncAppender[ASYNC_EMAIL] - Setting discardingThreshold to 0 21:46:59,762 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [jcg.zheng.demo.logbackdemo.component.TestComponent] to INFO 21:46:59,762 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting additivity of logger [jcg.zheng.demo.logbackdemo.component.TestComponent] to false 21:46:59,762 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [ASYNC_FILE] to Logger[jcg.zheng.demo.logbackdemo.component.TestComponent] 21:46:59,762 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [ASYNC_EMAIL] to Logger[jcg.zheng.demo.logbackdemo.component.TestComponent] 21:46:59,762 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [jcg.zheng.demo.logbackdemo.component.TestComponent2] to DEBUG 21:46:59,762 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting additivity of logger [jcg.zheng.demo.logbackdemo.component.TestComponent2] to false 21:46:59,762 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [ASYNC_FILE] to Logger[jcg.zheng.demo.logbackdemo.component.TestComponent2] 21:46:59,762 |-INFO in ch.qos.logback.classic.joran.action.RootLoggerAction - Setting level of ROOT logger to ERROR 21:46:59,762 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [ASYNC_CONSOLE] to Logger[ROOT] 21:46:59,765 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - End of configuration. 21:46:59,765 |-INFO in ch.qos.logback.classic.joran.JoranConfigurator@5034c75a - Registering current configuration as safe fallback point 21:47:00,217 |-INFO in ch.qos.logback.classic.AsyncAppender[ASYNC_CONSOLE] - Worker thread will flush remaining events before exiting. 21:47:00,220 |-INFO in ch.qos.logback.classic.AsyncAppender[ASYNC_CONSOLE] - Queue flush finished successfully within timeout. 21:47:00,220 |-INFO in ch.qos.logback.classic.AsyncAppender[ASYNC_FILE] - Worker thread will flush remaining events before exiting. 21:47:00,220 |-INFO in ch.qos.logback.classic.AsyncAppender[ASYNC_FILE] - Queue flush finished successfully within timeout. 21:47:00,220 |-INFO in ch.qos.logback.classic.AsyncAppender[ASYNC_EMAIL] - Worker thread will flush remaining events before exiting. 21:47:00,222 |-INFO in ch.qos.logback.classic.AsyncAppender[ASYNC_EMAIL] - Queue flush finished successfully within timeout. 21:47:00,228 |-WARN in Logger[org.springframework.core.env.PropertySourcesPropertyResolver] - No appenders present in context [default] for logger [org.springframework.core.env.PropertySourcesPropertyResolver]. 21:47:00,238 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - Will scan for changes in [file:/C:/gitworkspace/logback-demo/target/classes/logback.xml] 21:47:00,238 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - Setting ReconfigureOnChangeTask scanning period to 2 minutes 21:47:00,241 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [ch.qos.logback.core.ConsoleAppender] 21:47:00,241 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [CONSOLE] 21:47:00,241 |-INFO in ch.qos.logback.core.joran.action.NestedComplexPropertyIA - Assuming default type [ch.qos.logback.classic.encoder.PatternLayoutEncoder] for [encoder] property 21:47:00,241 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [ch.qos.logback.core.FileAppender] 21:47:00,241 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [FILE] 21:47:00,243 |-INFO in ch.qos.logback.core.joran.action.NestedComplexPropertyIA - Assuming default type [ch.qos.logback.classic.encoder.PatternLayoutEncoder] for [encoder] property 21:47:00,243 |-INFO in ch.qos.logback.core.FileAppender[FILE] - File property is set to [logs/demo.log] 21:47:00,246 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [ch.qos.logback.classic.net.SMTPAppender] 21:47:00,246 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [EMAIL] 21:47:00,251 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [ch.qos.logback.classic.AsyncAppender] 21:47:00,253 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [ASYNC_CONSOLE] 21:47:00,253 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [CONSOLE] to ch.qos.logback.classic.AsyncAppender[ASYNC_CONSOLE] 21:47:00,253 |-INFO in ch.qos.logback.classic.AsyncAppender[ASYNC_CONSOLE] - Attaching appender named [CONSOLE] to AsyncAppender. 21:47:00,253 |-INFO in ch.qos.logback.classic.AsyncAppender[ASYNC_CONSOLE] - Setting discardingThreshold to 0 21:47:00,253 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [ch.qos.logback.classic.AsyncAppender] 21:47:00,253 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [ASYNC_FILE] 21:47:00,253 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [FILE] to ch.qos.logback.classic.AsyncAppender[ASYNC_FILE] 21:47:00,253 |-INFO in ch.qos.logback.classic.AsyncAppender[ASYNC_FILE] - Attaching appender named [FILE] to AsyncAppender. 21:47:00,253 |-INFO in ch.qos.logback.classic.AsyncAppender[ASYNC_FILE] - Setting discardingThreshold to 0 21:47:00,253 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [ch.qos.logback.classic.AsyncAppender] 21:47:00,253 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [ASYNC_EMAIL] 21:47:00,256 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [EMAIL] to ch.qos.logback.classic.AsyncAppender[ASYNC_EMAIL] 21:47:00,256 |-INFO in ch.qos.logback.classic.AsyncAppender[ASYNC_EMAIL] - Attaching appender named [EMAIL] to AsyncAppender. 21:47:00,256 |-INFO in ch.qos.logback.classic.AsyncAppender[ASYNC_EMAIL] - Setting discardingThreshold to 0 21:47:00,256 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [jcg.zheng.demo.logbackdemo.component.TestComponent] to INFO 21:47:00,256 |-INFO in ch.qos.logback.classic.jul.LevelChangePropagator@71c8becc - Propagating INFO level on Logger[jcg.zheng.demo.logbackdemo.component.TestComponent] onto the JUL framework 21:47:00,256 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting additivity of logger [jcg.zheng.demo.logbackdemo.component.TestComponent] to false 21:47:00,256 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [ASYNC_FILE] to Logger[jcg.zheng.demo.logbackdemo.component.TestComponent] 21:47:00,256 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [ASYNC_EMAIL] to Logger[jcg.zheng.demo.logbackdemo.component.TestComponent] 21:47:00,256 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [jcg.zheng.demo.logbackdemo.component.TestComponent2] to DEBUG 21:47:00,256 |-INFO in ch.qos.logback.classic.jul.LevelChangePropagator@71c8becc - Propagating DEBUG level on Logger[jcg.zheng.demo.logbackdemo.component.TestComponent2] onto the JUL framework 21:47:00,256 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting additivity of logger [jcg.zheng.demo.logbackdemo.component.TestComponent2] to false 21:47:00,256 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [ASYNC_FILE] to Logger[jcg.zheng.demo.logbackdemo.component.TestComponent2] 21:47:00,256 |-INFO in ch.qos.logback.classic.joran.action.RootLoggerAction - Setting level of ROOT logger to ERROR 21:47:00,256 |-INFO in ch.qos.logback.classic.jul.LevelChangePropagator@71c8becc - Propagating ERROR level on Logger[ROOT] onto the JUL framework 21:47:00,256 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [ASYNC_CONSOLE] to Logger[ROOT] 21:47:00,258 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - End of configuration. 21:47:00,258 |-INFO in org.springframework.boot.logging.logback.SpringBootJoranConfigurator@a4102b8 - Registering current configuration as safe fallback point . ____ _ __ _ _ /\\ / ___'_ __ _ _(_)_ __ __ _ \ \ \ \ ( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \ \\/ ___)| |_)| | | | | || (_| | ) ) ) ) ' |____| .__|_| |_|_| |_\__, | / / / / =========|_|==============|___/=/_/_/_/ :: Spring Boot :: (v2.0.3.RELEASE) 21:47:01,778 |-INFO in ch.qos.logback.classic.net.SMTPAppender[EMAIL] - SMTPAppender [EMAIL] is tracking [1] buffers 21:47:01,984 |-INFO in ch.qos.logback.classic.AsyncAppender[ASYNC_CONSOLE] - Worker thread will flush remaining events before exiting. 21:47:01,984 |-INFO in ch.qos.logback.classic.AsyncAppender[ASYNC_CONSOLE] - Queue flush finished successfully within timeout. 21:47:01,984 |-INFO in ch.qos.logback.classic.AsyncAppender[ASYNC_FILE] - Worker thread will flush remaining events before exiting. 21:47:01,987 |-INFO in ch.qos.logback.classic.AsyncAppender[ASYNC_FILE] - Queue flush finished successfully within timeout. 21:47:01,987 |-INFO in ch.qos.logback.classic.AsyncAppender[ASYNC_EMAIL] - Worker thread will flush remaining events before exiting. 21:47:01,987 |-INFO in ch.qos.logback.classic.AsyncAppender[ASYNC_EMAIL] - Queue flush finished successfully within timeout.
Demo.Log
2018-08-13 21:47:01,776 2326 [main] INFO j.z.d.l.component.TestComponent - *** TestComponent started *** 2018-08-13 21:47:01,778 2328 [main] INFO j.z.d.l.component.TestComponent - Process step 0 started. 2018-08-13 21:47:01,789 2339 [main] INFO j.z.d.l.component.TestComponent - Process step 0 completed. 2018-08-13 21:47:01,789 2339 [main] INFO j.z.d.l.component.TestComponent - Process step 1 started. 2018-08-13 21:47:01,799 2349 [main] INFO j.z.d.l.component.TestComponent - Process step 1 completed. 2018-08-13 21:47:01,799 2349 [main] INFO j.z.d.l.component.TestComponent - Process step 2 started. 2018-08-13 21:47:01,809 2359 [main] INFO j.z.d.l.component.TestComponent - Process step 2 completed. 2018-08-13 21:47:01,809 2359 [main] INFO j.z.d.l.component.TestComponent - Process step 3 started. 2018-08-13 21:47:01,819 2369 [main] INFO j.z.d.l.component.TestComponent - Process step 3 completed. 2018-08-13 21:47:01,819 2369 [main] INFO j.z.d.l.component.TestComponent - Process step 4 started. 2018-08-13 21:47:01,829 2379 [main] INFO j.z.d.l.component.TestComponent - Process step 4 completed. 2018-08-13 21:47:01,829 2379 [main] INFO j.z.d.l.component.TestComponent - Process step 5 started. 2018-08-13 21:47:01,839 2389 [main] INFO j.z.d.l.component.TestComponent - Process step 5 completed. 2018-08-13 21:47:01,839 2389 [main] INFO j.z.d.l.component.TestComponent - Process step 6 started. 2018-08-13 21:47:01,849 2399 [main] INFO j.z.d.l.component.TestComponent - Process step 6 completed. 2018-08-13 21:47:01,849 2399 [main] INFO j.z.d.l.component.TestComponent - Process step 7 started. 2018-08-13 21:47:01,864 2414 [main] INFO j.z.d.l.component.TestComponent - Process step 7 completed. 2018-08-13 21:47:01,864 2414 [main] INFO j.z.d.l.component.TestComponent - Process step 8 started. 2018-08-13 21:47:01,874 2424 [main] INFO j.z.d.l.component.TestComponent - Process step 8 completed. 2018-08-13 21:47:01,874 2424 [main] INFO j.z.d.l.component.TestComponent - Process step 9 started. 2018-08-13 21:47:01,884 2434 [main] INFO j.z.d.l.component.TestComponent - Process step 9 completed. 2018-08-13 21:47:01,884 2434 [main] WARN j.z.d.l.component.TestComponent - *** TestComponent completed with {} ***PT0.108S 2018-08-13 21:47:01,884 2434 [main] INFO j.z.d.l.component.TestComponent2 - *** TestComponent2 started *** 2018-08-13 21:47:01,884 2434 [main] INFO j.z.d.l.component.TestComponent2 - Process step 0 started. 2018-08-13 21:47:01,894 2444 [main] DEBUG j.z.d.l.component.TestComponent2 - Process step 0 detail debug message. 2018-08-13 21:47:01,894 2444 [main] INFO j.z.d.l.component.TestComponent2 - Process step 0 completed. 2018-08-13 21:47:01,894 2444 [main] INFO j.z.d.l.component.TestComponent2 - Process step 1 started. 2018-08-13 21:47:01,904 2454 [main] DEBUG j.z.d.l.component.TestComponent2 - Process step 1 detail debug message. 2018-08-13 21:47:01,904 2454 [main] INFO j.z.d.l.component.TestComponent2 - Process step 1 completed. 2018-08-13 21:47:01,904 2454 [main] INFO j.z.d.l.component.TestComponent2 - Process step 2 started. 2018-08-13 21:47:01,914 2464 [main] DEBUG j.z.d.l.component.TestComponent2 - Process step 2 detail debug message. 2018-08-13 21:47:01,914 2464 [main] INFO j.z.d.l.component.TestComponent2 - Process step 2 completed. 2018-08-13 21:47:01,914 2464 [main] INFO j.z.d.l.component.TestComponent2 - Process step 3 started. 2018-08-13 21:47:01,924 2474 [main] DEBUG j.z.d.l.component.TestComponent2 - Process step 3 detail debug message. 2018-08-13 21:47:01,924 2474 [main] INFO j.z.d.l.component.TestComponent2 - Process step 3 completed. 2018-08-13 21:47:01,924 2474 [main] INFO j.z.d.l.component.TestComponent2 - Process step 4 started. 2018-08-13 21:47:01,934 2484 [main] DEBUG j.z.d.l.component.TestComponent2 - Process step 4 detail debug message. 2018-08-13 21:47:01,934 2484 [main] INFO j.z.d.l.component.TestComponent2 - Process step 4 completed. 2018-08-13 21:47:01,934 2484 [main] INFO j.z.d.l.component.TestComponent2 - Process step 5 started. 2018-08-13 21:47:01,944 2494 [main] DEBUG j.z.d.l.component.TestComponent2 - Process step 5 detail debug message. 2018-08-13 21:47:01,944 2494 [main] INFO j.z.d.l.component.TestComponent2 - Process step 5 completed. 2018-08-13 21:47:01,944 2494 [main] INFO j.z.d.l.component.TestComponent2 - Process step 6 started. 2018-08-13 21:47:01,954 2504 [main] DEBUG j.z.d.l.component.TestComponent2 - Process step 6 detail debug message. 2018-08-13 21:47:01,954 2504 [main] INFO j.z.d.l.component.TestComponent2 - Process step 6 completed. 2018-08-13 21:47:01,954 2504 [main] INFO j.z.d.l.component.TestComponent2 - Process step 7 started. 2018-08-13 21:47:01,964 2514 [main] DEBUG j.z.d.l.component.TestComponent2 - Process step 7 detail debug message. 2018-08-13 21:47:01,964 2514 [main] INFO j.z.d.l.component.TestComponent2 - Process step 7 completed. 2018-08-13 21:47:01,964 2514 [main] INFO j.z.d.l.component.TestComponent2 - Process step 8 started. 2018-08-13 21:47:01,974 2524 [main] DEBUG j.z.d.l.component.TestComponent2 - Process step 8 detail debug message. 2018-08-13 21:47:01,974 2524 [main] INFO j.z.d.l.component.TestComponent2 - Process step 8 completed. 2018-08-13 21:47:01,974 2524 [main] INFO j.z.d.l.component.TestComponent2 - Process step 9 started. 2018-08-13 21:47:01,984 2534 [main] DEBUG j.z.d.l.component.TestComponent2 - Process step 9 detail debug message. 2018-08-13 21:47:01,984 2534 [main] INFO j.z.d.l.component.TestComponent2 - Process step 9 completed. 2018-08-13 21:47:01,984 2534 [main] WARN j.z.d.l.component.TestComponent2 - *** TestComponent2 completed with {} ***PT0.1S
6.1 Logback AsyncAppender Configuration Options
AsyncAppender has five configuration options. The application developer should adjust them based on the logging requirements.
queueSize
– The maximum capacity of the buffer size. Default value is 256.discardingThreshold
– Instruct to drop events once the buffer reaches the max capacity. Default value is 20%.neverBlock
– Setting it to true will prevent any blocking on the application threads but it comes at the cost of lost log events if the AsyncAppender’s internal buffer fills up. Default value is false.includeCallerData
– Extracting caller data. Default value is false.maxFlushTime
– Specify a maximum queue flush timeout in milliseconds
You can change these configuration option values in the logback.xml
and verify it with the log output.
7. Summary
In this article, we covered the usage of Logback AsyncAppender
in a Spring Boot application. We demonstrated three configuration examples in AsyncAppender
for ConsoleAppender
, FileAppender
, and SMTPAppender
.
8. Download the Source Code
This example consists of a Spring Boot application to demonstrate the usage of Logback AsyncAppender
.
You can download the full source code of this example here: Logback AsyncAppender Example