Logging Block not Logging when says it should

Topics: Logging Application Block
May 7, 2007 at 2:57 PM
I have a logging block which is not logging particular categories and/or priorities of events. I have even configured a test section of code to use the ShouldLog function in order to check the what the outcome should be (which comes out correctly but is not the same as what gets logged in the file).

public static void TestLoggingConfig()
{
LogEnabledFilter lefLogEnabledFilter;
CategoryFilter cfCategoryFilter;
PriorityFilter pfPriorityFilter;

#if DEBUG
System.Text.StringBuilder sbBuilder = new System.Text.StringBuilder();

lefLogEnabledFilter = Logger.GetFilter<Microsoft.Practices.EnterpriseLibrary.Logging.Filters.LogEnabledFilter>();
if (lefLogEnabledFilter != null)
{
sbBuilder.AppendLine("Logging Enabled: " + lefLogEnabledFilter.Enabled);
}

cfCategoryFilter = Logger.GetFilter<Microsoft.Practices.EnterpriseLibrary.Logging.Filters.CategoryFilter>();
if (cfCategoryFilter != null)
{
//The Category object referenced here is a struct where the fields are constant strings equal to their own name
sbBuilder.AppendLine("Logging CategoryFilter: {Error} " + cfCategoryFilter.ShouldLog(Category.Error));
sbBuilder.AppendLine("Logging CategoryFilter: {General} " + cfCategoryFilter.ShouldLog(Category.General));
sbBuilder.AppendLine("Logging CategoryFilter: {Trace} " + cfCategoryFilter.ShouldLog(Category.Trace));
sbBuilder.AppendLine("Logging CategoryFilter: {Verbose} " + cfCategoryFilter.ShouldLog(Category.Verbose));
sbBuilder.AppendLine("Logging CategoryFilter: {Warning} " + cfCategoryFilter.ShouldLog(Category.Warning));
}

pfPriorityFilter = Logger.GetFilter<Microsoft.Practices.EnterpriseLibrary.Logging.Filters.PriorityFilter>();
if (pfPriorityFilter != null)
{
//The Priority object referenced here is a struct where the fields are constant integers starting at 0 = Lowest
sbBuilder.AppendLine("Logging PriorityFilter: " + pfPriorityFilter.ShouldLog(Priority.Lowest));
sbBuilder.AppendLine("Logging PriorityFilter: " + pfPriorityFilter.ShouldLog(Priority.Low));
sbBuilder.AppendLine("Logging PriorityFilter: " + pfPriorityFilter.ShouldLog(Priority.Normal));
sbBuilder.AppendLine("Logging PriorityFilter: " + pfPriorityFilter.ShouldLog(Priority.High));
sbBuilder.AppendLine("Logging PriorityFilter: " + pfPriorityFilter.ShouldLog(Priority.Highest));
}

LogEntry leLogEntry = new LogEntry();
leLogEntry.Message = "Demonstrate filter check";
leLogEntry.Priority = Priority.Normal;
leLogEntry.Categories.Add(Category.Verbose);

sbBuilder.AppendLine("Logging ShouldLog: " + Logger.ShouldLog(leLogEntry));
System.Diagnostics.Debug.WriteLine(sbBuilder.ToString());
#endif
}

//The Output is as follows:
//*****************************************
//Logging Enabled: True
//Logging CategoryFilter: {Error} True
//Logging CategoryFilter: {General} True
//Logging CategoryFilter: {Trace} False
//Logging CategoryFilter: {Verbose} True
//Logging CategoryFilter: {Warning} True
//Logging PriorityFilter: (Lowest) True
//Logging PriorityFilter: (Low) True
//Logging PriorityFilter: (Normal) True
//Logging PriorityFilter: (High) True
//Logging PriorityFilter: (Highest) True
//Logging ShouldLog: True

The results above are what I expect to and agree with the config file, but when I go to Log the following examples, I get absolutely nothing for the following. It doesn't matter if I change the Listener, the filters,etc.
Logger.Write("Test For Error. EH", Category.Error, Priority.High);
Logger.Write("Test For Error. WH", Category.Warning, Priority.High);
//Logger.Write("Test For Error. TH", Category.Trace, Priority.High); // Shouldn't write to log (and doesn't)
Logger.Write("Test For Error. EN", Category.Error, Priority.Normal);
Logger.Write("Test For Error. WN", Category.Warning, Priority.Normal);
//Logger.Write("Test For Error. TN", Category.Trace, Priority.Normal); // Shouldn't write to log (and doesn't)
Logger.Write("Test For Error. EL", Category.Error, Priority.Low);

