Open Discussion: Should SLF provide built-in Filtering?

Coordinator
Dec 2, 2009 at 4:31 PM

Filtering is currently not part of SLF - we rely on the individual filtering capabilities of the underlying frameworks and their configuration.

We should evaluate whether to include filtering directly in SLF for the following reasons:

  • Filtering in SLF would be a truly generic mechanism that promotes SLF's seamless switching capabilities between logging frameworks.
  • Filtering is a *very* fundamental concept - including it in SLF makes it available for simple loggers or custom logging strategies that don't need to provide their own filtering.
  • Filtering in certain frameworks is quite complex - providing it in SLF makes it very easy.
  • Filtering is an optional feature. One can always use proprietary filtering mechanism of the given logging frameworks.


One possible implementation: Filtering should be directly enabled via LoggerService, in order to keep things simple. Again, we could provide a pluggable mechanism (ILogFilter interface) which allows us to rely on app.config, or just plug in custom filtering at runtime:

//plug in a global filter at runtime
LoggerService.Filter = new LogLevelFilter(LogLevel.Fatal, LogLevel.Error, LogLevel.Warn);


Arguments Against Built-in Filtering

There are valid points against built-in filtering (which is why we didn't implement it in the first place):

  • SLF receives an additional aspect, which might contradict the idea of a thin façade to logging frameworks.
  • Filtering can be seen as the responsibility of the underlying logging framework, not SLF.
  • other?


Please discuss :)

Dec 2, 2009 at 6:14 PM

As a thin facade, I don't believe SLF should do filtering, or even formatting (which it already does!). It should really just be focused on what is done in code when you log something, not on how the something is finally logged. That's where specific logging frameworks (including custom) would come in, through the plug-in features. The one exception to this is log level filtering. This is fundamental to all logging, and it's very important that client code be able to determine if a logger will log anything for a given logging level. This information is used to determine whether or not to gather information for logging, which can be extremely important to optimizing logging code.  IOW, I would expect to be able to do this:

ILogger logger = LoggingService.GetLogger();
if (logger.WouldLog(LogLevel.Warn))
{
    logger.Warn(LongOperationToProduceTextToLog());
}
Coordinator
Dec 3, 2009 at 8:45 AM

Thanks for the feedback Bill. 

On the subject of log level filtering, we use this approach internally:

 

class LoggerBase
{

    ...

    protected virtual bool IsLogLevelEnabled(Level level) { ... }

}

The LoggerBase class uses the above method to check the logging level of the underlying framework logger before submitting a log message. Perhaps we should move this method onto the public API?

Another approach which we could take is to add method signatures to ILogger which have a delegate argument, so that your example becomes:

logger.Warn(() => LongOperationToProduceTextToLog());

internally, the delegate you provide is only invoked if WARN level is enabled on the logger.

Regards, Colin E.

 

Coordinator
Dec 3, 2009 at 9:16 AM
Edited Dec 3, 2009 at 9:25 AM

The fact that we already have a mechanism in LoggerBase is very convenient. I'd suggest we move the functionality into LoggerService, and just adjust LoggerBase to check this global filter instead. Deriving classes that perform additional checks (such as the NLogFacade) can now just combine their proprietary filtering and the global filter:

override IsLogLevelEnabled(LogLevel level)
{
  return base.IsLogLevelEnabled && DoInternalCheck(level));
}

A pluggable mechanism in LoggerService helps a great deal here. Of course, we rely on convention here (we can't force an ILogger to check LoggerService), but I don't see that as a problem. We also might push IsLogLevelEnabled up to the ILogger Interface (although more specific: IsDebugEnabled, IsInfoEnabled etc.).

Regarding the delegate technique: I've seen this elsewheres, but I'm not convinced. It allows for brevity, but it does actually cost readability, and we'd have to provide a ton of overloads:

 

//old school
if (logger.IsInfoEnabled)
{
logger.Info("User {0} logged in at {1}", GetUserName(), DateTime.Now);
}


//lambda logger.Info(() => "User {0} logged in at {1}", GetUserName(), DateTime.Now);

 

 

 

 

Dec 3, 2009 at 1:56 PM

Yes, just moving IsLogLevelEnabled to the public API would satisfy all of the needs for filtering, IMHO. The API could be made a little nicer (shorten the name a bit, and add properties for at least the more important log levels), but all of that is gravy and prone to religious debate ;). The idea of using a delegate isn't totally bad... but it's also a more advanced concept that isn't as palatable to some. As an addition, it would be fine, but not as a replacement for IsLogLevelEnabled. To be honest, I'd only put IsLogLevelEnabled on the interface, and would then consider adding extension methods for the delegate methods.

