Create a logger for watching your test progress as it runs.
I was creating a project that’s a Windows Service, which has components running in multiple processes, using multiple threads and named pipes for communication.
To understand the behavior of the code, I wanted to have accurate logging that:
· The timing was very critical, so I wanted the log to show the sequence of events with a timestamp, showing the relative order of events
· The logging to take very little time to execute
· See the log update as it gets written and the code runs in VS
· The log can be called from multiple processes, one of which is running as a Service
As usual, I really love Test Driven Development, so I have several tests and test utilities that install/uninstall the Windows Service, as well as test the service code while it’s not installed as a service.
When running multiple tests, it’s very difficult to tell in VS2012 which test is currently running. VS 2010 shows it easily. So, with this logging code, just watching the log tells which test is running. Because the main project is a Windows Service, it doesn’t have any user interface: it runs in a different desktop than the user desktop and it runs in a different security context.
The logger thus needed to just add the log string to a queue, making it very fast. The logger had a worker thread that monitors the queue and updates the log. Updating can fail because VS needs to read the file to update the display, which can cause an exception. In that case, the failed log update is retried.
Turn these 2 options on:
Tools->Options->Documents-> Detect when file is changed outside the environment
Auto-Load changes, if saved
Start VS 2012
File->New->Project->C# Unit Test Project
Paste in the code below to replace UnitTest1.cs contents.
Run the code by building, then choosing Run All in the Test Explorer (Test->Windows->Test Explorer)
The test creates multiple threads, each doing some fake work, and writing to the log.
The logger merely logs the log entry to a queue, which is drained on a private thread.
Open the generated log file (named like C:\Users\calvinh\Desktop\Log.txt)
I like to have the log file docked to the right of my main code window, so I can see both the log and the code at the same time.
A portion of the log file looks like this:
<code>
using System;
using System.Collections.Generic;
using System.Threading;
using System.Linq;
using Microsoft.VisualStudio.TestTools.UnitTesting;
using System.IO;
using System.Diagnostics;
namespace UnitTestProject1
{
/// <summary>
/// Outputs log text with timestamp to a file. Other applications (like VS) can have the file open to show the contents
/// as items are added to the log.
/// Useful to show log progress as tests are running
/// Adds log entries to a queue to minimize perf: queue is drained on a worker thread that
/// actually writes to the file
/// </summary>
public class Logger
{
internal static string _LogFileName;
public static string LogFileName
{
get
{
if (string.IsNullOrEmpty(_LogFileName))
{// C:\Users\calvinh\Desktop\Log.txt
//* // choose one or the other:
// if running as a service, the specialfolder will be
// different from the current user
_LogFileName = Path.Combine(
Environment.GetFolderPath(Environment.SpecialFolder.Desktop),
"Log.txt"
);
/*/
_LogFileName = @"C:\Users\calvinh\Desktop\Log.txt";
//*/
}
return _LogFileName;
}
}
/// <summary>
/// # of msecs the log queue background thread checks the queue
/// </summary>
public static int LogQueueCheckPeriod = 100;
/// <summary>
/// Change this to turn on/off logging
/// </summary>
public static LogVerbosity DefaultLogVerbosity = LogVerbosity.LogVerbosityDetailed;
/// <summary>
///
/// </summary>
public enum LogVerbosity
{
/// <summary>
/// No logging
/// </summary>
LogVerbosityNone,
LogVerbosityCSV,
LogVerbosityDetailed,
LogVerbosityDiagnostic
}
internal static bool _fStopLogging;
internal static Queue<string> _msgQueue = new Queue<string>();
private static DateTime _dtStart;
private static ManualResetEventSlim _evLogThreadDone;
internal static Logger __Logger; //singleton
internal static Logger _Logger
{
get
{
lock (_msgQueue)
{
if (__Logger == null)
{
__Logger = new Logger();
}
}
return __Logger;
}
set
{
__Logger = value;
}
}
internal protected Logger() // ctor: nobody else can create one
{
try
{
_dtStart = DateTime.Now;
_fStopLogging = false;
_evLogThreadDone = new ManualResetEventSlim();
ThreadPool.QueueUserWorkItem(O =>
{
var lst = new List<string>();
while (!_fStopLogging || _msgQueue.Count > 0)
{
lock (_msgQueue) //hold lock as short as possible
{
if (_msgQueue.Count > 0)
{
// copy to list fast
lst = _msgQueue.ToList();
_msgQueue.Clear();
}
}
foreach (var str in lst)
{
LogStringToFile(str);
}
lst.Clear();
Thread.Sleep(LogQueueCheckPeriod);
}
_evLogThreadDone.Set(); // signify done
});
LogString(LogVerbosity.LogVerbosityDetailed, "LogInit PID={0} {1} {2} {3}",
Process.GetCurrentProcess().Id,
Path.GetFileName(Process.GetCurrentProcess().MainModule.FileName),
(new StackTrace()).GetFrames()[0].GetMethod().Name,
Process.GetCurrentProcess().MainModule.FileName
);
}
catch (Exception ex)
{
Debug.Fail("logging init failed {0}", ex.ToString());
}
}
/// <summary>
/// Log a string to the logger (a file or trace listener)
/// </summary>
public static void LogString(string msg, params object[] args)
{
_Logger.LogStringPrivate(msg, args);
}
/// <summary>
/// Log a string to the logger (a file or trace listener)
/// </summary>
private void LogStringPrivate(string msg, params object[] args)
{
LogString(DefaultLogVerbosity, msg, args);
}
/// <summary>
/// Empty contents, but don't delete file
/// </summary>
public static void CleanLog()
{
_Logger = null; // next access will initialize logger
for (int i = 0; i < 10; i++)
{
try
{// init log to nothing
File.WriteAllText(Logger.LogFileName, string.Empty);
break;
}
catch (IOException)
{
Thread.Sleep(100);// VS is showing the file, retry
}
catch (Exception)
{
throw;
}
}
}
public void LogString(
LogVerbosity verbosity,
string msg,
params object[] args)
{
if (verbosity == LogVerbosity.LogVerbosityNone)
{
return;
}
var strMsg = msg;
if (args != null)
{
strMsg = string.Format(strMsg, args);
}
lock (_msgQueue)
{
var deltastr = string.Empty;
var dtNow = DateTime.Now;
if (_dtStart != null)
{
deltastr = string.Format(@"{0:mm\:ss\.fff}",
(dtNow - _dtStart)); //"49:12.842"
}
var strtolog = string.Empty;
strtolog = string.Format(@"[{0:hh\:mm\:ss\.fff t}], {1}, {2}" + "\r\n",
dtNow,
deltastr,
strMsg);
Trace.WriteLine(strtolog);
//*
_msgQueue.Enqueue(strtolog);
/*/
LogStringToFile(strtolog);
//*/
}
}
internal static void StopLogging()
{
LogString("Log shutting down PID = {0}",
Process.GetCurrentProcess().Id);
_fStopLogging = true;
_evLogThreadDone.Wait();
}
internal static void LogStringToFile(string strMsg)
{
try
{
File.AppendAllText(LogFileName, strMsg); // add to end of log.
}
catch (IOException)
{ //System.IO.IOException:
//The process cannot access the file 'C:\log.txt' because it is being used by another process.
// this can happen if VS is showing log too
System.Threading.Thread.Sleep(100);
LogStringToFile(strMsg); // retry recursively
// Debug.Fail("IO exception while logging " + ex.ToString());
}
catch (Exception ex)
{
// log can't throw
{
Debug.Fail("exception while logging " + ex.ToString());
}
}
}
}
[TestClass]
public class UnitTest1
{
public TestContext TestContext { get; set; } // this is set by test infrastructure
[TestInitialize]
public void TestInit()
{
Logger.CleanLog();
Logger.LogString("Starting test {0}", TestContext.TestName);
}
[TestCleanup]
public void TestCleanup()
{
Logger.StopLogging();
}
[TestMethod]
public void TestMethod1()
{
int nInstances = 30;
// create an event that the main thread can wait on
// when all instances are done.
var evDone = new ManualResetEventSlim();
for (int i = 0; i < nInstances; i++)
{
Logger.LogString("Starting inst={0,3}", i);
ThreadPool.QueueUserWorkItem(o => // o will be the iteration number
{
Logger.LogString("Start of work inst={0,3} {1,3}",
(int)o,
Thread.CurrentThread.ManagedThreadId
);
for (int j = 0; j < 30; j++)
{
Logger.LogString("In User Code inst={0,3} {1,3} {2,3}",
(int)o,
Thread.CurrentThread.ManagedThreadId,
j);
Thread.Sleep(10); // make the work take some time
}
if (Interlocked.Decrement(ref nInstances) == 0)
{
Logger.LogString("setting evDone");
evDone.Set(); // signal main thread
}
Logger.LogString("End of work inst={0,3} {1,3}",
(int)o,
Thread.CurrentThread.ManagedThreadId
);
},
i // pass in the iteration #
);
}
evDone.Wait();// wait for signal
Logger.LogString("evDone done");
}
}
}
</code>