Exploring Dynamic Threshold Turbo Filter

Turbo Filter

Logback TurboFilter is an abstract class which provides ways to intercept logging behaviour of java application.

It has a decide method which accepts list of parameters and makes the decision of whether to proceed with logging or not.

/**
 * Make a decision based on the multiple parameters passed as arguments. The
 * returned value should be one of <code>{@link FilterReply#DENY}</code>,
 * <code>{@link FilterReply#NEUTRAL}</code>, or
 * <code>{@link FilterReply#ACCEPT}</code>.
 *
 */
public abstract FilterReply decide(Marker marker, Logger logger,
                   Level level, String format, Object[] params, Throwable t);

FilterReply.ACCEPT informs the framework to proceed with logging the event/message. FilterReply.DENY informs the framework to decline the logging request. FilterReply.NEUTRAL informs the framework to proceed with other turbo filters (if available).

If all turbo filters responds with NEUTRAL, then requested log level is compared against effective log level. Effective log level is usually the level set in application configuration or in most cases root log level. Message is not logged if effective log level is GREATER THAN requested log level.

final FilterReply decision = <Response after executing turbo filters>
if (decision == FilterReply.NEUTRAL) {
  if (effectiveLevelInt > level.levelInt) {
      return;
  }
} else if (decision == FilterReply.DENY) {
   return;
}

Another interesting point to keep in mind is that execution of turbo filters terminates as soon as one of the filter responds with ACCEPT or DENY.

Object[] tfa = <turbo filter array>
final int len = tfa.length;
for (int i = 0; i < len; i++) {
    final TurboFilter tf = (TurboFilter) tfa[i];
    final FilterReply r = tf.decide(marker, logger, level, format, params, t);
    if (r == FilterReply.DENY || r == FilterReply.ACCEPT) {
        return r;
    }
}
return FilterReply.NEUTRAL;

Dynamic Threshold Filter

DynamicThresholdFilter implementation of turbo filter really piqued my interest when I read about it’s documentation. I do feel that the example provided in documentation does not justify the use case for this filter properly.

/**
 * This filter allows for efficient course grained filtering based on criteria
 * such as product name or company name that would be associated with requests
 * as they are processed.
 * 
 * <p>
 * This filter will allow you to associate threshold levels to a key put in the
 * MDC. This key can be any value specified by the user. Furthermore, you can
 * pass MDC value and level threshold associations, which are then looked up to
 * find the level threshold to apply to the current logging request. If no level
 * threshold could be found, then a 'default' value specified by the user is
 * applied. We call this value 'levelAssociatedWithMDCValue'.
 * 
 * <p>
 */

This filter uses MDC for making the decision about logging a message. After creating bean of this filter, we need to set a key. This key is used to get get a value from MDC. This value is used to get Log Level from valueLevelMap. This log level is then compared to requested log level for decision making. Confused ???? Let’s go through actual code

public FilterReply decide(Marker marker, Logger logger, Level level, 
            String s, Object[] objects, Throwable throwable) {

1.      String mdcValue = MDC.get(this.key);
        if (!isStarted()) {
            return FilterReply.NEUTRAL;
        }

        Level levelAssociatedWithMDCValue = null;
        if (mdcValue != null) {
2.          levelAssociatedWithMDCValue = valueLevelMap.get(mdcValue);
        }
        if (levelAssociatedWithMDCValue == null) {
            levelAssociatedWithMDCValue = defaultThreshold;
        }
3.     if (level.isGreaterOrEqual(levelAssociatedWithMDCValue)) {
            return onHigherOrEqual;
        } else {
            return onLower;
        }
    }

#1 Get the value from MDC for a key. Assume key is “userGroup”. Let’s say based on type of users, userGroup can have “B2B” or “B2C”.

#2 When object of DynamicThresholdFilter is created, valueLevelMap is set with appropriate values and their log levels. In our example, valueLevelMap may have below values B2B : Level.INFO B2C : Level.DEBUG

#3 This condition will decide whether to log the message or not. So, When request comes for userGroup B2B, only INFO level logs will be logged while for userGroup B2C, DEBUG level logs are logged.

Another use case I could think of, is using this filter for setting different log levels based on APIs.

/myapi/oldapi - Existing stable API
public void oldAPI() {
  A();
  B();
  C();
}

/myapi/newapi - new API
public void newAPI() {
  D();
  B();
  E();
}

This is very common case where we may be reusing existing code which may have DEBUG level logs. To debug possible issues in new API, we may want to log messages at DEBUG level for new API while continue logging INFO level logs for old API. To achieve this, DynamicThresholdFilter can be used as below

Initialize DynamicThresholdFilter object with 
key -> "api"
valueLevelMap -> {"oldAPI" : Level.INFO, "newAPI" : Level.DEBUG}
defaultThreshold - > Level.INFO
onHigherOrEqual - > FilterReply.ACCEPT

when request comes for old API, 
MDC.put("api", "oldAPI")

when request comes for new API,
MDC.put("api", "newAPI")

With above mentioned setup, Debug logs in method B() will ONLY be logged for new API request.

That’s it for quick introduction on TurboFilter and DynamicThresholdFilter use cases. Do comment if you guys have more use cases for DynamicThresholdFilter.