BTW, the "logger.Info(() => "User {0} logged in at {1}", GetUserName(), DateTime.Now)" example is misguided. No such method signature should exist, as it adds no utility and actually hurts readability. The simpler signature taking ONLY a delegate does provide utility, and reasonable people can argue both ways about what it does to readability ;).  "logger.Info(() => string.Format("User {0} logged in at {1}", GetUserName(), DateTime.Now))" accomplishes the same thing, and does so in a manner that's optimal in performance, which is the point behind log level filter checking.

Coordinator
Dec 3, 2009 at 3:41 PM

I agree with Bill, I think the delegate signature adds value, and we only need to add one per log-level. Also, adding them as extension methods is a nice idea.

However, I am still not sold on the idea of SLF having its own filtering mechanism. For users of log4net it means that you have 3 different locations where you can filter:

  • At the appender level
  • At the logger level
  • At the SLF level

If filtering is added to SLF, I would prefer to see a component split that I think I emailed you about a while back:

  • SLF facade (the current SLF - i.e. no filtering)
  • SLF logging (a simple logging framework which has filtering)

This way, SLF facade can use SLF logging in the same way that it uses NLog, log4net, ...

Something like the following pseudo-code:

 

IFilteredLogger logger = new FilteredLogger(new ConsoleLogger());
LoggerService.SetLogger(logger);
logger.Filter = new LogLevelFilter(DEBUG, ERROR);

Colin E.

 

Dec 3, 2009 at 4:00 PM

I'm not suggesting that SLF should do any filtering. What I am suggesting is that most (all?) logging frameworks provide not only filtering by LogLevel, but also interrogation of whether or not something would be logged at a given LogLevel. Since the interrogation part of that is essential to optimized logging, it should be included in the facade. I wouldn't expect SLF to do any filtering itself, but instead it would just delegate the interrogation to the underlying logging system. SLF loggers, like the DebugLogger, can expose LogLevel filtering, I suppose, but I would not care for SLF being able to modify the filtering of loggers from other underlying logging systems. It would just add confusion and complexity.

Coordinator
Dec 3, 2009 at 4:26 PM

I actually like the prospect of SLF being capable of filtering as a complementary mechanism. If I don't want to plug a filter into SLF, then fine, the logger just relies on filtering of the underlying framework itself (given that framework does provide that piece of functionality, which is usually the case). But if I want to proactively plug in filtering on SLF level, I can set a single property on LoggerService and control to the whole logging behaviour of all loggers. I don't see how this property would hurt. But we might have to agree to not agree (or whatever that saying is in English ;), so I hope there will be more feedback on this over time that goes into one or the other direction.

Extension methods sound fine by me, but would require us to break identical functionality for 2.0 / 3.5. Nothing I'd worry though - I enjoy the luxury of playing with the new toys :)

Dec 3, 2009 at 4:40 PM

Yeah, we may have to agree to disagree. I think "complementary" filtering at the SLF level, at best, just leads to confusion. "I've configured 'foo' logger provided by log4net to include informational messages, why are Info() calls not logging? Oh, someone else turned it off at the SLF level! Doh!" What I want from a logging facade is just a minimalistic facade to unify logging code, allowing me to replace the logging framework at will. I don't need/want a facade around configuring logging. If I've chosen to use a logging framework that doesn't support filtering, I certainly don't need SLF to add filtering for me. The same really goes for other aspects, such as formatting and even named-lookup (another topic we've discussed a lot). I need to be able to request a logger by name, but how named lookup happens should be solely dependent on the underlying logging framework, not based on SLF configuration. Now, there is a need (or at least a desire) to provide some "out of the box" logging capabilities when no other logging framework is being used, and at that level I have no problems with there being some of this configurability. But there should be a clear separation here.

Coordinator
Dec 3, 2009 at 4:44 PM

I also think complementary adds to confusion. However, I think we should add methods to ILogger to expose properties that allow the user to determine which level is enabled, i.e. IsWarnEnabled, IsDebugEnabled.

I will add a work item (or whatever codeplex calls it)

Coordinator
Jan 25, 2010 at 8:53 AM
Edited Jan 25, 2010 at 8:53 AM

I hate to bring this up again, but: Today I was thinking about using Twitter as an event notification system, and I'll write a small demo for that. And of course, I was thinking about writing an SLF façade for it as well. But of course, when not in development, I don't want the Twitter façade to log Debug and Info output. And accordingly, I'll have to write my own (proprietary) filtering logic. With SLF, I have a framework at hand that allows me to plug in a new façade with just a few lines of code, but in the end, it's worthless for production use because I don't have filtering at hand. That's a bit frustrating I'm afraid.

I guess we could write another logger interface that provides optional capabilities with regards to filtering and write another base class that also allows for LogLevel filter configuration in app.config. With such a base class in place, I could my SlfFaçade (as well as ConsoleLogger etc.) derive from that one. What do you think?

Cheers,

Philipp

Coordinator
Jan 25, 2010 at 9:33 AM

Hi Philipp,

Here we go again ;-)

