Enterprise framework logging - ShouldLog not working with SourceLevel filter

Question

I'm using EF 5 and am trying to use the ShouldLog method to determine whether a LogEntry will be logged prior to actually logging it. My issue is that ShouldLog always returns true, even if I have a filter in place to exclude certain levels. The filter works and the entries are not logged, but ShouldLog does not appear to work.

I'm configuring my logger like so:

internal static void ConfigureLogging(SourceLevels logLevel)
{
    var builder = new ConfigurationSourceBuilder();

    builder.ConfigureLogging()
        .LogToCategoryNamed("General")
        .WithOptions.SetAsDefaultCategory()
        .SendTo.FlatFile("Main log file")
        .FormatWith(
            new FormatterBuilder()
                .TextFormatterNamed("Text Formatter")
                .UsingTemplate("{timestamp(local:MM/dd/yyyy HH:mm:ss.fff)} [{severity}] {message}"))
        .Filter(logLevel) //Setting the source level filter
        .ToFile("log.txt");

    var configSource = new DictionaryConfigurationSource();
    builder.UpdateConfigurationWithReplace(configSource);
    EnterpriseLibraryContainer.Current
        = EnterpriseLibraryContainer.CreateDefaultContainer(configSource);
}

And testing it like this:

ConfigureLogging(SourceLevels.Warning); //Do not allow Information level

var logEntry = new LogEntry { Message = "test", Severity = TraceEventType.Information };
var shouldLog = Logger.Writer.ShouldLog(logEntry);
Logger.Writer.Write(logEntry);

After I run this code the shouldLog variable is true, but no log entry is written. If I pass SourceLevels.Information to the ConfigureLogging method instead I do get an entry written to my log. Am I doing something wrong?

Answer 1

I don't think you are doing anything wrong. However, I'll admit the behavior is a bit odd.

As mentioned here the ShouldLog method queries all of the configured Filters against the LogEntry. The reason why ShouldLog returns true is that you haven't defined any filters so everything passes.

"But wait!", you say. "I've set the source level Filter in the fluent configuration!"

That's true -- in a sense. But despite it's name the Filter method doesn't create an actual filter (perhaps it should, though)! It basically just sets a SourceLevels value which only gets checked when Write is called. If you use the configuration file instead of the fluent configuration then in the config file Filter is actual named switchValue so it's not quite as confusing.

So ShouldLog returns true because there are no filters but Write does not actually write because of the check against SourceLevels. This is pretty counter-intuitive. It would be nice if in version 6 the check could be included in ShouldLog? It defeats the purpose of ShouldLog if it returns true which causes the user to construct a bunch of expensive objects but in the end the message is never logged because of the SourceLevels check.

I checked and it looks like this behavior has been around since at least version 4.

What to do about this behavior? The easiest way is to add a custom filter to perform the SourceLevels check:

public class SourceLevelFilter : LogFilter
{
    private SourceLevels level;

    public SourceLevelFilter(NameValueCollection nvc)
        : base("SourceLevelFilter")
    {
        if (!Enum.TryParse<SourceLevels>(nvc["Level"], out level))
        {
            throw new ArgumentOutOfRangeException(
                "Value " + nvc["Level"] + " is not a valid SourceLevels value");
        }
    }

    public override bool Filter(LogEntry log)
    {
        if (log == null) throw new ArgumentNullException("log");
        return ShouldLog(log.Severity);
    }

    public bool ShouldLog(TraceEventType eventType)
    {
        return ((((TraceEventType)level) & eventType) != (TraceEventType)0);
    }

    public SourceLevels SourceLevels
    {
        get { return level; }
    }
}

// ...

SourceLevels logLevel = SourceLevels.Warning;

var builder = new ConfigurationSourceBuilder();

builder.ConfigureLogging()
    .WithOptions
    .FilterCustom<SourceLevelFilter>("SourceLevelFilter", 
        new NameValueCollection() { { "Level", logLevel.ToString() } } )
    .LogToCategoryNamed("General")
    .WithOptions.SetAsDefaultCategory()
    .SendTo.FlatFile("Main log file")
    .FormatWith(
        new FormatterBuilder()
            .TextFormatterNamed("Text Formatter")
            .UsingTemplate("{timestamp(local:MM/dd/yyyy HH:mm:ss.fff)} [{severity}] {message}"))
    .Filter(logLevel) //Setting the source level filter
    .ToFile("log.txt");

Now ShouldLog will incorporate the SourceLevels value in its check and will return false for the LogEntry with the Information severity when the SourceLevels is set to Warning.

UPDATE

One issue you might have with filters is that they are global so you'd probably have to beef up the filter above to store the SourceLevels along with the Category.

If you just wanted to check if Warning was enabled you could check the specific filter:

public bool IsWarningEnabled
{
    get
    {
        return writer.GetFilter<SourceLevelFilter>().ShouldLog(TraceEventType.Warning);
    }
}

Another approach would be to manage the SourceLevels yourself without a filter. Since you are writing a general purpose log wrapper then I assume that the SourceLevels will be set through your wrapper. You also talk about exposing your own methods such as IsDebugEnabled. If so, then you can maintain that knowledge internal to your wrapper and provide that check on demand. If you are returning EntLib LogWriters to callers then that might work since the user would want to call ShouldLog on the LogWriter. Although, you could also create extension methods (such as IsWarningEnabled() ) on LogWriter.