Logging to SQL Server with Log4Net

How do you know what’s happening on your production servers? Logging off course (if you wonder; no, ‘debug & breakpoints’ is never the correct answer. Never ever. Ever.).
We have been using Log4Net as our logging tool for 3-4 years by now and I just wanted to share how we are using it and how incredibly powerful good logging can be.
First of all, if you are not familiar with Log4Net it is an open source, free-for-use logging framework under the Apache Foundation umbrella. Among its strengths is that it is fairly easy to get started with, it has a low impact on the application performance and it has a lot of adapters that lets you log to a lot of different destinations (console, file, database, event log, etc).
At the beginning we set up logging to console (for those systems that had console output) and file, but after a while we added logging to SQL Server. It is the combination of logs stored in a SQL database and full-text indexing of these logs that really gives us eyes in to what happens on our production servers.

Log to console

Logging to console is definitely the easiest way to get started with Log4Net. But writing to the console output is also the one that gives you least payback in form of long-term insight into your production systems. Log4Net can be configured either using xml or code, but xml is by far the most used. Typically you do the xml configuration in your app/web.config, but you can also keep the Log4Net configuration in separate xml files if you prefer. We chose the app/web.config approach and so the xml for console logging looks like this:

<?xml version="1.0" encoding="utf-8"?>
<configuration>
    <configSections>
        <section 
            name="log4net" 
            type="log4net.Config.Log4NetConfigurationSectionHandler,Log4net" />
    </configSections>
    <log4net>
        <root>
            <level 
                value="DEBUG" />
            <appender-ref 
                ref="ConsoleAppender" />
        </root>
        <appender 
            name="ConsoleAppender" 
            type="log4net.Appender.ConsoleAppender">
            <layout 
                type="log4net.Layout.PatternLayout">
                <param 
                    name="ConversionPattern" 
                    value="%d [%t] %-5p [%x] - %m%n" />
            </layout>
            <filter 
                type="log4net.Filter.LevelRangeFilter">
                <param 
                    name="LevelMin" 
                    value="DEBUG" />
                <param 
                    name="LevelMax" 
                    value="FATAL" />
            </filter>
        </appender>
    </log4net>
</configuration>

You can do this configuration in code as well, but the great benefit of using xml for the configuration is that you can change the settings (for instance the log level threshold) without re-deploying your application. In the case of web hosts you can even change it without restarting the application. If you’ve been a good boy/girl and set up debug-level logging in your code, you can just flip an xml-switch and additional log entries will start flowing in.

Log to file

If you want your logs to survive application restarts (and the console window buffer) and/or have an application that doesn’t have console output, logging to file would be the next step on logging ladder.
The main thing to keep in mind when logging to file is to set limits on how large each log file can get. Log4Net has some defaults that might not suit your situation so be sure to check out the documentation on how you can configure logging to file. For one of our systems we chose to have a 10 mb limit on each file which you can see in this xml config:

<log4net>
    <root>
        <level value="DEBUG" />
        <appender-ref ref="LogFileAppender" />
    </root>
    <appender 
        name="LogFileAppender" 
        type="log4net.Appender.RollingFileAppender">
        <param 
            name="File" 
            value="logs.txt" />
        <param 
            name="AppendToFile" 
            value="true" />
        <!-- Logfiles are rolled over to backup files when size limit is reached -->
        <rollingStyle 
            value="Size" />
        <!-- Maximum number of backup files that are kept before the oldest is erased -->
        <maxSizeRollBackups 
            value="10" />
        <!-- Maximum size that the output file is allowed to reach before being rolled over to backup files -->
        <maximumFileSize 
            value="10MB" />
        <!-- Indicating whether to always log to the same file -->
        <staticLogFileName 
            value="true" />
        <layout type="log4net.Layout.PatternLayout">
            <param 
                name="ConversionPattern" 
                value="%-5p%d{yyyy-MM-dd hh:mm:ss} – %m%n" />
        </layout>
    </appender>
</log4net>

The above config specifies that maximum 100 mb of logs will be kept on file (10 mb pr file and max 10 files).

Log to console and file

There is no problem logging to both console and file simultaneously and you can even set different log levels on each appender. If you want to have different files for different log levels (e.g. ‘debug.log’, ‘info.log’, etc), you can just configure as many file appenders as you need. Here is an example of logging to both console and file at the same time:

