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:

 [TestMethod]

 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).

                                 DefaultIfEmpty(DateTime.MinValue).First();

     MyClass sut = new MyClass();

     // Exercise system

     sut.DoStuff();

     // 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.

Comments

• Anonymous
  October 07, 2008
  The comment has been removed

• Anonymous
  October 07, 2008
  Hi Alois Thank you for your comments - I agree :) If you can have an exclusive Event Log for your application, things become a lot simpler. From a technological viewpoint, this is always possible, but you may have a Product Owner that insists that entries go into the normal Application Event Log. In that case, things become a whole lot more complicated, as you can't even assume that the topmost entry is your entry. If you assume that EventLog.Entries are guaranteed to be ordered with the most recent entries first, then I agree that can you look up a new entry much faster. However, although this appears to be the case, I couldn't find any place in the documentation stating this. You could obviously choose to be pragmatic about it and just assume that the ordering is guaranteed, but on the other hand, I like the declarative style of LINQ, since it better communicates what's going on. In this case, communicative code is more important to me than speed, since I'd never run a test like the above in my normal test suite anyway. It belongs strictly in a suite of integration tests.

• Anonymous
  October 07, 2008
  The strict ordering is indeed not guaranteed. But that does only play a role when multi process logging is involved. Actually there event log entry has two time stamps TimeGenerated and TimeWritten which indicates that there can be a time gap. Basically the event log record must be sent to the windows event log service which will write the record at some later time. I guess it has some per process queues to make things fast so it can happen that you see logs not in a strictly timely manner. But for such simple scenarios it is surely enough. A linked LINQ query could do the job quite nicely like this:        EventLog el = new EventLog("Application");            var FirstElements = (from EventLogEntry e in el.Entries                                where e != null                                select e).Take(10);            foreach (var entry in FirstElements)            {                Console.WriteLine("{0} Message: {1}", entry.TimeGenerated, entry.Message);            } That uses LINQ and is performant at the same time. Yours,  Alois Kraus

• Anonymous
  October 08, 2008
  What I meant about the ordering applies even in the single-threaded scenario: Since ordering is not guaranteed, you can't be certain that the ten first entries in the collection are the ten most recent. If the ordering was different, it might instead be the ten oldest, or the ten with the lowest EventID or whatever. In fact, it looks a lot like the first entries in the collection are the oldest entries (even though this is not documented). So the LINQ query you posted will return the ten oldest entries in the Event Log. While it certainly is fast, it doesn't achieve the desired result.

• Anonymous
  October 08, 2008
  Yes last snippet contains an error. The newest events are at the end. Reflector shows that: internal EventLogEntry GetEntryAtNoThrow(int index) { ...    index += this.OldestEntryNumber;    return this.GetEntryWithOldest(index); } Index 0 returns the oldest event log entry. To make LINQ work with this you need to iterate the Entries collection in reverse.   static class Extensions    {        public static IEnumerable<T> ReverseSequence<T>(this T[] array)        {            for (int i = array.Length-1; i >= 0; i--)            {                yield return array[i];            }        }        public static IEnumerable<T> ReverseSequence<T>(this IList<T> array)        {            for (int i = array.Count - 1; i >= 0; i--)            {                yield return array[i];            }        }        public static IEnumerable<EventLogEntry> ReverseSequence(this EventLogEntryCollection array)        {            for (int i = array.Count - 1; i >= 0; i--)            {                yield return array[i];            }        }    } With that helper methods you can now do it properly: // Read the 10 latest event log entries          var FirstElements = (from EventLogEntry e in el.Entries.ReverseSequence()                                where e != null                                select e).Take(10); LINQ does contain an extension method called Reverse but it can operate only on an IEnumerable. Which in effect means that LINQ does read all entries into an array and then iterates the array in reverse. That is slow and violates the core principle of LINQ to delay execution until it is necessary. I wonder why the methods above are not part of .NET Framework 3.5. Yours,  Alois Kraus

• Anonymous
  October 09, 2008
  Hi Alois You are right, those extension methods really ought to be in the BCL :) If I remove the single ordering clause in my example and replace the calls to Cast<T> with calls to ReverseSequence, the test becomes very fast. It still assumes that EventLog.Entries are always ordered by time ascending, but given the gain, I could choose to be pragmatic about that :) Thanks for the tip!