Does anyone see something wrong with what I am doing and/or why only my General and Verbose items are being logged?
TIA
May 8, 2007 at 2:16 AM
Assuming your configuration is correct, perhaps you are getting an error when logging other categories, etc. I recommend checking the Special Sources -> Logging Errors & Warning to see if perhaps an error is occuring which is why you are seeing certain log messages.

For kicks, you may also want to log to the EventLog instead of a file to see if it gets all the messages.

Regards,

Dave

____________________________

David Hayden
Microsoft MVP C#
May 8, 2007 at 8:11 AM
Hey TechnoDex dude I have tried replicating your scenario, and I get similar results - in fact, I don't get anything logged, not even the General and Verbose categories. ( I am logging to the (Application) EventLog...ie, I have not changed the default "Formatted EventLog TraceListener"). Even though the line "Logger.ShouldLog(leLogEntry)" returns true, the line "Logger.Write(leLogEntry)" does nothing! What gives?
May 8, 2007 at 8:49 AM
Nevermind! I was a dumb-ass. Turns out my Application Event Log was full. However, the code was running and completeting without any errors. I tried manually adding something to the event log with the following line of code "System.Diagnostics.EventLog.WriteEntry("Enterprise Library Logging Test", "Manual Event Log Entry", System.Diagnostics.EventLogEntryType.Information);" and this is where I got an exception reporting that the Event Log was full. So I cleared the log, and reran your code as posted above, and all worked perfectly!
May 8, 2007 at 2:45 PM
Here is my app.config file. I have tried with both flat file and also Event Log, both give the same results. Am I missing something about the Special Sources dealing with Errors and Warnings? I have the standard events for Error and Warning configured and also in the Special Sources. I have tried removing one but not the other and vice versa but still no luck. Any suggestions?

<?xml version="1.0" encoding="utf-8"?>
<configuration>
<configSections>
<section name="loggingConfiguration" type="Microsoft.Practices.EnterpriseLibrary.Logging.Configuration.LoggingSettings, Microsoft.Practices.EnterpriseLibrary.Logging, Version=2.0.0.0, Culture=neutral, PublicKeyToken=null" />
</configSections>
<loggingConfiguration name="Logging Application Block" tracingEnabled="true"
defaultCategory="General" logWarningsWhenNoCategoriesMatch="true">
<listeners>
<add source="Enterprise Library Logging" formatter="Text Formatter"
log="Application" machineName="" listenerDataType="Microsoft.Practices.EnterpriseLibrary.Logging.Configuration.FormattedEventLogTraceListenerData, Microsoft.Practices.EnterpriseLibrary.Logging, Version=2.0.0.0, Culture=neutral, PublicKeyToken=null"
traceOutputOptions="None" type="Microsoft.Practices.EnterpriseLibrary.Logging.TraceListeners.FormattedEventLogTraceListener, Microsoft.Practices.EnterpriseLibrary.Logging, Version=2.0.0.0, Culture=neutral, PublicKeyToken=null"
name="Formatted EventLog TraceListener" />
</listeners>
<formatters>
<add template="Timestamp: {timestamp} Message: {message} Category: {category} Priority: {priority} EventId: {eventid} Severity: {severity} Title:{title}&#xD;&#xA;Machine: {machine} Application Domain: {appDomain} Process Id: {processId}"
type="Microsoft.Practices.EnterpriseLibrary.Logging.Formatters.TextFormatter, Microsoft.Practices.EnterpriseLibrary.Logging, Version=2.0.0.0, Culture=neutral, PublicKeyToken=null"
name="Text Formatter" />
</formatters>
<logFilters>
<add categoryFilterMode="DenyAllExceptAllowed" type="Microsoft.Practices.EnterpriseLibrary.Logging.Filters.CategoryFilter, Microsoft.Practices.EnterpriseLibrary.Logging, Version=2.0.0.0, Culture=neutral, PublicKeyToken=null"
name="Category Filter">
<categoryFilters>
<add name="Warning" />
<add name="Error" />
<add name="General" />
<add name="Verbose" />
</categoryFilters>
</add>
<add enabled="true" type="Microsoft.Practices.EnterpriseLibrary.Logging.Filters.LogEnabledFilter, Microsoft.Practices.EnterpriseLibrary.Logging, Version=2.0.0.0, Culture=neutral, PublicKeyToken=null"
name="LogEnabled Filter" />
<add minimumPriority="0" maximumPriority="4" type="Microsoft.Practices.EnterpriseLibrary.Logging.Filters.PriorityFilter, Microsoft.Practices.EnterpriseLibrary.Logging, Version=2.0.0.0, Culture=neutral, PublicKeyToken=null"
name="Priority Filter" />
</logFilters>
<categorySources>
<add switchValue="ActivityTracing" name="Trace">
<listeners>
<add name="Formatted EventLog TraceListener" />
</listeners>
</add>
<add switchValue="Verbose" name="Verbose">
<listeners>
<add name="Formatted EventLog TraceListener" />
</listeners>
</add>
<add switchValue="Warning" name="Warning">
<listeners>
<add name="Formatted EventLog TraceListener" />
</listeners>
</add>
<add switchValue="Error" name="Error">
<listeners>
<add name="Formatted EventLog TraceListener" />
</listeners>
</add>
<add switchValue="All" name="General">
<listeners>
<add name="Formatted EventLog TraceListener" />
</listeners>
</add>
</categorySources>
<specialSources>
<allEvents switchValue="All" name="All Events" />
<notProcessed switchValue="All" name="Unprocessed Category" />
<errors switchValue="All" name="Logging Errors & Warnings">
<listeners>
<add name="Formatted EventLog TraceListener" />
</listeners>
</errors>
</specialSources>
</loggingConfiguration>
</configuration>
May 8, 2007 at 8:07 PM
I don't see anything out of sorts, but it is hard to say without being at the code and in your environment.

