Logging asynchronously with logback

Motivation
Sometimes it may be useful to send log information about parts of the application execution to another system, like a monitoring system. In this post I'll show an example of how to log information in a JMS Queue using the logback JMSQueueAppender appender.

Project sample
For the purpose of this post, I created two projects in my GitHub repository. They can be found here:

https://github.com/mroger/logback-async-appender.git

To clone it using git, type the following command in your terminal, under the folder where you want to keep the project (First time using git? Click here):

    git clone https://github.com/mroger/logback-async-appender.git

Projects descriptions
logback-async-appender/spring-jms: a simple Spring Boot JMS consumer. It will consume our log messages.

logback-async-appender/logback-async: the project that declares the JMS appender and the logback configuration and logs messages. We'll use ActiveMQ as queue provider.

Putting it to work
As this is a demo with several moving parts, it takes some steps to its complete execution.

1. First of all,  you need an ActiveMQ up and running in your environment, configured to listen to connections in default port (61616). In your running ActiveMQ, create a queue with the name 'queue.logback-queue'.

2. Now start the JMS consumer in a separate console. Use the command below in a new shell window, under the spring-jms project folder:

    mvn spring-boot:run

3. Now, as the last step, let´s start the application that log execution to an JMS appender. In an yet another shell window, execute the command below, under the logback-async folder:

    mvn exec:java

Once it´s executed the following message can be seen in the shell where the spring-jms was started:

(...) b.o.r.s.SimpleListener - Message 'Message sent to the configured appender.' received.

How it works
The spring-jms project is really simple: one main class and one class that serves as JMS listener. This listener deserves some explanation, though.

	@Component
	public class SimpleListener {
	private static final Logger LOGGER = LoggerFactory.getLogger(SimpleListener.class);
	@JmsListener(destination = "queue.logback-queue")
	public void receiveOrder(Message message) throws JMSException {
	LoggingEventVO loggingEventVO = (LoggingEventVO) ((ActiveMQObjectMessage)message).getObject();
	LOGGER.info("Message '{}' received.", loggingEventVO.getMessage());
	}
	}

view raw SimpleActiveMQListener.java hosted with ❤ by GitHub

The physical name of the queue is the value of the destination parameter in the @JmsListener annotation.
And notice that there is a cast of the message to ActiveMQObjectMessage and then to LoggingEventVO. Those are classes from ActiveMQ and Logback libraries, respectively, so they are needed as dependencies in your listener application.

The Main class in the logback-async project is responsible for sending the log message through JMS appender.

	public class Main {
	private static final String JMS_LOGGER_CATEGORY = "JMS_LOGGER";
	private static final Logger LOGGER = LoggerFactory.getLogger(Main.class);
	private static final Logger JMS_LOGGER = LoggerFactory.getLogger(JMS_LOGGER_CATEGORY);
	public static void main(String[] args) {
	Stopwatch stopwatch = new Stopwatch();
	JMS_LOGGER.info("Message sent to the configured appender.");
	double elapsedTime = stopwatch.elapsedTimeInMillis();
	LOGGER.info("LOGGER.info() method took {} ms to execute", String.format("%1.12f", elapsedTime));
	ILoggerFactory loggerFactory = LoggerFactory.getILoggerFactory();
	if (loggerFactory instanceof LoggerContext) {
	LoggerContext context = (LoggerContext) loggerFactory;
	context.stop();
	}
	}
	}

view raw LogbackJMSSenderClass.java hosted with ❤ by GitHub

There are two defined loggers, LOGGER for console appender and JMS_LOGGER for the JMS appender, so it's possible to send different types of messages to distinct appenders.

Stopwatch is an utility a class that is used to calculate how much time was spent sending message to the JMSAppender. Later in this post we'll analyze some interesting results.

And in the last lines of the main() method there is a call to stop the logger context, needed to shut down the JMSAppender. We'll also see that in detail later.

The jndi.properties file has the ActiveMQ queue configuration. The queue.logback-queue is the physical name of the queue and is the name used to create que queue in ActiveMQ. The my-logback-queue is a reference and is used to configure the JMS appender in the logback configuration file as seen in the next code snippet.

	java.naming.factory.initial = org.apache.activemq.jndi.ActiveMQInitialContextFactory
	java.naming.provider.url = tcp://localhost:61616
	connectionFactoryNames = queueConnectionFactory
	queue.my-logback-queue = queue.logback-queue

