Separating logs of different threads of application is always a challenge while using log4j logging api. In practice when application has more than one execution thread it becomes very important to be able to trace the flow of each thread individually by looking at log files. Log4j appender configuration is limited at java package levels and doesn’t differentiate between different threads executing same class.
Solution:
Overriding conventional java package level logger hierarchy with thread level hierarchy. To be able to configure log4j at thread level instead of conventional java package level. Using thread local retrieve current thread name and find configured appender and log accordingly.
Details:
With conventional java package level logger hierarchy any given logger instance always logs to configured group of appenders irrespective of its thread. There are some drawbacks with this approach faced by multithreaded applications which can have different independent execution threads. Logs from all threads will go to same group of configured appenders in non deterministic order. To trace flow of any single thread and track issues becomes extremely difficult in such situations if application has more than say, 10 threads.
Log4j allows us to put thread Id in pattern formatter. We can do grep for such id’s to find logs done from particular thread. However we can’t trace them at runtime with this approach. Also Log file size increases with many threads logging to same file.
If Application threads are updating shared resources then logging these different thread activities to same file may be useful as it makes easy to find the order in which this shared resource is updated by these different threads. But when application spawns threads whose execution is completely independent of each other logging to same appender makes it confusing to understand log file. It will be very difficult to trace individual thread execution flows in such cases.
To explain this problem let me take simple example. Every application using Log4j configures one or more appenders for root logger category and other sub logger categories.
E.g. So when we instantiate Logger in our class like this
Logger myClassLogger = Logger.getLogger(org.my.MyClass.class);
This myClassLogger instance now hardcoded to use configuration for category org.my, org and root. This is because MyClass is defined inside package org.my. By default logging categorization in log4j is done at package level. So to decide which appenders to use when we log something using this myClassLogger instance like this:
myClassLogger.debug(“Log this message to org.my.MyClass appenders”);
Log4j finds if there is any appender configured at org.my level, org level and then at root level. Problem with this configuration is that it’s static. So for any thread calling log methods on myClassLogger instance it gets logged to these appenders. This may sound obvious but now lets say there are more than 10 threads running inside application. Log file becomes messy with log statements from all these threads starts logging to same file in non deterministic order.
I had encountered similar application recently where different independent application threads were logging to same log file making life extremely difficult to trace the individual executions. To track issues I needed configuration which will log these executions in different files so that at runtime I can track these flows independently.
I did some search on net to find how this kind of configuration can be achieved using log4j. But couldn’t get close to what I was expecting. I found some gui tools like ChainSaw etc. These tools provide user interface which understands your log files and allows you to filter result in many different ways. We can even use these tools to filter logs from different thread based on thread id. However these tools are not enough for application which are deployed on different servers based on regions. Where you should be in position to quickly access particular server and check logs to track issues.
What I needed was some way using core log4j api to create different log files for different executions so that even on production boxes I could get clear idea of every thread and find cause of problem if occured.
To solve this I have used
Thread Local Store,
extension to org.apache.log4j.Logger,
extension to org.apache.log4j.spi.LoggerFactory,
extension to org.apache.log4j.Hierarchy.
Basic Idea is to be able to configure appenders based on Thread Names. Every such thread will Update Its thread local store with its own Name. New Logger Factory will make sure that Logger.getLogger(Class) calls will return new Logger extension instance. That way whenever logging api’s are called it will invoke method on Logger extension which finds current thread name from thread local store and based on thread name it finds what appenders to be used to log that message.
This is example of Logging configuration which has 2 different threads with Name A and B. Thread name can be any arbitrary name given to differentiate threads. All rules for creating log4j properties file remains as it is. We can configure Thread A appenders to log only ERROR level while logging INFO level for thread B appenders. Only difference in this approach is being the way in which conventional logger hierarchies are overridden. We will have one parent root logger and all different thread loggers will be its child.
log4j.loggerFactory=org.threadlogger.ThreadLoggerFactory
log4j.rootCategory=INFO, defaultOp
#### Logging configuration for Root Logger
log4j.appender.defaultOp=org.apache.log4j.RollingFileAppender
log4j.appender.defaultOp.layout=org.apache.log4j.PatternLayout
log4j.appender.defaultOp.MaxFileSize=10000KB
log4j.appender.defaultOp.MaxBackupIndex=3
log4j.appender.defaultOp.File=../log/RootLogger.log
log4j.appender.defaultOp.layout.ConversionPattern=%d %5p [%t] (%F:%L) - %m%n
## Configuring Logger A and B for thread Id A and B respectively
log4j.logger.A =INFO, A
log4j.logger.B=ERROR, B
## this will avoid logging duplicates in root logger
#log4j.additivity.A=false
#log4j.additivity.B=false
## configuration of Logger A ‘s Appenders
log4j.appender.A=org.apache.log4j.RollingFileAppender
log4j.appender.A.layout=org.apache.log4j.PatternLayout
log4j.appender.A.MaxFileSize=10000KB
log4j.appender.A.MaxBackupIndex=3
log4j.appender.A.File=../run/A_LOGGER.log
log4j.appender.A.layout.ConversionPattern=%d %5p [%t] (%F:%L) - %m%n
## configuration of Logger B ‘s Appenders
log4j.appender.B=org.apache.log4j.RollingFileAppender
log4j.appender.B.layout=org.apache.log4j.PatternLayout
log4j.appender.B.MaxFileSize=10000KB
log4j.appender.B.MaxBackupIndex=3
log4j.appender.B.File=../run/B_LOGGER.log
log4j.appender.B.layout.ConversionPattern=%d %5p [%t] (%F:%L) - %m%n
This is org.threadlogger.ThreadLoggerFactory class. It’s main job is to return instances of ThreadLogger whenever asked. This way we can override package level logger hierarchies easily.
public class ThreadLoggerFactory implements LoggerFactory
{
@Override
public Logger makeNewLoggerInstance(String arg0)
{
return new ThreadLogger(arg0);
}
}
This is ThreadLogger class. It is basically wrapper which wraps logging methods of Logger class. It overrides all debug, info, error etc methods. Implementation of all such overriding methods will be similar to each. If thread local store has some logger stored for this thread then use it to log or else continue logging as per existing log4j convention. I have shown only 3 methods below being overridden for simplicity but actually we need to do this for all logging methods.
class ThreadLogger extends Logger
{
protected ThreadLogger (String name)
{
super(name);
}
@Override
public void debug(Object message)
{
Logger storedLogger = getThreadLogger();
if(storedLogger != null)
{
storedLogger.log(NAME, Level.DEBUG, message, null);
}
else
{
super.log(NAME, Level.DEBUG, message, null);
}
}
@Override
public void info(Object message)
{
Logger storedLogger = getThreadLogger();
if (storedLogger != null)
{
storedLogger.log(NAME, Level.INFO, message, null);
}
else
{
super.log(NAME, Level.INFO, message, null);
}
}
@Override
public void error(Object message, Throwable t)
{
Logger storedLogger = getThreadLogger();
if(storedLogger != null)
{
storedLogger.log(NAME, Level.ERROR, message, t);
}
else
{
super.log(NAME, Level.ERROR, message, t);
}
}
private Logger getThreadLogger()
{
ThreadLoggerLocalStore threadLocalStore = ThreadLoggerLocalStore.instance;
Logger storedLogger = (Logger) threadLocalStore.get();
return storedLogger;
}
}
Class org.threadlogger.ThreadLoggerLocalStore stores logger for given thread. This logger will be retrieved to log any messages from that thread.
public class ThreadLoggerLocalStore extends ThreadLocal
{
public static final ThreadLoggerLocalStore instance = new ThreadLoggerLocalStore();
public void setThreadName(String threadName){
Logger threadLogger = Logger.getLogger(threadName);
set(threadLogger);}
@Override
public Logger get()
{
return super.get();
}
}
Class org.threadlogger.ThreadLoggerHierarchy overrides convention logger Hierarchy with Thread based logger hierarchy.
public class ThreadLoggerHierarchy extends Hierarchy
{
public ThreadLoggerHierarchy (Logger root)
{
super(root);
}
@Override
public Logger getLogger(String name)
{
return getLogger(name, new ThreadLoggerFactory());
}
}
Somewhere in Main class where Log4j Is initialized we need to provide this configuration before setting log4j.properties path.
LogManager.resetConfiguration();
ThreadLoggerHierarchy logHierachy = new ThreadLoggerHierarchy(LogManager.getRootLogger(),
threadLoggerLocalStore);
DefaultRepositorySelector repositorySelector = new DefaultRepositorySelector(logHierachy);
LogManager.setRepositorySelector(repositorySelector, null);
In application thread we need to set current thread name to its thread local store like this:
public void run()
{
ThreadLoggerLocalStore.instance.setThreadName(“A”);
// for thread id B need to call
// ThreadLoggerLocalStore.instance.setThreadName(“B”);
}
As we have log4j.properties configured for thread A and B, we need to set thread name to A and B in these threads so that all logging calls will find configured appenders.
Steps for using this approach to any application logging with log4j:
This solution can be used even for existing application which was already implemented with conventional package based logger hierarchy.
All we have to do is
i) Update log4j properties file to reflect thread based appenders as mentioned above.
ii) In main class or class where you currently set log4j.properties file name to log4j manager, copy following code on top of that to configure log4j to use our logging hierarchy and logger factory.
LogManager.resetConfiguration();
ThreadLoggerHierarchy logHierachy = new ThreadLoggerHierarchy(LogManager.getRootLogger(),
threadLoggerLocalStore);
DefaultRepositorySelector repositorySelector = new DefaultRepositorySelector(logHierachy);
LogManager.setRepositorySelector(repositorySelector, null);
// and then continue with setting log4j properties file path etc.
iii) At the beginning of run method of new application thread update thread local store to set name of running thread. Once we do this all further calls to log4j methods within this thread will be logged to configured appender for that thread.
// e.g.
public void run()
{
ThreadLoggerLocalStore.instance.setThreadName(“A”);
...
}
This update to ThreadLoggerLocalStore can be done at any point in time within thread, but to make sure that all thread activities are logged to proper thread appender it is better to update it at the beginning of the run method.
Summary:
Conventional Logger Hierarchy of package level appenders is not enough for application having different execution threads. We need mechanism that distributes logs from different threads to different appenders at runtime. There are tools which can filter log files based on thread ids and provide us this type of log distribution. However there is limit on applicability of such tools in production environment. We need a way that creates different files for different independent execution thread to trace flows and track issues quickly and efficiently. More importantly without putting logic of this thread based distribution in application code.
We can override logger hierarchy of log4j and configure appenders based on Thread Names. Appenders can be configured for every thread in such a way that logs from any class inside that thread will be logged to configured thread appender and not class package appender. This solution can even be used for any existing application using log4j without any significant application change.
