Log4j2 Logging: A Primer
Logging is required in any application that we write. This is one of the most common components that developers across different industries are required to understand. Long running systems are more understandable and maintainable if logging is done correctly within these systems. Some of the important reasons I find logging useful:
During Development
- To allow debugging programs especially for distributed systems.
- To quickly identify the failure point within a system.
- To understand the code flow for a given system capability.
During Production
- To register anomalies with in the system.
- To register temporary failures
- To register permanent failures
- To provide information regarding any of the above events so that developers / dev-ops can gather enough context to understand why they happened.
To allow to infer the above information, the logging systems generally provide the following capabilities:
- Allow formatting the message such that, most commonly required fields like time / source of message are printed along with the message, without the developer being required to provide this every time he tries to log a message. This allows developers concentrate on the important bits of the message throughout the development of the system. It also allows them to create a representation of the message that would the application most. For Ex: some developers might print time at the beginning of every message, others might prefer the class / source of the message.
- Custom destinations to write messages to. Most basic destinations provided by all logging systems are System Console and A File at some location. A few other common destinations are Databases , network service etc.
- Ability to control the flow of information / messages to various destinations. This most commonly accomplished by assigning a priority to the message and then filtering messages to a given destination based on what the destination accepts.
- Ability to configure different destinations for different messages, different priorities.
- A stand alone library / component that can be easily integrated into any system without affecting other dependencies of the system.
I am going to discuss a few ways of using the log4j2 library using 2.7 version. The log4j2 documentation is a great place to get detailed information about how to use the log4j2 system. I am going to list down some of the common modes of configuring log4j2 for different scenarios, they will be listed from simple → complex. I am going to use maven for building the project.
<dependency>
<groupId>org.apache.logging.log4j</groupId>
<artifactId>log4j-api</artifactId>
<version>2.7</version>
</dependency>
<dependency>
<groupId>org.apache.logging.log4j</groupId>
<artifactId>log4j-core</artifactId>
<version>2.7</version>
</dependency>
All configurations for log4j are done using log4j2.xml. To start off the initial log4j2.xml is as below:
<Configuration status="debug">
<Appenders>
<File name="file-log" fileName="/tmp/logging.out" append="false">
<PatternLayout>
<pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [%t] %C - %msg%n</pattern>
</PatternLayout>
</File>
</Appenders>
<Loggers>
<Logger name="com.anishek" level="info" additivity="false">
<appender-ref ref="file-log" level="info"/>
</Logger>
</Loggers>
</Configuration>
Scenario 1: Just print a message from a class to a specific logger. This is achieved by the following code:
package com.anishek.logging;
import org.apache.logging.log4j.LogManager;
public class Start {
public static void main(String[] args) {
LogManager.getLogger(Start.class).info("log something that will be useful.");
}
}
which will print the following message in /tmp/logging.out
2016-12-29 16:34:52.126 [main] com.anishek.logging.Start - log something that will be useful.
The way this works is in the log config xml the </Loggers> tag defines the association between the java packages and the log destination, in our case any log from a java class which is under the package com.anishek(this is nothing but a string matcher) and the destination is the log file @ /tmp/logging.out. Additionally, we also specify that only allow messages of priority level info or above to be printed. The various build in priority levels are defined here for log4j2. As you will see the framework provides certain log levels for ease of use, but the developers can always define custom priority levels if need be for their applications.
Scenario 2: Print Log messages selectively across different destinations. There can be different combinations you might need for example
- from same class different priority messages exclusively going to different logs.
<?xml version="1.0" encoding="UTF-8"?>
<Configuration status="debug">
<Appenders>
<File name="file-log" fileName="/tmp/logging.out" append="false">
<PatternLayout>
<pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [%t] %C - %msg%n</pattern>
</PatternLayout>
</File>
<File name="file-log-2" fileName="/tmp/error.out" append="false">
<PatternLayout>
<pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [%t] %C - %msg%n</pattern>
</PatternLayout>
</File>
</Appenders>
<Loggers>
<Logger name="com.anishek-info" level="info" additivity="false">
<appender-ref ref="file-log" level="info"/>
</Logger>
<Logger name="com.anishek-error" level="error" additivity="false">
<appender-ref ref="file-log-2" level="error"/>
</Logger>
</Loggers>
</Configuration>
with code as:
LogManager.getLogger("com.anishek-info").info("log something that will be useful.");
LogManager.getLogger("com.anishek-error").error("A critical event occurred and we want to separately track this.");
and output as :
$ cat /tmp/logging.out
2016-12-29 17:12:15.662 [main] com.anishek.logging.Start - log something that will be useful.
$ cat /tmp/error.out
2016-12-29 17:12:15.667 [main] com.anishek.logging.Start - A critical event occurred and we want to separately track this.
As you can see we have configured two different loggers com.anishek-info / com.anishek-error which write to two different destinations(files). This allows us to only have messages of respective priority to only be written to respective destinations. We also have to make sure that when we write messages we write to the correct logger in code. This can be seen by how we get the loggers to write messages.
LogManager.getLogger(“com.anishek-info”) → this is used for info messages only
LogManager.getLogger(“com.anishek-error”) → this is used for error messages only
The problem with this kind of logging approach is that the developer has to specifically know which priority messages are to go to which logger hence the names com.anishek-info / com.anishek-error . This becomes unnecessary burden on the developer to keep track of the mapping at all times such that he invokes the correct logger to send messagse.
- a better approach from the previous mode would be to, additionally send messages of high priority ( error ) from same class (all classes) to a separate logger. This can be achieved using
<Configuration status="debug">
<Appenders>
<File name="file-log" fileName="/tmp/logging.out" append="false">
<PatternLayout>
<pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [%t] %C - %msg%n</pattern>
</PatternLayout>
</File>
<File name="file-log-2" fileName="/tmp/error.out" append="false">
<PatternLayout>
<pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [%t] %C - %msg%n</pattern>
</PatternLayout>
</File>
</Appenders>
<Loggers>
<Logger name="com.anishek" level="info" additivity="false">
<appender-ref ref="file-log" level="info"/>
<appender-ref ref="file-log-2" level="error"/>
</Logger>
</Loggers>
</Configuration>
we can fall back to our original mode of getting a logger for a class and the code now becomes:
Logger logger = LogManager.getLogger(Start.class);
logger.info("log something that will be useful.");
logger.error("A critical event occurred and we want to separately track this.");
and thus the output now is as:
$ cat /tmp/logging.out
2016-12-29 17:08:15.998 [main] com.anishek.logging.Start - log something that will be useful.
2016-12-29 17:08:15.999 [main] com.anishek.logging.Start - A critical event occurred and we want to separately track this.$ cat /tmp/error.out
2016-12-29 17:08:15.999 [main] com.anishek.logging.Start - A critical event occurred and we want to separately track this.
The above approach allows us to still filter and send important messages to a specific destination. Log4j2 provides various destinations that can be configured as appenders.
We have till now configured loggers at a high level package like com.anishek, We might want to configure different loggers based on different functionalities in certain sub level packages like for example :
com.anishek.service → service.log
com.anishek.ui → ui.log
com.anishek.domain → domain.log
etc which can be done via a sample configuration as below:
<?xml version="1.0" encoding="UTF-8"?>
<Configuration status="debug">
<Appenders>
<File name="ui-log" fileName="/tmp/ui.out" append="false">
<PatternLayout>
<pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [%t] %C - %msg%n</pattern>
</PatternLayout>
</File>
<File name="service-log" fileName="/tmp/service.out" append="false">
<PatternLayout>
<pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [%t] %C - %msg%n</pattern>
</PatternLayout>
</File>
<File name="domain-log" fileName="/tmp/domain.out" append="false">
<PatternLayout>
<pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [%t] %C - %msg%n</pattern>
</PatternLayout>
</File>
</Appenders>
<Loggers>
<Logger name="com.anishek.ui" level="info" additivity="false">
<appender-ref ref="ui-log" level="info"/>
</Logger>
<Logger name="com.anishek.service" level="info" additivity="false">
<appender-ref ref="service-log" level="info"/>
</Logger>
<Logger name="com.anishek.domain" level="info" additivity="false">
<appender-ref ref="domain-log" level="info"/>
</Logger>
</Loggers>
</Configuration>
Scenario 3: If we have different loggers for different packages but still want to log errors from any package additionally to an error file
The log configuration we can use is
<?xml version="1.0" encoding="UTF-8"?>
<Configuration status="debug">
<Appenders>
<File name="ui-log" fileName="/tmp/ui.out" append="false">
<PatternLayout>
<pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [%t] %C - %msg%n</pattern>
</PatternLayout>
</File>
<File name="service-log" fileName="/tmp/service.out" append="false">
<PatternLayout>
<pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [%t] %C - %msg%n</pattern>
</PatternLayout>
</File>
<File name="domain-log" fileName="/tmp/domain.out" append="false">
<PatternLayout>
<pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [%t] %C - %msg%n</pattern>
</PatternLayout>
</File>
<File name="error-log" fileName="/tmp/error.out" append="false" level="">
<PatternLayout>
<pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} %level [%t] %C - %msg%n</pattern>
</PatternLayout>
</File>
</Appenders>
<Loggers>
<Logger name="com.anishek.ui" level="info">
<appender-ref ref="ui-log" level="info"/>
</Logger>
<Logger name="com.anishek.service" level="info">
<appender-ref ref="service-log" level="info"/>
</Logger>
<Logger name="com.anishek.domain" level="info">
<appender-ref ref="domain-log" level="info"/>
</Logger>
<Logger name="com" level="error">
<appender-ref ref="error-log" level="error"/>
</Logger>
</Loggers>
</Configuration>
Looking at the previous scenarios we could have configured a additional appender-ref ( <appender-ref ref=”error-log” level=”error”/> ) for the existing ui/service/domain loggers. This would just make it difficult for a new developer, who wants to introduce a new logger for his module to also additionally incorporate the the error-log appender-ref. He would have to understand in detail the overall log setup for the system. Rather he can just worry about his module, if the configuration was initially setup using a hierarchical error-log appender-ref for the pattern “com” as above. A great place to understand these hierarchy of loggers is here.
Most of the production applications are multi threaded. We will now look at some use cases in such a environment.
Scenario 4: Associate logical association of messages with a single thread.
If we have just one user interacting with an application doing an operation which be accomplished using a single thread with in the application, then all log messages (say about 100 of them) can easily be associated with the user or a thread ( if server does not need to identify the user to do the action ). However if there are multiple users are simultaneously interacting with the application then the similar log messages will be emitted across all users with messages interleaved in the file from different users. The only way to group information per thread would be to log along with every message a thread identifier. This is another repeated information that is logged across all log statements in the application, an easy way to achieve the same is to use %t in the <pattern> section across different appenders. This would lead to printing the thread name along with the message which can then be grep from the log file.
Scenario 5: If any action on the application is performed in the context of a user, then we need the user identifier to logged with every message.
This can be achieved by providing access to the current user identifier (session) to all classes in the system and then log the user identifier explicitly along with each message. This is again more cumbersome and an activity which you have to keep doing every time more code changes are done to the code.
A better way to do the same would be to use the Diagnostic Context feature that log4j2 provides. log4j2 provides org.apache.logging.log4j.ThreadContext class with static methods to achieve the above to create MDC (Mapped Diagnostic Context). This means that there are static put(key, value) and remove(key) methods that can be used to populate a map maintained by ThreadContext to store data which can be printed along with every message by adding %X to the <pattern>element of the log4j2.xml configuration. This would mean every time you log something, the log4j2 framework will look at the contents of the map in ThreadContext and print all the (key, value) pairs in the log along with the log message. Adding data to ThreadContext can be done at any point of time along the execution flow, obviously only logging statements after the population of the ThreadContext map can access the data. A detailed list of various patterns that can configured in the layout can be found here.
More fine grained logging of the context can be done. Also if the application creates additional Threads to execute a user operation then the context can be passed from parent thread to child threads by doing a specific configuration as part of application / log4j2 startup. This is done by setting isThreadContextMapInheritable to “true”.
<?xml version="1.0" encoding="UTF-8"?>
<Configuration status="debug">
<Appenders>
<File name="default-log" fileName="/tmp/default.out" append="false">
<PatternLayout>
<pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} %level [%t] %C - %X %msg%n</pattern>
</PatternLayout>
</File>
</Appenders>
<Loggers>
<Logger name="com.anishek" level="info" additivity="false">
<appender-ref ref="default-log" level="info"/>
</Logger>
</Loggers>
</Configuration>
with the code being:
package com.anishek.logging;
import org.apache.logging.log4j.LogManager;
import org.apache.logging.log4j.Logger;
import org.apache.logging.log4j.ThreadContext;
public class Start {
public static void main(String[] args) {
ThreadContext.put("useId", "testUser");
Logger logger = LogManager.getLogger(Start.class);
logger.info("log something from parent thread.");
new Thread(() -> logger.info("log something from child thread")).start();
}
and the logs being:
2016-12-30 17:11:22.880 INFO [main] com.anishek.logging.Start - {useId=testUser} log something from parent thread.
2016-12-30 17:11:22.886 INFO [Thread-1] com.anishek.logging.Start - {} log something from child thread
if we now set the property in the code as :
package com.anishek.logging;
import org.apache.logging.log4j.LogManager;
import org.apache.logging.log4j.Logger;
import org.apache.logging.log4j.ThreadContext;
public class Start {
public static void main(String[] args) {
System.setProperty("isThreadContextMapInheritable", "true");
ThreadContext.put("useId", "testUser");
Logger logger = LogManager.getLogger(Start.class);
logger.info("log something from parent thread.");
new Thread(() -> logger.info("log something from child thread")).start();
}
and run it again with the same configuration , the log output will be:
2016-12-30 17:13:52.636 INFO [main] com.anishek.logging.Start - {useId=testUser} log something from parent thread.
2016-12-30 17:13:52.641 INFO [Thread-1] com.anishek.logging.Start - {useId=testUser} log something from child thread
We can also set the property as “-D isThreadContextMapInheritable=true” when we start our application. A detailed list of various system properties that is used by log4j2 are available here. One thing we have to be very careful about, when using the ThreadContext is that, the developer should call the appropriate clearAll / remove / clearMap / clearStack / removeStack method when the thread execution finishes so that the thread local state is clear. This is particularly required when applications create thread pools to execute some sub tasks. The following code demonstrates the above:
package com.anishek.logging;
import org.apache.logging.log4j.LogManager;
import org.apache.logging.log4j.Logger;
import org.apache.logging.log4j.ThreadContext;
import java.util.concurrent.ExecutorService;
import java.util.concurrent.Executors;
import java.util.concurrent.ThreadFactory;
import java.util.concurrent.TimeUnit;
import java.util.concurrent.atomic.AtomicInteger;
public class MultiThreaded {
public static void main(String[] args) throws InterruptedException {
System.setProperty("isThreadContextMapInheritable", "true");
ExecutorService poolOne = Executors.newFixedThreadPool(3, threadFactory("pool-1-"));
ExecutorService poolTwo = Executors.newFixedThreadPool(1, threadFactory("pool-2-"));
AtomicInteger atomicInteger = new AtomicInteger(1);
Logger logger = LogManager.getLogger(MultiThreaded.class);
Runnable runnableTwo = () -> logger.info("now we are in another");
Runnable runnableOne = () -> {
String value = String.valueOf(atomicInteger.getAndIncrement());
ThreadContext.put(value, value);
ThreadContext.put("thread", Thread.currentThread().getName());
logger.info("something to log in one thread");
poolTwo.submit(runnableTwo);
};
poolOne.submit(runnableOne);
poolOne.submit(runnableOne);
poolOne.submit(runnableOne);
poolOne.submit(runnableOne);
poolOne.submit(runnableOne);
poolOne.submit(runnableOne);
poolOne.shutdown();
poolOne.awaitTermination(5, TimeUnit.SECONDS);
poolTwo.shutdown();
poolTwo.awaitTermination(5, TimeUnit.SECONDS);
}
private static ThreadFactory threadFactory(final String prefix) {
return new ThreadFactory() {
int counter = 0;
@Override
public Thread newThread(Runnable r) {
return new Thread(r, prefix + (++counter));
}
};
}
}
with result being:
2017-01-02 15:17:57.067 INFO [pool-1-2] com.anishek.logging.MultiThreaded - {2=2, thread=pool-1-2} something to log in one thread
2017-01-02 15:17:57.067 INFO [pool-1-1] com.anishek.logging.MultiThreaded - {1=1, thread=pool-1-1} something to log in one thread
2017-01-02 15:17:57.067 INFO [pool-1-3] com.anishek.logging.MultiThreaded - {3=3, thread=pool-1-3} something to log in one thread
2017-01-02 15:17:57.070 INFO [pool-1-1] com.anishek.logging.MultiThreaded - {1=1, 4=4, thread=pool-1-1} something to log in one thread
2017-01-02 15:17:57.070 INFO [pool-1-2] com.anishek.logging.MultiThreaded - {2=2, 6=6, thread=pool-1-2} something to log in one thread
2017-01-02 15:17:57.070 INFO [pool-1-3] com.anishek.logging.MultiThreaded - {3=3, 5=5, thread=pool-1-3} something to log in one thread
2017-01-02 15:17:57.070 INFO [pool-2-1] com.anishek.logging.MultiThreaded - {2=2, thread=pool-1-2} now we are in another
2017-01-02 15:17:57.070 INFO [pool-2-1] com.anishek.logging.MultiThreaded - {2=2, thread=pool-1-2} now we are in another
2017-01-02 15:17:57.070 INFO [pool-2-1] com.anishek.logging.MultiThreaded - {2=2, thread=pool-1-2} now we are in another
2017-01-02 15:17:57.071 INFO [pool-2-1] com.anishek.logging.MultiThreaded - {2=2, thread=pool-1-2} now we are in another
2017-01-02 15:17:57.071 INFO [pool-2-1] com.anishek.logging.MultiThreaded - {2=2, thread=pool-1-2} now we are in another
2017-01-02 15:17:57.071 INFO [pool-2-1] com.anishek.logging.MultiThreaded - {2=2, thread=pool-1-2} now we are in another
The highlighted lines show the output from previous updates on subsequent executions. Hence using the correct methods is of utmost importance if we dont what to print out the wrong context information. The correct code is :
public class MultiThreaded {
public static void main(String[] args) throws InterruptedException {
System.setProperty("isThreadContextMapInheritable", "true");
ExecutorService poolOne = Executors.newFixedThreadPool(3, threadFactory("pool-1-"));
ExecutorService poolTwo = Executors.newFixedThreadPool(1, threadFactory("pool-2-"));
AtomicInteger atomicInteger = new AtomicInteger(1);
Logger logger = LogManager.getLogger(MultiThreaded.class);
Runnable runnableTwo = () -> logger.info("now we are in another");
Runnable runnableOne = () -> {
String value = String.valueOf(atomicInteger.getAndIncrement());
ThreadContext.put(value, value);
ThreadContext.put("thread", Thread.currentThread().getName());
logger.info("something to log in one thread");
poolTwo.submit(runnableTwo);
ThreadContext.remove("thread");
ThreadContext.remove(value);
};
poolOne.submit(runnableOne);
poolOne.submit(runnableOne);
poolOne.submit(runnableOne);
poolOne.submit(runnableOne);
poolOne.submit(runnableOne);
poolOne.submit(runnableOne);
poolOne.shutdown();
poolOne.awaitTermination(5, TimeUnit.SECONDS);
poolTwo.shutdown();
poolTwo.awaitTermination(5, TimeUnit.SECONDS);
}
private static ThreadFactory threadFactory(final String prefix) {
return new ThreadFactory() {
int counter = 0;
@Override
public Thread newThread(Runnable r) {
return new Thread(r, prefix + (++counter));
}
};
}
}
Another thing to note from the above example is that the threads in the poolTwo are printing the same values. I dont know why java seems to pass the threadContext for the first call to the new thread. Ideally, the behavior should be that none of the ThreadContext values should be printed as the threads part of poolTwo are not child threads of the threads part of poolOne. The correct values from the maps are passed along if we use a child thread to run runnableTwo, as in :
public class MultiThreaded {
public static void main(String[] args) throws InterruptedException {
System.setProperty("isThreadContextMapInheritable", "true");
ExecutorService poolOne = Executors.newFixedThreadPool(3, threadFactory("pool-1-"));
AtomicInteger atomicInteger = new AtomicInteger(1);
Logger logger = LogManager.getLogger(MultiThreaded.class);
Runnable runnableTwo = () -> logger.info("now we are in another");
Runnable runnableOne = () -> {
String value = String.valueOf(atomicInteger.getAndIncrement());
ThreadContext.put(value, value);
ThreadContext.put("thread", Thread.currentThread().getName());
logger.info("something to log in one thread");
new Thread(runnableTwo).start();
ThreadContext.remove("thread");
ThreadContext.remove(value);
};
poolOne.submit(runnableOne);
poolOne.submit(runnableOne);
poolOne.submit(runnableOne);
poolOne.submit(runnableOne);
poolOne.submit(runnableOne);
poolOne.submit(runnableOne);
poolOne.shutdown();
poolOne.awaitTermination(5, TimeUnit.SECONDS);
}
private static ThreadFactory threadFactory(final String prefix) {
return new ThreadFactory() {
int counter = 0;
@Override
public Thread newThread(Runnable r) {
return new Thread(r, prefix + (++counter));
}
};
}
}
this will have the following output, with the the highlighted section representing the correct values as :
2017-01-02 15:26:08.128 INFO [pool-1-2] com.anishek.logging.MultiThreaded - {2=2, thread=pool-1-2} something to log in one thread
2017-01-02 15:26:08.128 INFO [pool-1-3] com.anishek.logging.MultiThreaded - {3=3, thread=pool-1-3} something to log in one thread
2017-01-02 15:26:08.128 INFO [pool-1-1] com.anishek.logging.MultiThreaded - {1=1, thread=pool-1-1} something to log in one thread
2017-01-02 15:26:08.130 INFO [pool-1-3] com.anishek.logging.MultiThreaded - {4=4, thread=pool-1-3} something to log in one thread
2017-01-02 15:26:08.130 INFO [pool-1-2] com.anishek.logging.MultiThreaded - {6=6, thread=pool-1-2} something to log in one thread
2017-01-02 15:26:08.130 INFO [pool-1-1] com.anishek.logging.MultiThreaded - {5=5, thread=pool-1-1} something to log in one thread
2017-01-02 15:26:08.130 INFO [Thread-3] com.anishek.logging.MultiThreaded - {3=3, thread=pool-1-3} now we are in another
2017-01-02 15:26:08.130 INFO [Thread-2] com.anishek.logging.MultiThreaded - {1=1, thread=pool-1-1} now we are in another
2017-01-02 15:26:08.130 INFO [Thread-1] com.anishek.logging.MultiThreaded - {2=2, thread=pool-1-2} now we are in another
2017-01-02 15:26:08.131 INFO [Thread-4] com.anishek.logging.MultiThreaded - {4=4, thread=pool-1-3} now we are in another
2017-01-02 15:26:08.131 INFO [Thread-6] com.anishek.logging.MultiThreaded - {5=5, thread=pool-1-1} now we are in another
2017-01-02 15:26:08.131 INFO [Thread-5] com.anishek.logging.MultiThreaded - {6=6, thread=pool-1-2} now we are in another
Scenario 6: Improved logging performance.
As users start using loggers extensively, developers will notice that the application starts becoming slow, on profiling a lot of times they will zero in on the logging framework being a bit slow, the reason for this being the logging is done synchronously in the same thread as application execution and since most of the times the destination sink is a file, disk operations result in additional the overhead. Log4j2 provides a asynchronous mode of operations using LMAX disruptor library internally to provide low latency logging, high throughput logging. This logger can be configured programmatically adding the following code:
System.setProperty("Log4jContextSelector", "org.apache.logging.log4j.core.async.AsyncLoggerContextSelector");
LogManager.setFactory(new Log4jContextFactory());
Detailed information about async loggers is available here.