If you log All Events by adding a TraceListener to the Special Sources -> All Events, do you get all the events?

Regards,

Dave

____________________________

David Hayden
Microsoft MVP C#
May 8, 2007 at 10:10 PM
If I put a trace listener in the All Events section, then all of the events are logged to that listener. Please explain as this does not make sense and/or is counter intuitive. Why can I not log particular events using particular Trace Listeners? If I want to send Emails on Errors and Warnings and log Verbose and Info to a flat file then this Special Sources section does not make sense.
May 8, 2007 at 10:39 PM
I just want to make sure the Logging Application Block is working correctly and what you are experiencing is a configuration problem. If the events you are having a problem with get added to the TraceListener associated with All Events but not in a TraceListener defined in your configuration, then it must mean they are being caught by a filter. Sounds like the block is working okay and there is just something up with your configuration and/or environment.

Regards,

Dave

____________________________

David Hayden
Microsoft MVP C#
May 9, 2007 at 2:56 AM
I would tend to disagree with you as in my original post, I show that via the ShouldLog method that out of all Categories that only Trace should not be logged and out of all Priorities that all Priorities should be logged. With this information, we should be able to create a matrix of Categories vs Priorities and be able to identify all items which should not be logged. In this case all Trace Categories no matter what that Priority should not be logged. Continuing to work along this vein all others should that have been identified should be logged. Making this even more interesting is the fact that I have removed the filters and still the problem persists. You also continue to indicate it might be my environment. I have tried this on multiple machines which starts to negate this point. Personally my thought is that it is dealing with the config file, but no one seams to be able to indicate what I am missing. The documentation for the custom settings section seams to be limited also which is why I feel I am missing some key item that hasn't been indentified.
May 9, 2007 at 4:33 AM
Dude the only structural difference between my app.config and yours is that mine has the section categoryFilterMode="AllowAllExceptDenied" and yours has categoryFilterMode="DenyAllExceptAllowed". Functionally this really should make no difference though. What I think you should try is to add your TraceListerner to the Unprocessed Categories special category...see what difference that makes.

