nLog - Updating ExceptionLayoutRenderer to capture “Exception.Data”

Something that appears to be missing from many logging frameworks is the ability to log/report the “data” collection of any thrown exceptions. I originally encountered this issue with log4net, and have recently found nLog appears to be lacking the same desired functionality. As our current project looks like it will be switching to using nLog I’ve had a dig around in the source code to see how easily this functionality can be added.

Basically for a quick and dirty solution the desired functionality can be added by adding the following function to the class “ExceptionLayoutRenderer”:

private static void AppendData(StringBuilder sb, Exception ex)

{

var separator = string.Empty;

foreach (var key in ex.Data.Keys)

{

sb.Append(separator);

sb.AppendFormat("{0}: {1}", key, ex.Data[key]);

separator = " ";

}

}

And the referencing this new function inside the “switch” statement of “CompileFormat”:

case "DATA":

dataTargets.Add(AppendData);

break;

Finally to use this new functionality, in the configuration section add “data” to the ${exception:format=} comma delimited list any where you want to report on exception data. Right now the formatting is pretty basic, I want to play some more to see what options are available to improve the rendering options whilst adhering to the existing nLog configuration model. It may be easier to add a custom LayoutRenderer just for exception data that can be held outside of the nLog DLL, removing the requirement to reference a custom build of the DLL (which probably breaks NuGet package deployments, etc).

SQL Agent Immediately Stops

We just run into an interesting problem where starting the SQL Server Agent would start and then immediately stop. No errors were reported in the event log, but running the following via the command line returned "StartServiceCtrlDispatcher failed (error 6)"

"[[your SQL Path]]\Binn\SQLAGENT.EXE" -i [[sql Instance]]

