Introduction
One of the shortcomings of the test results reporting of NUnit is the absence an absolute start and end time timestamp for each individual test execution. That makes it especially difficult to correlate failing tests with events in the test infrastructure.
Figure 1: NUnit test results with start and end time timestamp for each individual test
Luckily there is an easy way to hook into the NUnit test runner events using a custom Event Listener Addin. This blog post provides the Visual Studio 2010 project and some additional information about my NUnitTestLogger Addin.
Reference links
Some information about the NUnit Event Listener hooks that I used for this Addin can be found in the NUnit documentation. A more detailed overview is provided by a blog post that describes the capabilities of the NUnit Addin framework.
File format
I decided to write the additional test timestamp information into CSV files. Each test assembly would get its own file using the following file name format:
[Test assembly build version]_[Test assembly name]_[Test start time]_[Test computer name]_[Number of tests in test assembly].csv
The following example file name shows the application of this format definition:
0.1.0.28281_BlogShellTx.UnitTests.dll_20110819234257_LABSTATUS_24.csv
Figure 2: CSV file name format
Addin implementation
The following screenshot shows the kind of information the NUnit Event Listener provides.
Figure 3: Event Listener hooks capabilities
Implementing the hooks is fairly easy. The following two cs files demonstrate how I did it :
TestRecord.cs
using System;
using System.Collections.Generic;
using System.Text;
using System.IO;
using System.Reflection;
namespace NUnitTestLogger
{
class TestRecord
{
public string FullName { get; set; }
public int ResultState { get; set; }
public DateTime StartTime { get; set; }
public DateTime EndTime { get; set; }
public string AssemblyName { get; set; }
public string ComputerName { get; set; }
public string BuildVersionNumber { get; set; }
public DateTime RunDateTime { get; set; }
public int Count { get; set; }
public double Time { get; set; }
public override string ToString()
{
StringBuilder sb = new StringBuilder();
sb.Append(FullName);
sb.Append(",");
sb.Append(StartTime.ToString("yyyy-MM-dd HH:mm:ss.fff"));
sb.Append(",");
sb.Append(EndTime.ToString("yyyy-MM-dd HH:mm:ss.fff"));
sb.Append(",");
sb.Append(Time.ToString());
sb.Append(",");
sb.Append(ResultState.ToString());
return sb.ToString();
}
public string GetContainerName()
{
StringBuilder sb = new StringBuilder();
sb.Append(BuildVersionNumber);
sb.Append("_");
sb.Append(AssemblyName);
sb.Append("_");
sb.Append(RunDateTime.ToString("yyyyMMddHHmmss"));
sb.Append("_");
sb.Append(ComputerName);
sb.Append("_");
sb.Append(Count);
return sb.ToString();
}
internal void StartRun(string name, int testCount)
{
RunDateTime = DateTime.UtcNow;
Count = testCount;
AssemblyName = GetAssemblyNameFromPath(name);
BuildVersionNumber = GetAssemblyVersionFromPath(name);
ComputerName = Environment.MachineName;
}
private string GetAssemblyVersionFromPath(string name)
{
var assemblies = AppDomain.CurrentDomain.GetAssemblies();
string assemblyNameFromPath = GetAssemblyNameFromPath(name);
foreach( Assembly a in assemblies)
{
string testAssemblyName = (a.GetName()).Name + ".dll";
if (String.Compare(testAssemblyName, assemblyNameFromPath, true) == 0)
{
return a.GetName().Version.ToString();
}
}
return "0.0.0000.0";
}
private string GetAssemblyNameFromPath(string name)
{
if (!String.IsNullOrEmpty(name))
{
FileInfo fi = new FileInfo(name);
return fi.Name;
}
else
{
return "unknown";
}
}
internal string GetHeader()
{
StringBuilder sb = new StringBuilder();
sb.Append("FullName");
sb.Append(",");
sb.Append("StartTime");
sb.Append(",");
sb.Append("EndTime");
sb.Append(",");
sb.Append("Duration");
sb.Append(",");
sb.Append("ResultState");
return sb.ToString();
}
internal void StartTest(NUnit.Core.TestName testName)
{
StartTime = DateTime.UtcNow;
FullName = testName.FullName;
}
internal void CompleteTest(NUnit.Core.TestResult result)
{
EndTime = DateTime.UtcNow;
Time = result.Time;
if (result.Executed)
{
if (result.IsSuccess)
{
ResultState = 0; //Successfull assertions
}
if (result.IsFailure)
{
ResultState = 1; //Failed assertion
}
if (result.IsError)
{
ResultState = 2; //Error
}
}
else
{
ResultState = -1; //Not run
}
}
internal void CompleteTestWith(Exception exception)
{
EndTime = DateTime.UtcNow;
Time = 0;
ResultState = 2; //Error
}
}
}
EventTracer.cs
using System;
using NUnit.Core.Extensibility;
using NUnit.Core;
using NUnit.Framework;
using System.Diagnostics;
using System.IO;
using System.Text;
using System.Collections.Generic;
namespace NUnitTestLogger
{
[NUnitAddin(Description = "Event Timestamp Logger")]
public class EventTimestampLogger : IAddin, EventListener
{
public bool Install(IExtensionHost host)
{
if (host == null)
throw new ArgumentNullException("host");
IExtensionPoint listeners = host.GetExtensionPoint("EventListeners");
if (listeners == null)
return false;
listeners.Install(this);
return true;
}
TestRecord testRecord = new TestRecord();
StringBuilder sb = new StringBuilder();
#region EventListener Members
public void RunStarted(string name, int testCount)
{
testRecord.StartRun(name, testCount);
string logFileName = GetLogFileName(testRecord);
LogHeader(logFileName, testRecord);
}
public void RunFinished(TestResult result)
{
return;
}
public void SuiteStarted(TestName testName)
{
return;
}
public void TestStarted(TestName testName)
{
testRecord.StartTest(testName);
}
public void TestFinished(TestResult result)
{
testRecord.CompleteTest(result);
string logFileName = GetLogFileName(testRecord);
LogResult(logFileName, testRecord);
}
public void SuiteFinished(TestResult result)
{
return;
}
public void RunFinished(Exception exception)
{
testRecord.CompleteTestWith(exception);
string logFileName = GetLogFileName(testRecord);
LogResult(logFileName, testRecord);
}
private string GetLogFileName(TestRecord testRecord)
{
if (testRecord != null)
{
string fileName = testRecord.GetContainerName() + ".csv";
string filePath = Environment.GetFolderPath(Environment.SpecialFolder.MyDocuments) + "\\" + fileName;
return filePath;
}
else
{
return "testresultlog.csv";
}
}
public void TestOutput(TestOutput testOutput)
{
return;
}
public void UnhandledException(Exception exception)
{
Debug.Write("UnhandledException " + exception);
}
private void LogHeader(string logFileName, TestRecord testRecord)
{
string message = testRecord.GetHeader();
LogMessage(logFileName, message);
}
private void LogResult(string logFileName, TestRecord testRecord)
{
string message = testRecord.ToString();
LogMessage(logFileName, message);
}
private void LogMessage(string logFileName, string message)
{
using (StreamWriter sw = File.AppendText(logFileName))
{
sw.WriteLine(message);
}
}
#endregion
}
}
Installation
The Addin assemblies need to be copied into a folder called “addins”, which is a subfolder of the directory where the test runners like for example nunit.exe are located.
Figure 4: Addin assemblies location
NUnit will pick up and load the Addin assemblies automatically. The Registered Addins dialog shows which Addins have been loaded. For my assembly to load successfully in NUnit 2.5 it needed to be build for the x64 processor architecture using the .NET Framework 2.0 binding.
Figure 5: NUnit is loading Addins automatically
Download
The Visual Studio 2010 project with the built Addin assembly and an example test result CSV file can be downloaded here: NUnitTestLogger.zip
Ausblick
By the way, have you ever tried to specify a date time format in Excel that displays milliseconds? Here is how you can do it. Select the Custom Category in Format Cells and use the following format specifier: m/d/yyyy h:mm:ss.000
Figure 6: Excel custom format for displaying milliseconds in a date time field
Subscribe