What I find odd though is that your app.config is not "well-formed xml"... yours has a line reading <errors switchValue="All" name="Logging Errors & Warnings"> That ampersand is not allowed in xml...it should be <errors switchValue="All" name="Logging Errors & Warnings"> as per my app.config. My text formatter definition also looks somewhat different to yours: yours is <add template="Timestamp: {timestamp} Message: {message} Category: {category} Priority: {priority} EventId: {eventid} Severity: {severity} Title:{title}&#xD;&#xA;Machine: {machine} Application Domain: {appDomain} Process Id: {processId}" while mine is <add template="Timestamp: {timestamp}&#xD;&#xA;Message: {message}&#xD;&#xA;Category: {category}&#xD;&#xA;Priority: {priority}&#xD;&#xA;EventId: {eventid}&#xD;&#xA;Severity: {severity}&#xD;&#xA;Title:{title}&#xD;&#xA;Machine: {machine}&#xD;&#xA;Application Domain: {appDomain}&#xD;&#xA;Process Id: {processId}&#xD;&#xA;Process Name: {processName}&#xD;&#xA;Win32 Thread Id: {win32ThreadId}&#xD;&#xA;Thread Name: {threadName}&#xD;&#xA;Extended Properties: {dictionary({key} - {value}&#xD;&#xA;)}"
May 9, 2007 at 5:36 PM
I have tried adding in the Unprocessed Categories listeners, but this does not change a thing. I have tried using the AllowAllExceptDenied as opposed to using the DenyAllExceptAllowed. I have tried not using any log filters but still no luck. As for the text formatter, I did remove some of the options from the default as I didn't want or need all of the information provided.
May 10, 2007 at 7:39 PM
At this point it appears that the the LogSource.TraceData method calls the ShouldTrace() method which is stopping it listeners from being called. Apparently this is comparing the LogSource Level against the EventType which is always Information. I've been trying to dig deeper into where the LogSource Level gets set, but I'm getting tangled in the misdirection of code. The EventType appears to be a default value of Information based on the overload of the Logger.Write() method I am calling. Is my understanding of the way the Category functionality works incorrect? Are the categories designed to be arbitrary strings which you associate with categorySources in order to log data for this particular category? Does someone actually have a working example of logging code that that could post?
Nov 1, 2007 at 7:25 PM
What appears to resolve this problem is changing the switch value to "All" for each categorySource. I'm not sure why the switch value must be All but I picked this difference up looking someone else's example on the web. Can someone explain why the switch value for certain settings prevent logging?

<categorySources>
<add switchValue="All" name="Trace">
<listeners>
<add name="Formatted EventLog TraceListener" />
</listeners>
</add>
<add switchValue="All" name="Verbose">
<listeners>
<add name="Formatted EventLog TraceListener" />
</listeners>
</add>
<add switchValue="All" name="Warning">
<listeners>
<add name="Formatted EventLog TraceListener" />
</listeners>
</add>
<add switchValue="All" name="Error">
<listeners>
<add name="Formatted EventLog TraceListener" />
</listeners>
</add>
<add switchValue="All" name="General">
<listeners>
<add name="Formatted EventLog TraceListener" />
</listeners>
</add>
</categorySources>
Nov 28, 2007 at 7:13 PM
I'm having the same problem except I still don't get any messages when logging to Special Sources -> All Events. It seems like category filtering isn't working or doesn't work the way I expect because when I remove the category filters I added to the config file messages begin to log again. Below is my config file. Any ideas?

