Say I have a class like this:
public class MyClass
{
private Logger log = LoggerFactory.getLogger(MyClass.class); //org.slf4j.LoggerFactory
public void foo(Params p)
{
log.info("Foo params: " + p);
long t1 = System.currentTimeMillis();
Result r = someMethod(p);
long t2 = System.currentTimeMillis();
log.info("Foo result: " + r)
log.info("Foo time taken: + (t2-t1)/1000);
}
}
Now when it comes to printing this info, I want to be able to turn on and off the different types of info (Parameters, Results, Time Taken).
The problem with using logging levels to differentiate, is that the finer levels of granularity also encompass the coarser levels.
How can I easily set this up?
I think what John Ament meant, is that the logger name (or category, as it is also sometimes called) can be freely chosen. The call
LoggerFactory.getLogger(MyClass.class)
is mostly just a convenience for calling
LoggerFactory.getLogger(MyClass.class.getName())
There is no requirement from the logging framework that you name your loggers according to the full name of the class. This is just a convention supported by the first getLogger overload above.
So instead of having three different Logger implementations with the same name as in your example:
private AbstractLogger l1= new LoggerOne(this.getClass());
private AbstractLogger l2= new LoggerTwo(this.getClass());
private AbstractLogger l3= new LoggerThree(this.getClass());
You can simple use the standard Logger implementation with 3 different names:
public class MyClass
{
private static final String loggerBaseName = MyClass.class.getName();
private final Logger paramsLogger = LoggerFactory.getLogger(loggerBaseName + ".params");
private final Logger resultsLogger = LoggerFactory.getLogger(loggerBaseName + ".results");
private final Logger durationLogger = LoggerFactory.getLogger(loggerBaseName + ".duration");
public void foo(Params p)
{
paramsLogger.info("Foo params: {}", p);
long t1 = System.currentTimeMillis();
Result r = someMethod(p);
long t2 = System.currentTimeMillis();
resultsLogger.info("Foo result: {}", r)
durationLogger.info("Foo time taken: {}", (t2-t1)/1000);
}
}
Since log4j loggers are hierarchical, you can control them together or indivially as needed. So if you wanted to enable all of them:
log4j.logger.org.myproject.MyClass=DEBUG, stdout
If you later need to turn results off:
log4j.logger.org.myproject.MyClass=DEBUG, stdout
log4j.logger.org.myproject.MyClass.results=OFF
In the same way you can send the output to different destinations if needed.
Using markers
All of the above was written using only the basic functionality available in any SLF4J implementation. If you are using Log4j 2 or are willing to switch to logback, you can instead use markers to achieve the same, but on a global level. Thus, instead of having multiple loggers in the class, you could have multiple markers, like so:
public class GlobalMarkers
{
public static final Marker PARAMS = MarkerFactory.getMarker("PARAMS");
public static final Marker RESULTS = MarkerFactory.getMarker("RESULTS");
public static final Marker DURATION = MarkerFactory.getMarker("DURATION");
}
public class MyClass
{
private Logger logger = LoggerFactory.getLogger(MyClass.class);
public void foo(Params p)
{
logger.info(GlobalMarkers.PARAMS, "Foo params: {}", p);
long t1 = System.currentTimeMillis();
Result r = someMethod(p);
long t2 = System.currentTimeMillis();
logger.info(GlobalMarkers.RESULTS, "Foo result: {}", r)
logger.info(GlobalMarkers.DURATION, "Foo time taken: {}", (t2-t1)/1000);
}
}
This will allow you to toggle logging of parameters, results and durations globally, by using Log4j 2.0 MarkerFilter or logback MarkerFilter.
Configuration in Log4j 2.0
Log4j 2.0 gives you a lot of flexibility in how to use MarkerFilter:
- You can apply it as a context-wide filter and thus turn off all logging of durations, for example.
- You can apply it to the org.myproject.MyClass logger, to turn off logging of results (for example) for that specific class.
- You can apply it to a specific appender and thus do parameter logging to a separate file from result logging or similar.
Configuration in logback
In logback the story is more complex, depending on what you wish to achieve. To turn off all logging of a given marker globally, simply use MarkerFilter. This is a TurboFilter, so it applies to the entire logging context. If you want to log different markers to separate sources, you could use SiftingAppender and write a marker-based discriminator by extending AbstractDiscriminator. Since logback does not support filters directly on loggers, if you need to configure output per-class per-marker, like turning off logging of results for MyClass but keeping it on for other classes, you should use class-specific markers instead of global ones.
Here is a sample implementation of a marker-based discriminator for use with SiftingAppender:
public class MarkerBasedDiscriminator extends AbstractDiscriminator<ILoggingEvent> {
private static final String KEY = "markerName";
private String defaultValue;
public String getDefaultValue() {
return defaultValue;
}
public void setDefaultValue(String defaultValue) {
this.defaultValue = defaultValue;
}
public String getKey() {
return KEY;
}
public void setKey() {
throw new UnsupportedOperationException("Key not settable. Using " + KEY);
}
public String getDiscriminatingValue(ILoggingEvent e) {
Marker eventMarker = e.getMarker();
if (eventMarker == null)
return defaultValue;
return eventMarker.getName();
}
}
This implementation is heavily inspired by the standard ContextBasedDiscriminator. You would use MarkerBasedDiscriminator like this:
<configuration>
<appender name="SIFT" class="ch.qos.logback.classic.sift.SiftingAppender">
<discriminator class="org.myproject.MarkerBasedDiscriminator">
<defaultValue>general</defaultValue>
</discriminator>
<sift>
<appender name="FILE-${markerName}" class="ch.qos.logback.core.FileAppender">
<file>${markerName}.log</file>
<append>false</append>
<encoder>
<pattern>%d [%thread] %level %logger{35} - %msg%n</pattern>
</encoder>
</appender>
</sift>
</appender>
<root level="DEBUG">
<appender-ref ref="SIFT" />
</root>
</configuration>
You set different logging behaviour by creating custom logging classes.
Here's my solution:
public abstract class AbstractLogger {
protected Logger log;
protected Class callingClass;
public AbstractLogger(Class c)
{
this.log = LoggerFactory.getLogger(this.getClass());
this.callingClass = c;
}
public void log(String s)
{
log.debug(this.callingClass + " :" + s);
}
}
public class LoggerOne extends AbstractLogger {
public LoggerOne(Class c) {
super(c);
}
}
public class LoggerTwo extends AbstractLogger {
public LoggerTwo(Class c) {
super(c);
}
}
public class LoggerThree extends AbstractLogger {
public LoggerThree(Class c) {
super(c);
}
}
Setup in Log4j.properties
#Define custom levels by package
#set to ERROR to turn them off
log4j.logger.org.myproject.loggers.LoggerOne=ERROR
log4j.logger.org.myproject.loggers.LoggerTwo=DEBUG
log4j.logger.org.myproject.loggers.LoggerThree=DEBUG
When using these loggers:
To use these logger:
public class MyMain {
// private Logger log = LoggerFactory.getLogger(MyMain.class);
private AbstractLogger l1= new LoggerOne(this.getClass());
private AbstractLogger l2= new LoggerTwo(this.getClass());
private AbstractLogger l3= new LoggerThree(this.getClass());
public void run()
{
l1.log("log 1");
long t1 = System.currentTimeMillis();
try {
Thread.sleep(1000); //1000 milliseconds is one second.
} catch(InterruptedException ex) {
Thread.currentThread().interrupt();
}
long t2 = System.currentTimeMillis();
l2.log("log 2");
l3.log("Foo time taken:" + (t2-t1)/1000);
}
public static void main(String[] args) {
MyMain me = new MyMain();
me.run();
}
}
Log output:
12:27:29 DEBUG LoggerTwo:18 - class maventestspace.MyMain :log 2
12:27:29 DEBUG LoggerThree:18 - class maventestspace.MyMain :Foo time taken:1
Note that LoggerOne isn't printing, because it is set to ERROR in the properties file.
To redirect these seperate log files, you need to set up new appenders and loggers.
log4j.logger.org.myproject.loggers.LoggerOne=DEBUG, file1, stdout
log4j.logger.org.myproject.loggers.LoggerTwo=DEBUG, file2, stdout
log4j.logger.org.myproject.loggers.LoggerThree=DEBUG, file3, stdout
# Direct log messages to a log file
log4j.appender.file1=org.apache.log4j.RollingFileAppender
#log4j.appender.TextProcessor.Threshold=debug
log4j.appender.file1.File=E:\\logs\\log1.txt
log4j.appender.file1.MaxFileSize=10MB
log4j.appender.file1.MaxBackupIndex=1
log4j.appender.file1.layout=org.apache.log4j.PatternLayout
log4j.appender.file1.layout.ConversionPattern=%d{HH:mm:ss} %-5p %c{1}:%L - %m%n
# Direct log messages to a log file
log4j.appender.file2=org.apache.log4j.RollingFileAppender
#log4j.appender.TextProcessor.Threshold=debug
log4j.appender.file2.File=E:\\logs\\log2.txt
log4j.appender.file2.MaxFileSize=10MB
log4j.appender.file2.MaxBackupIndex=1
log4j.appender.file2.layout=org.apache.log4j.PatternLayout
log4j.appender.file2.layout.ConversionPattern=%d{HH:mm:ss} %-5p %c{1}:%L - %m%n
# Direct log messages to a log file
log4j.appender.file3=org.apache.log4j.RollingFileAppender
#log4j.appender.TextProcessor.Threshold=debug
log4j.appender.file3.File=E:\\logs\\log3.txt
log4j.appender.file3.MaxFileSize=10MB
log4j.appender.file3.MaxBackupIndex=1
log4j.appender.file3.layout=org.apache.log4j.PatternLayout
log4j.appender.file3.layout.ConversionPattern=%d{HH:mm:ss} %-5p %c{1}:%L - %m%n
It sounds like the most straight forward solution is to leverage distinct categories for what you're logging. Using this as an example
String baseCategory = MyClass.class.getName();
String params = baseCategory+".params";
String duration = baseCategory+".duration";
You would simply pass those names in as logger factory categories.
