Logback AsyncAppender Example

Mary ZhengAugust 16th, 2018Last Updated: August 14th, 2018

0 3,937 12 minutes read

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 version 2.0.3
Enter the group name as jcg.zheng.demo and the artifact name as logback-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 from org.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 to CONSOLE appender
Line 47: Config ASYNC_FILE to direct to FILE appender
Line 57: Config ASYNC_EMAIL to direct to EMAIL appender
Line 67, 68: Output jcg.zheng.demo.logbackdemo.component.TestComponent to ASYNC_FILE and ASYNC_EMAIL
Line 75: Output jcg.zheng.demo.logbackdemo.component.TestComponent2 to ASYNC_FILE
Line 80: Output root to ASYNC_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.

Download
You can download the full source code of this example here: Logback AsyncAppender Example

Logback AsyncAppender Example

1. Introduction

2. Technologies Used

3. Spring Boot Application

3.1 Dependency Manages

3.2 LogbackDemoApplication

4. Log Messages

4.1 TestComponent

4.2 TestComponent2

5. Logback Configuration

6. Demo

6.1 Logback AsyncAppender Configuration Options

7. Summary

8. Download the Source Code

Thank you!

Mary Zheng

Thank you!

1. Introduction

2. Technologies Used

3. Spring Boot Application

3.1 Dependency Manages

3.2 LogbackDemoApplication

4. Log Messages

4.1 TestComponent

4.2 TestComponent2

5. Logback Configuration

6. Demo

6.1 Logback AsyncAppender Configuration Options

7. Summary

8. Download the Source Code

Thank you!

Related Articles

Thank you!