Testing Against the Real Event Log

Lots of applications write to the Windows Event Log. When TDD'ing, event logging is part of an application's Indirect Output, so to verify that logging happens correctly, you need to verify the test against an Observation Point. As always, the correct approach to this requirement is to inject some sort of event logging abstraction (such as an interface that models the event log) into your SUT, and then verify the behavior using a Test Spy or Mock Object.

In an old post, I've described how to do this with Enterprise Library. These days, I don't use Enterprise Library, but the principle stays the same, even if the specific API is a bit different.

As such, you can TDD an entire application's event logging functionality without ever touching the real log, but at some point you will need to write an implementation that writes to the real Windows Event Log. In most cases, the implementation should be so simple that you can treat it as a Humble Object, so no testing is necessary.

However, if, for some reason, you'd like to test your Windows Event Log code, you'll need to do the following:

  1. In the Fixture Setup phase of the test, get the time of the most recent event log entry, so that you can later verify that the entry you expect to be written was, in fact, written after the test executed.
  2. Exercise the SUT.
  3. Verify that the entry was written by looking through the event log entries that are more recent than the time you recorded previously.

This pretty much models how you'd perform a manual test by first looking in the Event Log using the MMC snap-in; running your code; and then finally refreshing the view in the Event Log MMC again.

Here's how it can be done using LINQ to Objects:

 public void DoStuffWillWriteEntyInTheEventLog()
     // Fixture setup
     string sourceName = "MyApp";
     EventLog el = new EventLog("Application");
     DateTime latestEntryTime = (from entry in el.Entries.Cast<EventLogEntry>()
                                 where entry.Source == sourceName
                                 orderby entry.TimeWritten descending
                                 select entry.TimeWritten).
     MyClass sut = new MyClass();
     // Exercise system
     // Verify outcome
     bool entryExists = (from entry in el.Entries.Cast<EventLogEntry>()
                         where entry.Source == sourceName
                         && entry.TimeWritten >= latestEntryTime
                         && entry.Message.Contains("ploeh")
                         select entry).Any();
     Assert.IsTrue(entryExists, "Entry was written");
     // Teardown

Following the above algorithm, I first extract the most recent entry from the event source I'm interested, and using DateTime.MinValue if none was ever written - which would be the case the first time I ever run the test on any given system.

After exercising the SUT, a new query to the event log determines whether the entry was written after latestEntryTime.

A word of caution: There are generally tens of thousands of entries in the normal Windows Event log, so these queries are almost guaranteed to lead to Slow Tests. The single test in this example takes almost 15 seconds on my laptop, so don't rely on LINQ to the Event Log as a substitute for abstracting away the Windows Event Log.

In fact, don't even include one of these tests in your normal TDD test suite, since even 15 seconds is way to long to wait when you are following the Red, Green, Refactor rythm.

Such a test belongs in a special integration test suite, and may also be a good candidate to be included in a Build Verification Test suite.