How can I set up separate streams of logging for log4j?

Question

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?

Answer 1

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:

1. You can apply it as a context-wide filter and thus turn off all logging of durations, for example.
2. You can apply it to the org.myproject.MyClass logger, to turn off logging of results (for example) for that specific class.
3. 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>