If you have found yourself in the situation again where you think filtering should be included in SLF, then I would say go for it!

In terms of the API, I liked your original suggestion at the top where you expose a LogService.Filter property. Would this new base class implementation interact with the LogService.Filter in order to achieve filtering?

I think for consistency, all of our facades should share this base-class and this behaviour.

Let me know how it goes.

Regards, Colin E.

Coordinator
Jan 25, 2010 at 9:48 AM

Hi Colin,

I guess I won't touch LoggerService - both you and Bill made your points and they are valid. Accordingly, I was thinking more like adding the whole filtering directly into a base class:

public abstract class FilteringLoggerBase : LoggerBase
{
  //my suggestion about LoggerService.Filter just goes here
  //rather than into LoggerService
  public XXX Filter { get; set; }


  //we already have that one in LoggerBase if I'm not mistaken
  override bool IsLogLevelEnabled(LogLevel level)
  {
    return Filter.IsLogLevelEnabled(level);
  }
}



Like that, the API would remain "clean", and we had filtering in all core loggers that currently cannot be filtered. Accordingly, I was also thinking about configurability - accordingly on the factory level:

<factories>
  <factory name="acme"
           type="Acme.Logging.MyLogger, Acme.Logging">
    <factory-data>
      <!-- all our core logger factories check for a filter element -->
      <filter level="Warn" />
    </factory-data>
  </factory>
</factories>

 

Coordinator
Jan 25, 2010 at 9:59 AM

I see, so the factor would create an instance of Filter, then associate it with the Logger. That sounds OK to me.

I the Filter property is not on the interface, would the factory have to check that the logger is a LoggerBase subclass?

An alternative implementation would be to apply the filtering before LoggerBase.Log(LogItem) is invoked, providing the LogItem instance to the Filter. This would allow filtering based on more than just the log level.

The factory configuration you provided looks nice and simple to me.

 

Coordinator
Jan 25, 2010 at 10:29 AM

Usually, the factory knows about the loggers it creates, so there's no need to check for an interface (IFilteringLogger or something like this). But then, the generic base factories (including the reflection-based one) could (should?) probably provide the ability to detect a filter.

A word of warning though: I am promoting a distinction of cases here! Filtering is decidedly not a feature of SLF, but a proprietary feature of certain façades that is just part of the core library in order to avoid code duplication. Accordingly, declaring a filter on an NLogFactory declaration would not have any effect, because the NLog factory just doesn't provide that particular feature (again: it's not an SLF feature!). This might indeed be confusing if someone actually wanted to add an SLF filter for the NLog façade, but I guess there's just no way around. If I wrote a proprietary façade that supports filtering (without touching the SLF core), the external API and configuration markup for that façade would look exactly the same, being the only difference that my "base class" is in the façade library rather than the SLF core library.

Regarding submitting the LogItem: This is what I was thinking about with the initial snippet on top of this thread. But then, an advanced filter would have to be injected via code. Maybe we should keep things simple and have SLF's filtering limited to the LogLevel? (Although both scenarios sit fine with me.

btw: This discussion is related to this work item: http://slf.codeplex.com/WorkItem/View.aspx?WorkItemId=25523. Do you already have an implementation at hand for this?

Coordinator
Jan 25, 2010 at 11:03 AM

I think the distinction you describes makes sense. It avoids the problem of which filtering mechanism to use when using an NLog facade.

To be honest, I can;t recall ever seeing an application with more complex logging filtering than simple log levels. The only reason I suggested it is if you were thinking fo adding some more complex filtering in future. NLog really goes to town in this area:

http://nlog-project.org/conditions.html

But like I said, I am not sure very many people use this feature!

No, I never did get round to implementing that work item - should be a pretty trivial implentation though.