Googling the error in question returned this forum post which contained the solution. We had reinstalled the service and the account that we were running under did not have the permissions to update / overwrite something (it wasn't the error file in question). Running the agent under a different account solved the issue; would be good to look into what the exact problem we are encountering is, but it's enough that it's running for us right now.

Exceptions inside IComparer.Compare(x, y)

When writing or using an implementation of IComparer.Compare(x,y) you encounter the following error message:

Unable to sort because the IComparer.Compare() method returns inconsistent results. Either a value does not compare equal to itself, or one value repeatedly compared to another value yields different results

It is highly likely that the code within the "Compare" statement is throwing an exception. We encountered this problem when trying to access an array out of bounds in a particular scenario. Updating our tests and our code to return a correct result in this scenario fixed the issue for us.

Unit Test Code Coverage

It seems that a common aim when first starting out in unit testing is to obtain 100% code coverage with our unit tests.  This single metric is the defining goal and once obtained a new piece of functionality is targeted.  After all if you have 100% code coverage you can’t get better than that, can you?

It’s probably fair to say that it’s taken me several years and a few failed attempts at test driven development (TDD) to finally understand why when production code fails it can still occur in code that is “100%” covered by tests!  At it’s most fundamental level this insight comes from realising that “100% code coverage” is not the aim of well tested code, but a by-product!

Consider a basic object “ExamResult” that is constructed with a single percentage value.  The object has a read only property returning the percentage and a read only bool value indicating a pass/fail status.  The code for this basic object is shown below:

namespace CodeCoverageExample

{

using System;

public class ExamResult

{

private const decimal PASSMARK = 75;

public ExamResult(decimal score)

{

if (score < 0 || score > 100)

{

throw new ArgumentOutOfRangeException("score", score, "'Score' must be between 0 and 100 (inclusive)");

}

this.Score = score;

this.Passed = DetermineIfPassed(score);

}

public decimal Score { get; private set; }

public bool Passed { get; private set; }

private static bool DetermineIfPassed(decimal score)

{

return (score >= PASSMARK);

}

}

}

For the code above, the following tests would obtain the magic“100% code coverage” figure:

namespace CodeCoverageExample

{

using System;

using Microsoft.VisualStudio.TestTools.UnitTesting;

using NUnit.Framework;

using Assert = NUnit.Framework.Assert;

[TestClass]

public class PoorCodeCoverage

{

[TestMethod]

public void ExamResult_BadArgumentException()

{

var ex = Assert.Throws<ArgumentOutOfRangeException>(() => new ExamResult(-1));
Assert.That(ex.ParamName, Is.EqualTo("score"));

}

[TestMethod]

public void ExamResult_DeterminePassed()

{

Assert.IsTrue(new ExamResult(79).Passed);

}

[TestMethod]

public void ExamResult_DetermineFailed()

{

Assert.IsFalse(new ExamResult(0).Passed);

}

}

}

Note: The testing examples in these blog posts use both MSTest and NUnit.  By decorating the class with MSTest attributes you will get automated test running in TFS continuous integration “out of the box”.  Aliasing “ASSERT” to the NUnit version allows access to NUnit version of this command (which I was originally more familiar with and still prefer).

Running any code coverage tool will clearly show all the paths are being tested but are you really protected against modifications introducing unintended logic changes?  This can be checked by running through a few potential situations:  Changing the pass mark to 80% would cause the above unit tests to fail, but reducing it to 1% wouldn’t.  If you consider the main purpose of the unit test is to verify that the exam result is correctly determined (and the potential consequences in the “real world” if it is not) then it would imply that this sort of check is not fit for purpose.  In the scenario it is critical that edge cases are tested – these are the points in which a result passes from being a failure to a pass and similarly from being a valid result to invalid (you can’t score less than 0% or more than 100%).  Similarly short cuts should not be taken in asserting the state of the object under test in each individual test - don’t assume because the “Result” property was correctly set in one test it will be correct in another (and therefore not tested).  The following improved unit tests verifies the desired behaviour of the object in full and in the process of this verification covers 100% of the code.  It is this change in priority that is critical when designing and developing your unit tests.  Only when all the logic paths through your code are tested are your unit tests complete and at this point you should by default have 100% code coverage.

namespace CodeCoverageExample

{

using System;

using Microsoft.VisualStudio.TestTools.UnitTesting;

using NUnit.Framework;

using Assert = NUnit.Framework.Assert;

[TestClass]

class GoodCodeCoverage

{

private const decimal LOWEST_VALID_SCORE = 0;

private constdecimal HIGHEST_VALID_SCORE = 100;

private const decimal PASSMARK = 80;

[TestMethod]

public void ExamResult_BadArgumentException_UpperLimit()

{

var ex = Assert.Throws<ArgumentOutOfRangeException>(() => new ExamResult(HIGHEST_VALID_SCORE + 1));

Assert.That(ex.ParamName, Is.EqualTo("score"));

}

[TestMethod]

public void ExamResult_BadArgumentException_LowerLimit()

{

var ex = Assert.Throws<ArgumentOutOfRangeException>(() => new ExamResult(LOWEST_VALID_SCORE - 1));

Assert.That(ex.ParamName, Is.EqualTo("score"));

}

[TestMethod]

public void ExamResult_DeterminePassed_HigherLimit()

{

AssertCall(HIGHEST_VALID_SCORE, true);

}

[TestMethod]

public void ExamResult_DeterminePassed_LowerLimit()

{

AssertCall(PASSMARK, true);

}

[TestMethod]

public void ExamResult_DetermineFailed_HigherLimit()

{

AssertCall(PASSMARK - 1, false);

}

[TestMethod]

public void ExamResult_DetermineFailed_LowerLimit()

{

AssertCall(LOWEST_VALID_SCORE, false);

}

private void AssertCall(decimal score, bool result)

{

var examResult = new ExamResult(score);

Assert.That(examResult.Score, Is.EqualTo(score));

Assert.That(examResult.Passed, Is.EqualTo(result));

}

}

}

Additional Comment: Whilst working through these examples I considered exposing the “pass-mark” constant held in the “ExamResult” object so it could be used within our unit test.  In certain situations that could be acceptable (or even desirable).  However unless there is a requirement it is probably better to keep the two separate as this requires that the unit test explicitly defines the pass / fail point that it is testing.

Improving “Boiler Plate” Data-Reader Code – Part 2

In Part 1 of this series we started with a basic Data-Reader / SQL Connection/Command pattern and illustrated how it is possible to abstract the parsing of the Data Reader into a standalone object that can be fully unit tested in isolation of the calling code.   In Part two of the series we will highlight a very simple optimisation that can be made to the “DataReader” convertor and the required update to the tests to capture/verify the changes.  In this revision the original “CustomerDRConvertor” has been updated to include extremely basic caching, which for the duration of the object’s existence should ensure that only the first call needs to reference the “GetOrdinal(…)” method to find the element index of each desired column.  Subsequent calls can then use this “cached” index to reference the column by position rather than name.

namespace DataAccess.Example

{

using System.Data;

using System.Data.BoilerPlater;

public class CustomerDRConvertorPart2 : IConvertDataReader<Customer>

{

private int idIndex = -1;

private int firstNameIndex = -1;

private int surnameIndex = -1;

public Customer Parse(IDataReader dataReader)

{

if (idIndex == -1)

{

idIndex = dataReader.GetOrdinal("Id");

firstNameIndex = dataReader.GetOrdinal("FirstName");

surnameIndex = dataReader.GetOrdinal("Surname");

}

return new Customer

{

Id = dataReader.GetGuid(idIndex),

FirstName = dataReader.GetString(firstNameIndex),

Surname = dataReader.GetString(surnameIndex)

};

}

}

}

In traditional ASP applications (back in the day) the above caching pattern used to result in reasonable performance gains.   I’ve not looked into the benefits within a modern day .NET application and in some instances could be classed as premature optimisation.  But for the purpose of this example it provides a perfect illustration as to how the abstracting the data reader parsing from the connection/command code can provide many benefits.  Updated objects can be developed and tested in complete isolation of the existing code and then plugged into the code base with only minimal changes.

This updated code can be verified using the unit test below.  In the test the “Parse(…)” method is called once and the mocked objects are verified that they were called correctly.  The “Parse(…)” method is then called again and the mocked objects verified to make sure that the second call only resulted in an additional call to the GetGuid(…) and GetString(…) methods.  Due to the very basic caching that was implemented there is no need for the second call to make any GetOrdinal(…) references, which the verification of the mocked objects can confirm.  The tests verify the expected behaviour, not the inner workings of any implementation of a DataReader object.

namespace DataAccess.Example.Tests

{

using System;

using System.Data;

using Microsoft.VisualStudio.TestTools.UnitTesting;

using NUnit.Framework;

using Moq;

using Assert = NUnit.Framework.Assert;

[TestClass]

public class CustomerDRConvertorPart2Tests

{

[TestMethod]

public void CustomerDRConvertor_GoodCall()

{

var dataReader = new Mock<IDataReader>();

dataReader.Setup(dr=>dr.GetOrdinal("Id")).Returns(1);

dataReader.Setup(dr=>dr.GetOrdinal("FirstName")).Returns(2);

dataReader.Setup(dr=>dr.GetOrdinal("Surname")).Returns(3);

var id = Guid.NewGuid();

const string firstName = "John";

const string surname = "Doe";

dataReader.Setup(dr=>dr.GetGuid(1)).Returns(id);

dataReader.Setup(dr=>dr.GetString(2)).Returns(firstName);

dataReader.Setup(dr=>dr.GetString(3)).Returns(surname);

var convertor = new CustomerDRConvertorPart2();

var customer = convertor.Parse(dataReader.Object);

Assert.That(customer.Id, Is.EqualTo(id));

Assert.That(customer.FirstName, Is.EqualTo(firstName));

Assert.That(customer.Surname, Is.EqualTo(surname));

dataReader.Verify(dr=>dr.GetOrdinal(It.IsAny<string>()), Times.Exactly(3));

dataReader.Verify(dr=>dr.GetOrdinal("Id"), Times.Once());

dataReader.Verify(dr=>dr.GetOrdinal("FirstName"), Times.Once());

dataReader.Verify(dr=>dr.GetOrdinal("Surname"), Times.Once());

dataReader.Verify(dr=>dr.GetGuid(It.IsAny<int>()), Times.Once());

dataReader.Verify(dr=>dr.GetGuid(1), Times.Once());

dataReader.Verify(dr=>dr.GetString(It.IsAny<int>()), Times.Exactly(3));

dataReader.Verify(dr=>dr.GetString(2), Times.Once());

dataReader.Verify(dr=>dr.GetString(3), Times.Once());

convertor.Parse(dataReader.Object);

dataReader.Verify(dr=>dr.GetOrdinal(It.IsAny<string>()), Times.Exactly(3));

dataReader.Verify(dr=>dr.GetOrdinal("Id"), Times.Once());

dataReader.Verify(dr=>dr.GetOrdinal("FirstName"), Times.Once());

dataReader.Verify(dr=>dr.GetOrdinal("Surname"), Times.Once());

dataReader.Verify(dr=>dr.GetGuid(It.IsAny<int>()), Times.Exactly(2));

dataReader.Verify(dr=>dr.GetGuid(1), Times.Exactly(2));

dataReader.Verify(dr=>dr.GetString(It.IsAny<int>()), Times.Exactly(4));

dataReader.Verify(dr=>dr.GetString(2), Times.Exactly(2));

dataReader.Verify(dr=>dr.GetString(3), Times.Exactly(2));

}

}

}

In part three of this series I will cover how the above code can be moved into an abstract base class for data access that all inheriting classes can utilise through interfaces and generics.

Improving “Boiler Plate” Data-Reader Code – Part 1

Recently we’ve been looking at improving our unit test code coverage and reducing the amount of duplicated code around our bespoke data access layer.  Where possible we have moved over to NHibernate but certain parts of the data access must still be written using the standard ADO.NET connection/command pattern.  Typically hidden right in the middle of this bespoke code is a while loop that is pivoting a data reader into a POCO that is impossible to repeat-ably unit test in a stable environment unless you set up a dedicated data repository for testing or try to wrap up / mock the connection / command objects.   Neither of these options are really desirable as we aren’t really interested in testing / mocking the .NET provider data access objects.

To get around this issue we looked into how we could generate some boiler-plate code that we could roll out across our code base.  This code base will be introduced step by step during this series with the first step covering the abstraction of the data reader processing into a standalone object that can be tested in isolation of the data access code.   The example code that we are looking to migrate is shown below, a typical unrestricted “Get()” call (in this example we don’t have many customers!).

public IEnumerable<Customer> Get()

{

using(var connection = new SqlConnection(this.config.ConnectionString))

{

using(var command = connection.CreateCommand())

{

command.CommandText = "SELECT id, Firstname, Surname FROM Customer";

connection.Open();

using (var dataReader = command.ExecuteReader())

{

while(dataReader.Read())

{

yield return new Customer

{

Id = dataReader.GetGuid(dataReader.GetOrdinal("Id")),

FirstName = dataReader.GetString(dataReader.GetOrdinal("FirstName")),

Surname = dataReader.GetString(dataReader.GetOrdinal("Surname"))

};

}

}

}

}

}

Hidden below (and behind) a concrete implementation of a SqlConnection and and SqlCommand is the code that we are interested in right now:

yield return new Customer

{

Id = dataReader.GetGuid(dataReader.GetOrdinal("Id")),

FirstName = dataReader.GetString(dataReader.GetOrdinal("FirstName")),

Surname = dataReader.GetString(dataReader.GetOrdinal("Surname"))

};

As previously stated, unless we set up a test repository or find a way to wrap / mock these concrete instances we are unable to test the creation from the data reader of the customer POCO. To rectify this we start with an interface defining how we would like the calling code to convert the passed in data reader:

namespace System.Data.BoilerPlate

{

public interface IConvertDataReader<out T>

{

T Parse(IDataReader dataReader);

}

}

Taking a very basic customer POCO object:

namespace DataAccess.Example

{

using System;

public class Customer

{

public Guid Id { get; set; }

public string FirstName { get; set; }

public string Surname { get; set; }

}

}

An implementation of the IConvertDataReader interface can be created quite simply using the code below.  The validation / error checking around each data reader value conversion could be as simple or as complex as you need. Part two of this series will cover a basic optimisation that can be made to this code to potentially speed up access in repeated calls such as a “while(dataReader.Read())” loop.

namespace DataAccess.Example

{

using System.Data;

using System.Data.BoilerPlate;

public class CustomerDRConvertor : IConvertDataReader<Customer>

{

public Customer Parse(IDataReader dataReader)

{

return new Customer

{

Id = dataReader.GetGuid(dataReader.GetOrdinal("Id")),

FirstName = dataReader.GetString(dataReader.GetOrdinal("FirstName")),

Surname = dataReader.GetString(dataReader.GetOrdinal("Surname"))

};

}

}

}

This data reader convertor can now be unit tested in isolation of the code that will be implementing it, using a combination NUnit and Mock to both assert actual returned results and verify expected behaviour. It’s probably worth highlighting at this stage we are using a combination of MsTest and NUnit, doing things this way brings the best of both worlds – in TFS you get automated Unit Testing as part of the CI build as you are referencing MsTest, but by adding an alias to NUnit’s assert you are getting access to NUnit’s fluent API (which we prefer).

namespace DataAccess.Example.Tests

{

using System;

using System.Data;

using Microsoft.VisualStudio.TestTools.UnitTesting;

using NUnit.Framework;

using Moq;

using Assert = NUnit.Framework.Assert;

[TestClass]

public class CustomerDRConvertorTests

{

[TestMethod]

public void CustomerDRConvertor_GoodCall()

{

var dataReader = new Mock<>IDataReader>();

dataReader.Setup(dr => dr.GetOrdinal("Id")).Returns(1);

dataReader.Setup(dr => dr.GetOrdinal("FirstName")).Returns(2);

dataReader.Setup(dr => dr.GetOrdinal("Surname")).Returns(3);

var id = Guid.NewGuid();

const string firstName = "John";

const string surname = "Doe";

dataReader.Setup(dr => dr.GetGuid(1)).Returns(id);

dataReader.Setup(dr => dr.GetString(2)).Returns(firstName);

dataReader.Setup(dr => dr.GetString(3)).Returns(surname);

var convertor = new CustomerDRConvertor();

var customer = convertor.Parse(dataReader.Object);

Assert.That(customer.Id, Is.EqualTo(id));

Assert.That(customer.FirstName, Is.EqualTo(firstName));

Assert.That(customer.Surname, Is.EqualTo(surname));

dataReader.Verify(dr => dr.GetOrdinal(It.IsAny<string>()), Times.Exactly(3));

dataReader.Verify(dr => dr.GetOrdinal("Id"), Times.Once());

dataReader.Verify(dr => dr.GetOrdinal("FirstName"), Times.Once());

dataReader.Verify(dr => dr.GetOrdinal("Surname"), Times.Once());

dataReader.Verify(dr => dr.GetGuid(It.IsAny<int>()), Times.Once());

dataReader.Verify(dr => dr.GetGuid(1), Times.Once());

dataReader.Verify(dr => dr.GetString(It.IsAny<int>()), Times.Exactly(3));

dataReader.Verify(dr => dr.GetString(2), Times.Once());

dataReader.Verify(dr => dr.GetString(3), Times.Once());

}

}

}

Obviously the above is a very basic test, but any solution can be scaled to reflect any addition or complex processing that may take place in the implementation of Parse(IDataReader dataReader) method. In fact in part two of this series we will highlight how we can implement some potential implementation and verify the expected behaviour whilst confirming that the returned results have not changed.

Finally to wrap up part one of this series here is the original code updated to reflect the changes discussed here. We’ve not really changed a lot, but are now able to unit test code that was previously difficult to easily reach.

public IEnumerable<Customer> Get()

{

using (var connection = new SqlConnection(this.config.ConnectionString))

{

using (var command = connection.CreateCommand())

{

command.CommandText = "SELECT id, Firstname, Surname FROM Customer";

connection.Open();

using (var dataReader = command.ExecuteReader())

{

var convertor = new CustomerDRConvertor();

while (dataReader.Read())

{

yield return convertor.Parse(dataReader);

}

}

}

}

}

MVC3.0 Installation Hangs

I've just installed MVC3.0 on a fresh PC using the new web installer application and was surprised at how long it seemed to be taking.  Digging around a bit deeper I remembered that in the options I'd selected to use IIS rather than IIS Express and taking a quick look at the service panel highlighted that IIS was currently stopped.  I restarted IIS and the MVC3.0 installation finished in seconds!

So if you're having problems installing MVC3.0 then just take a moment to check that IIS is started.