<?xml version="1.0" encoding="utf-8"?>
<configuration>
<configSections>
<section name="loggingConfiguration" type="Microsoft.Practices.EnterpriseLibrary.Logging.Configuration.LoggingSettings, Microsoft.Practices.EnterpriseLibrary.Logging, Version=3.1.0.0, Culture=neutral, PublicKeyToken=b03f5f7f11d50a3a" />
<section name="dataConfiguration" type="Microsoft.Practices.EnterpriseLibrary.Data.Configuration.DatabaseSettings, Microsoft.Practices.EnterpriseLibrary.Data, Version=3.1.0.0, Culture=neutral, PublicKeyToken=b03f5f7f11d50a3a" />
</configSections>
<loggingConfiguration name="Logging Application Block" tracingEnabled="true"
defaultCategory="General" logWarningsWhenNoCategoriesMatch="true">
<listeners>
<add source="Enterprise Library Logging" formatter="Text Formatter"
log="Application" machineName="" listenerDataType="Microsoft.Practices.EnterpriseLibrary.Logging.Configuration.FormattedEventLogTraceListenerData, Microsoft.Practices.EnterpriseLibrary.Logging, Version=3.1.0.0, Culture=neutral, PublicKeyToken=b03f5f7f11d50a3a"
traceOutputOptions="None" type="Microsoft.Practices.EnterpriseLibrary.Logging.TraceListeners.FormattedEventLogTraceListener, Microsoft.Practices.EnterpriseLibrary.Logging, Version=3.1.0.0, Culture=neutral, PublicKeyToken=b03f5f7f11d50a3a"
name="Formatted EventLog TraceListener" />
<add fileName=".\rs-rolling.log" rollSizeKB="10000" timeStampPattern="yyyy-MM-dd"
rollFileExistsBehavior="Overwrite" rollInterval="Week" formatter="Text Formatter"
header="----------------------------------------" footer="----------------------------------------"
listenerDataType="Microsoft.Practices.EnterpriseLibrary.Logging.Configuration.RollingFlatFileTraceListenerData, Microsoft.Practices.EnterpriseLibrary.Logging, Version=3.1.0.0, Culture=neutral, PublicKeyToken=b03f5f7f11d50a3a"
traceOutputOptions="None" type="Microsoft.Practices.EnterpriseLibrary.Logging.TraceListeners.RollingFlatFileTraceListener, Microsoft.Practices.EnterpriseLibrary.Logging, Version=3.1.0.0, Culture=neutral, PublicKeyToken=b03f5f7f11d50a3a"
name="Rolling Flat File Trace Listener" />
</listeners>
<formatters>
<add template="Timestamp: {timestamp}&#xD;&#xA;Message: {message}&#xD;&#xA;Category: {category}&#xD;&#xA;Priority: {priority}&#xD;&#xA;EventId: {eventid}&#xD;&#xA;Severity: {severity}&#xD;&#xA;Title:{title}&#xD;&#xA;Machine: {machine}&#xD;&#xA;Application Domain: {appDomain}&#xD;&#xA;Process Id: {processId}&#xD;&#xA;Process Name: {processName}&#xD;&#xA;Win32 Thread Id: {win32ThreadId}&#xD;&#xA;Thread Name: {threadName}&#xD;&#xA;Extended Properties: {dictionary({key} - {value}&#xD;&#xA;)}"
type="Microsoft.Practices.EnterpriseLibrary.Logging.Formatters.TextFormatter, Microsoft.Practices.EnterpriseLibrary.Logging, Version=3.1.0.0, Culture=neutral, PublicKeyToken=b03f5f7f11d50a3a"
name="Text Formatter" />
</formatters>
<logFilters>
<add enabled="true" type="Microsoft.Practices.EnterpriseLibrary.Logging.Filters.LogEnabledFilter, Microsoft.Practices.EnterpriseLibrary.Logging, Version=3.1.0.0, Culture=neutral, PublicKeyToken=b03f5f7f11d50a3a"
name="LogEnabled Filter" />
<add categoryFilterMode="DenyAllExceptAllowed" type="Microsoft.Practices.EnterpriseLibrary.Logging.Filters.CategoryFilter, Microsoft.Practices.EnterpriseLibrary.Logging, Version=3.1.0.0, Culture=neutral, PublicKeyToken=b03f5f7f11d50a3a"
name="Debug Filter">
<categoryFilters>
<add name="Debug" />
</categoryFilters>
</add>
<add categoryFilterMode="DenyAllExceptAllowed" type="Microsoft.Practices.EnterpriseLibrary.Logging.Filters.CategoryFilter, Microsoft.Practices.EnterpriseLibrary.Logging, Version=3.1.0.0, Culture=neutral, PublicKeyToken=b03f5f7f11d50a3a"
name="DataAccessLayer Filter">
<categoryFilters>
<add name="DataAccessLayer" />
</categoryFilters>
</add>
</logFilters>
<categorySources>
<add switchValue="All" name="Debug">
<listeners>
<add name="Rolling Flat File Trace Listener" />
</listeners>
</add>
<add switchValue="All" name="DataAccessLayer">
<listeners>
<add name="Formatted EventLog TraceListener" />
</listeners>
</add>
<add switchValue="All" name="General">
<listeners>
<add name="Formatted EventLog TraceListener" />
</listeners>
</add>
</categorySources>
<specialSources>
<allEvents switchValue="All" name="All Events">
<listeners>
<add name="Formatted EventLog TraceListener" />
</listeners>
</allEvents>
<notProcessed switchValue="All" name="Unprocessed Category" />
<errors switchValue="All" name="Logging Errors & Warnings">
<listeners>
<add name="Formatted EventLog TraceListener" />
</listeners>
</errors>
</specialSources>
</loggingConfiguration>
</configuration>