Thursday, July 31, 2014

log4net: DebugAppender

The DebugAppender in log4net allows you to output messages to any “debug” listener.  There is another similar appender called OutputDebugStringAppender. The difference is that OutputDebugStringAppender uses unmanaged code to call the Windows Debug API.  If you are running through the Visual Studio debugger, the output will not be displayed unless you request display from Unmanaged Code.  With DebugAppender, the display will happen automatically because its managed code.

Use with Windows Service

One of the cool things you can do with the DebugAppender is use this in a Windows Service.  In your service, use debug statements liberally throughout your code going to the DebugAppender.  If you use TopShelf for your Windows Service (which allows you to run in console mode and windows service mode), then while running through Visual Studio, you will see you debug statements showing through the Debug Output Window.  Then, what’s really cool, is that when you deploy the application, you can run Microsoft’s DebugView (dbgview.exe) on the machine where the service is running and you can AGAIN see the debug messages in a LIVE environment.  If debug view is not running, then the overhead on the live application should be minimal.

Visual Studio “swallows” Debug Messages


Note that if you want to see debug messages in DebugView while running through Visual Studio, you will have to “Debug >> Run without Debugging”.  If the Visual Studio debugger is running, then it EATS the debug message and DebugView will never “see” the message.

log4net: EventLogAppender

Using the EventLogAppender in log4net allows you to post messages to the Windows Event Log so that they can be seen in the Event Viewer.  However, there are a few “special” issues with this logger that I’d like to point out.

Here’s a typical appender definition:

<appender name="EventLogAppender" type="log4net.Appender.EventLogAppender" >
<applicationName value="MainService" />
<layout type="log4net.Layout.PatternLayout">
<conversionPattern value="%date [%thread] %-5level %logger - %message%newline" />
</layout>

<filter type="log4net.Filter.LevelRangeFilter">
<levelMin value="INFO" />
<levelMax value="FATAL" />
</filter>
</appender>


1) applicationName attribute
The application name is what the “source” column will display in the event viewer:
image 
2) Default Event ID is 0 – Causes error message
image If you do not specify an EventID, then by default, the EventID logged with the message is 0.  This causes the event viewer to display a warning with you message content (1):
The description for Event ID 0 from source MainService cannot be found. Either the component that raises this event is not installed on your local computer or the installation is corrupted. You can install or repair the component on the local computer.

If the event originated on another computer, the display information had to be saved with the event.

The following information was included with the event:


You message is still displayed (2), but you will have this message displayed first.

To eliminate this message, you simply need to specify an EventID greater than 0 in either the ThreadContext or GlobalContext arrays for log4net.  I will let you research this further on your own, but to quickly get rid of the message, right after you configure log4net in your application, just set the GlobalContext property like this:

XmlConfigurator.ConfigureAndWatch(new FileInfo(@".\log4net.config"));
GlobalContext.Properties["EventID"] = 1;
var log = LogManager.GetLogger(typeof(Program));

With a 1 as the EventID, your logged message will be cleaner:
image


3) log4net Levels and Event Log Levels
When logging log4net messages in the Event Log, here is how the “levels” translate:

log4net Level –> Windows Event Log Level
DEBUG, INFO –> Information
WARN –> Warning
ERROR, FATAL –> Error

image

log4net: Custom Filter

I have been playing around with log4net and some of its advanced features.  I wanted to blog about a custom filter I wrote: CompoundFilter.  This filter allows me to combine multiple standard filters into one “if all these filters are true, then…”.  Specifically, what I wanted to do was define an Appender, but then filter messages based on BOTH logger (LoggerMatchFilter) AND Level (LevelMatchFilter or LevelRangeFilter).

In a project called Log4Net.CustomFilter, I added a (nuget) log4net reference, then created CompoundFilter.cs:

using System;
using System.Collections.Generic;
using log4net.Core;
using log4net.Filter;

namespace Log4Net.CustomFilters
{
public class CompoundFilter : FilterSkeleton
{
private bool _acceptOnMatch;
private readonly IList<IFilter> _filters = new List<IFilter>();

public override FilterDecision Decide(LoggingEvent loggingEvent)
{
if (loggingEvent == null)
throw new ArgumentNullException("loggingEvent");

foreach (IFilter filter in _filters)
{
if (filter.Decide(loggingEvent) != FilterDecision.Accept)
return FilterDecision.Neutral; // one of the filter has failed
}

// All conditions are true
return _acceptOnMatch ? FilterDecision.Accept : FilterDecision.Deny;
}

public IFilter Filter
{
set { _filters.Add(value); }
}

public bool AcceptOnMatch
{
get { return _acceptOnMatch; }
set { _acceptOnMatch = value; }
}
}
}


Then, in my main application, I add a reference to the project (better – add a reference to the DLL).  Then, in the log4net.config file, you can add this syntax:

<appender name="ConsoleAppender" type="log4net.Appender.ConsoleAppender">
<layout type="log4net.Layout.PatternLayout">
<param name="ConversionPattern" value="%d [%t] %-5p %c - %m%n"/>
</layout>

<filter type="Log4Net.CustomFilters.CompoundFilter, Log4Net.CustomFilters">
<filter type="log4net.Filter.LoggerMatchFilter">
<loggerToMatch value="MultiConnectG2.MainService" />
</filter>
<filter type="log4net.Filter.LevelMatchFilter">
<levelToMatch value="DEBUG"/>
</filter>
<acceptOnMatch value="true" />
</filter>

<filter type="log4net.Filter.LoggerMatchFilter">
<loggerToMatch value="MultiConnectG2.MainService" />
<acceptOnMatch value="false" />
</filter>

</appender>


The first filter uses the new CompoundFilter and tells it what assembly to find it in (Log4Net.CustomFilters).  Inside, we specify 2 standard filters: LoggerMatchFilter and LevelMatchFilter.  What this means is that this Compound filter will match if the logger’s name is MultiConnectG2.MainService and the level of the message is DEBUG.  And, if both of these match, then we should accept this message.


The second filter is a simply LoggerMatchFilter that simply says, if the logger name is MultiConnectG2.MainService, then do not accept the message.


Filters quit trying to match once the first filter is matched.  So this appender will ONLY allow DEBUG messages from any logger who’s name starts with MultiConnectG2.MainService and reject any other message from those loggers.


Any other logger (with a name that does not start with MultiConnectG2.MainService) will be processed normally through this appender.