Application Logging in Java: Filters

15 Jun 2019 • logging

TL;DR: Filters are used to determine whether an appender should log an event or not. Many loggers will log at INFO level far too often, and cause excessive logging. An filter using a custom evaluator can be used to create a budget for logging at different levels, and throttle logs down to a reasonable level.

This is part of the series of blog posts:

The design of Logback starts with the idea of generating a logging event first, and then sending that event to multiple appenders. However, appenders do have a check on what they can log; only an event that makes its way through the appender's filters can be logged. You may have no filters at all writing to the filesystem, but if you're appending to a centralized logger, you may filter by threshold level, or check for specific markers (which requires some custom code).

The logic for filters is interesting, because it it's not binary. Instead, filters return ACCEPT, DENY, or NEUTRAL. Neutral means that no decision is made here, and so you can run several filters together. This is useful when several appenders share filter logic and build up lists of filters in the appender, but it also means that if you're indicating a binary state, you may not want it to go into a filter directly.

The Logging Costs blog post discussed the expense of storing logs and the costs of excessive logging, and vaguely mentioned budget aware appenders as a solution to deal with excessive logging. Let's dig into that.

The threshold and level filters don't prevent excessive logging, per se. They don't keep track of the number of logging events that pass through the appender, or the amount of time between resets. However, circuit breakers are well known as a solution to limit excessive number of calls, and can be configured on an event count over time. If the circuit breaker is closed, then return true. If the circuit breaker is open, then return false.

This sounds like an evaluator, so I wrote a BudgetEvaluator that uses circuit breakers, and plugged it into an EvaluatorFilter.

It's in terse-logback in the logback-budget module.

public class BudgetEvaluator extends EventEvaluatorBase<LoggingEvent> implements BudgetRuleAttachable {

    private List<BudgetRule> budgetRules = new ArrayList<>();
    private Map<String, CircuitBreaker<Integer>> levelRules = new HashMap<>();

    @Override
    public void start() {
        for (BudgetRule budgetRule : budgetRules) {
            CircuitBreaker<Integer> breaker = createCircuitBreaker(budgetRule);
            levelRules.put(budgetRule.getName(), breaker);
        }
        super.start();
    }

    private CircuitBreaker<Integer> createCircuitBreaker(BudgetRule budgetRule) {
        final int threshold = budgetRule.getThreshold();
        final long checkInterval = budgetRule.getInterval();
        final TimeUnit checkUnit = TimeUnit.valueOf(budgetRule.getTimeUnit().toUpperCase());
        return new EventCountCircuitBreaker(threshold, checkInterval, checkUnit);
    }

    @Override
    public boolean evaluate(LoggingEvent event) {
        if (levelRules.isEmpty()) {
            return true; // not applicable
        }

        Level level = event.getLevel();
        CircuitBreaker<Integer> breaker = levelRules.get(level.levelStr);
        if (breaker == null) {
            return true; // does not apply to this level
        }

        if (breaker.checkState()) {
            return breaker.incrementAndCheckState(1);
        } else {
            return false;
        }
    }

    @Override
    public void addBudgetRule(BudgetRule budget) {
        budgetRules.add(budget);
    }

    @Override
    public void clearAllBudgetRules() {
        budgetRules.clear();
    }
}

The nice thing about using an evaluator together with a filter is that it gives more flexibility about what to do when the circuit breaker is open.

For, example, you can prevent loggers from spamming at INFO level, by setting OnMismatch to DENY and OnMatch to NEUTRAL. This is useful for slimming down the logs while still getting occasional heartbeat and "processing packet" messages from services.

 <filter class="ch.qos.logback.core.filter.EvaluatorFilter">
    <evaluator class="com.tersesystems.logback.budget.BudgetEvaluator">
        <budget-rule name="INFO" threshold="5" interval="1" timeUnit="SECONDS"/>
    </evaluator>
    <OnMismatch>DENY</OnMismatch>
    <OnMatch>NEUTRAL</OnMatch>
</filter>

Or you can say "I only want to hear something from this appender if there's LOTS of output". This makes sense for high volume services that may have brief network partitions that resolve themselves very quickly.

 <filter class="ch.qos.logback.core.filter.EvaluatorFilter">
    <evaluator class="com.tersesystems.logback.budget.BudgetEvaluator">
        <budget-rule name="ERROR" threshold="1000" interval="1" timeUnit="MINUTES"/>
    </evaluator>
    <OnMismatch>NEUTRAL</OnMismatch>
    <OnMatch>DENY</OnMatch>
</filter>

This works very well with audio appenders, which you don't want going off several thousand times a second.

<appender name="AUDIO" class="com.tersesystems.logback.core.CompositeAppender">
    <filter class="ch.qos.logback.core.filter.EvaluatorFilter">
        <evaluator class="com.tersesystems.logback.budget.BudgetEvaluator">
            <budget-rule name="WARN" threshold="1" interval="5" timeUnit="seconds"/>
            <budget-rule name="ERROR" threshold="1" interval="5" timeUnit="seconds"/>
        </evaluator>
        <OnMismatch>DENY</OnMismatch>
        <OnMatch>NEUTRAL</OnMatch>
    </filter>

    <appender-ref ref="AUDIO-WARN"/>
    <appender-ref ref="AUDIO-ERROR"/>
</appender>

And that's how you write a budget aware appender.