view raw jndi.properties hosted with ❤ by GitHub

In the logback.xml configuration file below we can see the JMSQueueAppender configured. It uses the ActiveMQ default connection resources.
The QueueBindingName is the queue name specified in the properties file seen above.

The additivity attribute was set to false in the logger configuration so that only loggers that write to that specific log category have its messages sent to the specified appender.

	<configuration>
	<appender name="console" class="ch.qos.logback.core.ConsoleAppender">
	<layout class="ch.qos.logback.classic.PatternLayout">
	<Pattern>%date [%thread] %-5level %logger{25} - %msg%n</Pattern>
	</layout>
	</appender>
	<appender name="file" class="ch.qos.logback.core.FileAppender">
	<file>logs/main.log</file>
	<append>true</append>
	<encoder>
	<Pattern>%date [%thread] %-5level %logger{25} - %msg%n</Pattern>
	</encoder>
	</appender>
	<appender name="queue" class="ch.qos.logback.classic.net.JMSQueueAppender">
	<InitialContextFactoryName>
	org.apache.activemq.jndi.ActiveMQInitialContextFactory
	</InitialContextFactoryName>
	<ProviderURL>tcp://localhost:61616</ProviderURL>
	<QueueConnectionFactoryBindingName>queueConnectionFactory</QueueConnectionFactoryBindingName>
	<QueueBindingName>my-logback-queue</QueueBindingName>
	</appender>
	<logger name="JMS_LOGGER" level="INFO" additivity="false">
	<appender-ref ref="queue" />
	</logger>
	<logger name="br.org.roger.logback" level="INFO" additivity="false">
	<appender-ref ref="console" />
	</logger>
	<root level="INFO">
	<appender-ref ref="console" />
	</root>
	</configuration>

view raw logback.xml hosted with ❤ by GitHub

Caveats
Some caution is needed when adopting this solution.

For example, as said earlier,  the code below is needed when sending messages to a JMSAppender. That´s because the JMSQueueAppender class does not release JMS resources by itself.

	ILoggerFactory loggerFactory = LoggerFactory.getILoggerFactory();
	if (loggerFactory instanceof LoggerContext) {
	LoggerContext context = (LoggerContext) loggerFactory;
	context.stop();
	}

view raw LogbackStopContext.java hosted with ❤ by GitHub

In an web application you would put that code in the contextDestroyed method of  a ServletContextListener implementation.

Another issue that you have to keep in mind is that sending messages to a JMS appender performs poorly compared to a console or file appender, for example. Sending one message in the Main class above took 50ms in average. Differently from console and file appender, more messages means much more processing time. If you change the code in class Main to send a thousand messages

	Stopwatch stopwatch = new Stopwatch();
	for (int i = 0 ; i < 1000 ; i++) {
	JMS_LOGGER.info("Message sent to the configured appender.");
	}
	double elapsedTime = stopwatch.elapsedTimeInMillis();
	LOGGER.info("LOGGER.info() method took {} ms to execute", String.format("%1.12f", elapsedTime));

view raw ThousandMessages.java hosted with ❤ by GitHub

you´ll notice that there is a considerable increase in processing time. Now it takes about 3s to execute. The good news is that if your queue broker is out, the JMS does not get in your way; it fails immediately, consuming almost no processing time. You can test this shutting down ActiveMQ and executing the logback-async project.

And finally, but not exactly an issue, with logback JMSQueueAppender you cannot use the SLF4J formatter to format your messages using parameters. The LoggingEventVO in  LoggingEventPreSerializationTransformer, in order to enhance performance, ignores the ILoggingEvent formattedMessage attribute.

Conclusion
Using a JMSAppender may be of a great help when there is a need to send log information outside the system border. Just be careful not to log too much information.

Thank You
Please let me know if you have any questions or if this post somehow helped you in your projects, dropping some lines in the comments below.
To follow my updates to this library and my other projects:

Follow @mr0ger