<log4net>
    <root>
        <level value="INFO" />
        <appender-ref ref="LogFileAppender" />
        <appender-ref ref="ConsoleAppender" />
    </root>
    <appender name="LogFileAppender" type="log4net.Appender.RollingFileAppender">
        <filter type="log4net.Filter.LevelRangeFilter">
            <param name="LevelMin" value="WARN" />
            <param name="LevelMax" value="FATAL" />
        </filter>
        ...
    </appender>
    <appender name="ConsoleAppender" type="log4net.Appender.ConsoleAppender">
        ...
    </appender>
</log4net>    

The default log level is set to INFO, which means that unless otherwise specified in the appenders, messages with level INFO, WARN, ERROR and FATAL will be logged. The file appender is set to only log WARN, ERROR and FATAL though.

Log to SQL Server

As already mentioned the logging to file and console is easy to get started with and does not take much effort to set up. Setting up logging to a database takes a bit more work, but it is far from difficult. Here is how we configured logging to a SQL database from one of our web hosts:

<root>
    <level value="DEBUG" />
    <appender-ref ref="AdoNetAppender" />
</root>
<appender 
    name="AdoNetAppender" 
    type="log4net.Appender.AdoNetAppender">
    <threshold>INFO</threshold>
    <bufferSize 
        value="50" />
    <connectionType 
        value="System.Data.SqlClient.SqlConnection, System.Data, Version=1.0.3300.0, Culture=neutral, PublicKeyToken=b77a5c561934e089" />
    <connectionString 
        value="data source=SERVERNAME;initial catalog=DATABASE;integrated security=false;persist security info=True;User ID=USERNAMEN;Password=PASSWORD" />
    <commandText 
        value="INSERT INTO Logs ([Date],[Thread],[Source],[Level],[Logger],[Message],[Exception],[HostName]) VALUES (@log_date, @thread, 'LOG SOURCE',@log_level, @logger, @message, @exception, @hostname)" />
    <parameter>
        <parameterName value="@log_date" />
        <dbType value="DateTime" />
        <layout type="log4net.Layout.RawTimeStampLayout" />
    </parameter>
    <parameter>
        <parameterName value="@thread" />
        <dbType value="String" />
        <size value="255" />
        <layout type="log4net.Layout.PatternLayout">
            <conversionPattern value="%thread" />
        </layout>
    </parameter>
    <parameter>
        <parameterName value="@hostname" />
        <dbType value="String" />
        <size value="255" />
        <layout type="log4net.Layout.PatternLayout">
            <conversionPattern value="%property{log4net:HostName}" />
        </layout>
    </parameter>
    <parameter>
        <parameterName value="@log_level" />
        <dbType value="String" />
        <size value="50" />
        <layout type="log4net.Layout.PatternLayout">
            <conversionPattern value="%level" />
        </layout>
    </parameter>
    <parameter>
        <parameterName value="@logger" />
        <dbType value="String" />
        <size value="255" />
        <layout type="log4net.Layout.PatternLayout">
            <conversionPattern value="%logger" />
        </layout>
    </parameter>
    <parameter>
        <parameterName value="@message" />
        <dbType value="String" />
        <size value="-1" />
        <layout type="log4net.Layout.PatternLayout">
            <conversionPattern value="%message" />
        </layout>
    </parameter>
    <parameter>
        <parameterName value="@exception" />
        <dbType value="String" />
        <size value="-1" />
        <layout type="log4net.Layout.ExceptionLayout" />
    </parameter>
</appender>
    </log4net>

The xml config is the same whether you are configuring logging in web- or app.config (you need to insert your own values for servername, database and login).
The main thing to point out here is the ‘buffer’ element, which tells Log4Net how many log entries to buffer up before writing them the database. There isn’t any correct number here and you need to figure out what suits your environment the best. The trade-offs are performance versus reliability, since a low buffer will take more resources because of the many writes to the database table (and yes, we learned that the hard way off course). A high buffer limit will be less reliable because if your application crashes, the logs not yet written will never be written.
Also; it might make sense to have different buffer limits for different environments. In the development and test/QA environments, a low limit might be preferable since the logs will be written faster to the database. And since the number of log entries will be far less than in the production system, it might be long time to wait for the logs to be available if you run with the same limits as in production. In a production environment, instant logs are in most cases not relevant and performance is more critical. Then again, reliability is also a good thing so you need to find a good trade off.
Another thing to notice is that we have a lot of subsystems (web hosts, windows services, message bus, cron jobs, etc) that logs to the database. To know where the logs come from we add the ‘LOG SOURCE’ as the name of the subsystem where the config is defined in (e.g ‘CommandsHost’ as the web host that receives commands from our application).
To get the logs into a database, you will need to create a table that matches the log entry that you have defined in the appender config. Here is the t-sql to create a table that matches the above config:

