TurboFilters should be called with format/params/throwable when using fluent logging API

[christophejan]

I think TurboFilter decide method should be called with provided format/params/throwable the same way whether fluent logging API has been used or not.

Currently, with slf4j-api 2.0.16 and logback-classic 1.5.8 :

• logger.info(“Hello world.”); call TurboFilter decide method with provided format/params/throwable
• logger.atInfo().log(“Hello world.”); never call TurboFilter decide with provided format/params/throwable (A call equivalent to logger.isInfoEnabled() with null format/params/throwable is done ; that’s not a problem but that’s not what is expected).

In logback documentation, I found :

• On Fluent Logging API : The statement logger.atInfo().log(“Hello world.”); is equivalent to : logger.info(“Hello world.”);
• […] (TurboFilter) are called not only when a given appender is used, but each and every time a logging request is issued. Their scope is wider than appender-attached filters.

I think it’s an issue that TurboFilters is not called with format/params/throwable when using fluent logging API.

[jakobleck]

+1
I had an issue trying to filter logs using a TurboFilter based on matching the format with a specific string and returning a DENY, but in the resulting logs in the console the string still appeared, presumably from calls to decide with format = null. Adding a

    if (format == null) {
      return FilterReply.DENY;
    }

to the decide fixed it, but doesn't look that good to me... (Or is it?)

At the very least, I think, it should be documented that TurboFilter's decide can be called with null parameters.

[christophejan]

Hi @jakobleck

Denying all decide calls with null format will skip all code blocks inside any isXxxEnabled. You may filter out a lot of logs you don’t want to miss.

This issue is only regarding logs emitted with fluent api that never call decide with provided format (etc.).

[christophejan]

Hi @ceki,

Sorry to bother you. Could you please give us some guidance. Do you agree that current behavior is an issue ? Do you plan to continue to maintain and enhance Turbo filter (like adding KeyValuePairs as parameter) or do do you recommend to rather switch to regular filter ? Regular filter will be much less easy to use in some use case as regular filter are not tied to the logging context but at appender level. Anyway, it could be better than staying on a feature you perhaps consider legacy.

Thanks a lot for this great lib.

Regards

[mvitz]

As this is related to micrometer-metrics/micrometer#4404 I would be interested, too.

[ceki]

Note: this comment has been largely revised.

TurboFilters were originally designed to act as highly efficient global filters before a LoggingEvent instance is created.

Here is a synopsis of the current implementation:

• Since it is invoked before the the logger-level filter, aka basic selection rule, a TurboFilter can override logger-level filter. For example, it can force a DEBUG-level log request to be processed even if the logger is disabled for DEBUG.

• When atTrace(), atInfo, ... methods are invoked, only the calling logger and the level are known. It follows that when atTrace(), atInfo, ... methods call turbo filters, the only provided parameters are level and logger.

Calling TurboFilter.decide after the LoggingEvent has already been created contradicts the original design intent, which aimed to avoid event creation for soon-to-be-filtered-out logs. However, if the goal of turbo filters is to act as context-wide fiters, then this design intent can be partially ignored.

In the Logger.log(slf4jEvent) method all LoggingEvent fields are populated and can be passed to the turbo filters. Thus, one option is to move the invocation of turbo filters from at atTrace(), atInfo, ... methods into the Logger.log(slf4jEvent) method. On the other hand, events that have been already filtered out by the basic selection rule are lost and can no longer be salvaged by turbo filters.

[ceki]

After giving it some more thought, a secondary consideration is to add a new decide method taking a LoggingEvent as a parameter and delegating to the original decide method. Here is an implementation:

abstract class TurboFilter ... {
   ... 
   // a default implementation delegating to the  original decide method
   public FilterReply getTurboFilterChainDecision(org.slf4j.event.LoggingEvent slf4jEvent) {
        List<Marker> markers = slf4jEvent.getMarkers();
        Marker firstMarker = (markers != null && !markers.isEmpty()) ? markers.get(0) : null;
        
        LoggerContext loggerContext = (LoggerContext) getContext();
        
        Logger logger = loggerContext.getLogger(slf4jEvent.getLoggerName());
        Level logbackLevel = Level.convertAnSLF4JLevel(slf4jEvent.getLevel());
        String format = slf4jEvent.getMessage();
        Object[] params = slf4jEvent.getArgumentArray();
        Throwable t = slf4jEvent.getThrowable();
        
        // delegate to the original decide method
        return decide(firstMarker, logger, logbackLevel, format, params, t);
  }    
}

The advantage of this approach is that it is backward compatible with existing code.

However, the issue of previously filtered events remains.

[ceki]

Commit 1cd2df4 addresses this issue by calling turbo filters in the log(LoggingEvent) method of Logger with the contents of the LoggingEvent (around line 821 of Logger class).

Invocations of turbo filters in isDeugEnabled, isInfoEnabled()... remain as they were, untouched.

I think micrometer-metrics/micrometer#4404 should be fixed by this commit.
In LogbackMetrics line 208-210, the the conditional can (should?) be simplified as

// ignore isXYZEnabled calls
if (format == null ) {
  return FilterReply.NEUTRAL;
}

[christophejan]

Hi @ceki,

Thank you very much for your time, your analysis, the fix etc.

I’ve made some tests with it and get exactly the behavior I was expecting.

I’ve seen that the analysis and fix were not easy.

You did a great job by achieving to preserve backward compatibility including the ability to override the logger level filter and to control conditional behavior like with isXxxEnabled() or atXxx().

I saw that you even achieved to provide access to extra data like KeyValuePairs.

I greatly appreciate.

Once again, a lot of thanks.

[mvitz]

I was not expecting such a quick fix. Thanks for all your work. This will resolve my underlying issue once I can use the fluent API without messing up the metrics.