CREATE TABLE [dbo].[Logs](
    [Id] [int] IDENTITY(1,1) NOT NULL,
    [Date] [datetime] NOT NULL,
    [Thread] [varchar](255) NOT NULL,
    [Level] [varchar](50) NOT NULL,
    [Logger] [varchar](255) NOT NULL,
    [Message] [nvarchar](max) NOT NULL,
    [Exception] [nvarchar](max) NULL,
    [Source] [varchar](100) NULL,
    [HostName] [nvarchar](255) NULL
CONSTRAINT [PK_Log] PRIMARY KEY CLUSTERED 
(
    [Id] ASC
)

Xml transforms

Using xml transforms is an easy way to set up different settings for different environments. For web projects this is built into Visual Studio and MSBuild/MSDeploy, so the tooling support for this is pretty good. The only caveat is that the transformation is only run during deployment – not during the build. So if your switching between different build configs in Visual Studio, the web host on your dev machine will only use the web.config – not any of the web.debug.config, web.release.config, etc (unless you are actually deploying to your local IIS).
If you are developing a console/WPF/WebForms application you still can take advantage of the same xml transform as web projects, but the tooling is not built into Visual Studio or MSBuild/MSDeploy. There is however an excellent free tool (VS extension) called SlowCheetah developed by Sayed Ibrahim Hashimi that will do this for you. You can download it as a Visual Studio extension, and it has an extra gem that Visual Studio doesn’t have; transformation preview.

SQL Server Full-Text search

The real power when it comes to database log entries is when you pair it with full-text searching. Full-text search will require quite a bit of resources in the form of hardware (disk, memory, cpu), but you don’t have to (and shouldn’t) set up the full-text indexing on your production database server. Instead you should set up log shipping in SQL Server (or some other form of pulling the logs off your production servers) and then do your full-text indexing and searching on a separate database server.

Pair full-text search of logs with a message based (event driven) system, and you have an incredible insight to your production system and an invaluable, searchable history.

Resources

Log4Net: http://logging.apache.org/log4net/

SlowCheetah: https://visualstudiogallery.msdn.microsoft.com/69023d00-a4f9-4a34-a6cd-7e854ba318b5

Unit testing asynchronous operations with the Task Parallel Library (TPL)

Unit testing asynchronous operations has never been easy in C#. The most common methods (or at least the methods I usually end up with) is either;

1. Write a synchronous version of the method to test, unit test this one and then call the synchronous method from another method that runs it asynchronous in the production code.
2. Raise an event in the production code when the asynchronous operation has finished, subscribe to the event in the unit test, and use the ManualResetEvent to wait for the event before making any assertions.

Neither is a good solution.
Writing a synchronous version and let the production code call it is probably the easiest one, but breaks down once you need to do more than just call the synchronous method in production (e.g. orchestrating several dependent asynchronous operations, or have some logic run when the asynchronous operation(s) completes). And the worst part of it; a vital part of the production code will be untested.
The ManualResetEvent is better, but it takes a lot more code, makes the unit tests harder to read and you need to fire events in the prod code that possibly only unit tests are interested in. And unit tests dependent on ManualResetEvent tends to be fragile when run in parallel.
But with the Task Parallel Library (TPL) the table has turned; TPL makes unit testing asynchronous code a lot easier. That is; it’s easy if you now how to do it.
Running some code asynchronously without any concerns for testability is pretty straight forward with TPL:

Task.Factory.StartNew(MyLongRunningJob);

And in fact; it’s not much harder to make it test-friendly. You only need a bit insight into what’s going in the Task Factory. And to have it straight from the horse’s mouth; here’s what MSDN says about it:

Behind the scenes, tasks are queued to the ThreadPool, which has been enhanced with algorithms (like hill-climbing) that determine and adjust to the number of threads that maximizes throughput. This makes tasks relatively lightweight, and you can create many of them to enable fine-grained parallelism. To complement this, widely-known work-stealing algorithms are employed to provide load-balancing.

The Task Factory will use a Task Scheduler to queue the tasks and the default scheduler is the ThreadPoolTaskScheduler, which will run the tasks on available threads in the thread pool.

The trick when unit testing TPL code is to not have those tasks running on threads that we have no control over, but to run them on the same thread as the unit test itself. The way we do that is to replace the default scheduler with a scheduler that runs the code synchronously. Enter the CurrentThreadTaskScheduler;

public class CurrentThreadTaskScheduler : TaskScheduler
{
    protected override void QueueTask(Task task)
    {
        TryExecuteTask(task);
    }

    protected override bool TryExecuteTaskInline(
       Task task, 
       bool taskWasPreviouslyQueued)
    {
        return TryExecuteTask(task);
    }

    protected override IEnumerable<Task> GetScheduledTasks()
    {
        return Enumerable.Empty<Task>();
    }

    public override int MaximumConcurrencyLevel { get { return 1; } }
}

TaskScheduler is an abstract class that all schedulers must inherit from and it only contains 3 methods that needs to be implemented;

1. void QueueTask(Task)
2. bool TryExecuteTaskInline(Task, bool)
3. IEnumerable<Task> GetScheduledTasks()

In the more advanced schedulers like the ThreadPoolTaskScheduler, this is where the heavy-lifting of getting tasks to run on different threads in a thread-safe manner happens. But for running tasks synchronously, we really don’t need that. In fact, that’s exactly what we don’t need. So instead of scheduling tasks to run on different threads, the TryExecuteTaskInline method will just execute them immediately on the current thread.

Now it’s time to actually use it in the production code;

public TaskScheduler TaskScheduler
{
    get
    {
        return _taskScheduler
            ?? (_taskScheduler = TaskScheduler.Default);
    }
    set { _taskScheduler = value; }
}
private TaskScheduler _taskScheduler;

public Task AddAsync(int augend, int addend)
{
    return new TaskFactory(this.TaskScheduler)
        .StartNew(() => Add(augend, addend));
}

To be able to inject a different TaskScheduler from unit tests, I’ve made the dependency settable through a public property on the class I’ll be testing. If no TaskScheduler has been explicitly set (which it won’t be when executed ‘in the wild’), the default TaskScheduler will be used.

The method Task AddAsync(int, int) is the method we would like to unit test. As you can see it’s a highly CPU intensive computation that will add 2 numbers together. Just the kind of work you’d want to surround with all the ceremony and overhead of running asynchronously.

The important part here is the instantiation of the TaskFactory that will take the TaskScheduler as a constructor parameter.

With that in place we can set the TaskScheduler from the unit tests:

[Test]
public void It_should_add_numbers_async()
{
    var calc = new Calculator
    {
        TaskScheduler = new CurrentThreadTaskScheduler()
    };

    calc.AddAsync(1, 1);

    calc.GetLastSum().Should().Be(2);
}

The System Under Test, SUT, is the Calculator-class that has the AddAsync-method we’d like to unit test. Before calling the AddAsync-method we set the CurrentThreadTaskScheduler that the TaskFactory in the Calculator should use.

Since AddAsync doesn’t return the result of the calculation, I’ve added a method to get the last sum. Not exactly production-polished code, but it’ll do for the purpose of this example.

Anyway; the end result is that the test pass. And if I don’t assign the CurrentThreadTaskScheduler to Calculator.TaskScheduler – that is it runs with the default ThreadPoolTaskScheduler – it will fail, because the addition will not be finished before the assertion.

But don’t trust me on this. I’ve uploaded the complete (absurd) example to GitHub, so you can run the tests and see for yourself; https://github.com/bulldetektor/TplSpike.

References

You can read the MSDN-article that I quoted from here; http://msdn.microsoft.com/en-us/library/dd537609.aspx

I found the code for the CurrentThreadTaskScheduler in the TPL samples here; http://code.msdn.microsoft.com/windowsdesktop/Samples-for-Parallel-b4b76364. The samples contains a dozen or so TaskSchedulers, for instance;

• QueuedTaskScheduler - provides control over priorities, fairness, and the underlying threads utilized
• OrderedTaskScheduler - ensures only one task is executing at a time, and that tasks execute in the order that they were queued.
• ReprioritizableTaskScheduler - supports reprioritizing previously queued tasks
• RoundRobinTaskSchedulerQueue - participates in scheduling that support round-robin scheduling for fairness
• IOCompletionPortTaskScheduler - uses an I/O completion port for concurrency control
• IOTaskScheduler - targets the I/O ThreadPool
• LimitedConcurrencyLevelTaskScheduler - ensures a maximum concurrency level while running on top of the ThreadPool
• StaTaskScheduler - uses STA threads
• ThreadPerTaskScheduler - dedicates a thread per task
• WorkStealingTaskScheduler - a work-stealing scheduler, not much more to say about that

Auto-Wiring EventAggregator Subscription in Caliburn.Micro

 

Just wanted to make a quick note about how to get auto-wiring of the EventAggregator subscription up and running for Caliburn.Micro. What I want to accomplish is to avoid having to write this:

… and instead make this "just happen" when a type implements IHandle. And as you can see from the code above, the IoC I use here is MEF.

So I haven't used MEF before, but I found this post ("Introduction to InterceptingCatalog – Part I") by Piotr Włodek and figured that with a little bit of tweaking this should work.

This code relies on the MEFContrib project up on CodePlex/GitHub, so if you haven't already downloaded it you can get it from there or just NuGet-it into your project;

To be able to get any class that implements IHandle to list itself as a subscriber in the EventAggregator, we need to hook into the creation pipeline in MEF. And MEF hasn't any hooks that let us do this, but fortunately MEFContrib has and it's called an InterceptingCatalog.

The InterceptingCatalog takes two arguments; a ComposablePartCatalog and an InterceptionConfiguration. It's the InterceptionConfiguration that let's us provide an interceptor that can do the auto-wiring for us. But first, let's create the class that will do the interception - the EventSubscriptionsStrategy:

This object creation strategy will be added to the MEF creation pipeline. This class will be called for every object resolved from MEF, but in this case we're only interested in those who implements the IHandle interface. So if the casting succeeds we now that this is class that will want to subscribe to events. So by using the Intercept method from the IExportedValueInterceptor interface, we can tell the EventAggregator that this object is an event subscriber.

The only thing missing then, is to plug our EventSubscriptionStrategy into MEF;

This is from the default AppBootstrapper from Caliburn.Micro with the changes I made to get the EventSubscriptionStragegy registered in MEF marked in red.

References

Caliburn.Micro: http://caliburnmicro.codeplex.com/ - This is a WPF/SL/WP7 framework along the same lines as PRISM from Microsoft Patterns & Practices. Only much smaller (in size, not necessarily feature set) and much more "opinionated".

MEF Contrib: http://mefcontrib.codeplex.com/ and https://github.com/mefcontrib - Open source extensions to the Managed Extensibility Framework (MEF). In other words; extending the extensibility with extensions…

MemberAccessException

Exceptions are meant for those exceptional conditions that never should happened during your programs lifetime, but that you cannot guarantee won't happen. As you might expect from this statement, I'm not a big fan of sprinkling the code with unnecessary exception throws. I find it more useful to test those exceptional cases using unit and integration tests.

Anyway; while studying the source code from the excellent CodeProject article "NHibernate Best Practices with ASP.NET" by Billy McCafferty, I came across this quite interesting use of MemberAccessException;

public IOrderDao OrderDao
{
  get
  {
    if (orderDao == null) {
      throw new MemberAccessException("OrderDao has not yet been initialized");
    }
    return orderDao;
  }
  set { orderDao = value; }
}

If it were me coding this, I’d probably just throw the far more general ApplicationException or something (if I'd throw it all, mind my words in the intro to this post). But I definitely see that the MemberAccessException would be a lot better fit for this exceptional case.

Empty delegate makes event raising easy and thread-safe

I'm currently working on a project that will use some of the guidelines from the WPF Composite Application Guidance. And as I was studying the source code I kept seeing a strange
initialization of events that looked something like this;

public event EventHandler EmptyDelegateEvent = delegate { };

I mean; I do know my way around delegates, but these empty delegates puzzled me. After googling around a bit I found that this was a just a clever way of avoiding null reference exception when raising the event. So instead of this;

public event EventHandler CheckForNullEvent;

void RaiseEvent()
{
  // the usuall way
  if (CheckForNullEvent != null)
    CheckForNullEvent(this, new EventArgs());
}

...you can simply do this;

public event EventHandler EmptyDelegateEvent = delegate { };

void RaiseEvent()
{
   // the easy way
   EmptyDelegateEvent(this, new EventArgs());
}

When using empty delegates you can simply raise the event without checking for null. Note though, that performance wise it will be better to do the "if not null" check than a "delegate {}". But I ran some performance testing to compare the two, and the performance hit is really not that big of an issue. Even though the performance of the empty delegate was 20-30% slower than the null check, the time it takes to do either of them is miniscule. This is really not where you should put your performance tuning effort. A 'null reference exception', which is much more likely to happen if you forget to check for the null, will have a much bigger impact on the overall performance of your application. Or even worse; if a raise condition occurs. Which again reminds me that the correct way of checking the event for null and at the same time making sure it's thread-safe, is this;

void RaiseEvent()
{
   // the thread-safe way
   EventHandler copyOfEvent = CheckForNullEvent;
   if (copyOfEvent != null)
       copyOfEvent(this, new EventArgs());
}

And how many does actually do that? And talking of performance; what about 'developer performance'? Instantiating an empty delegate and no need for null checking or possible raise conditions, means faster coding and less bugs - e.g. better developer performance.